1
0
mirror of synced 2025-12-19 18:10:59 -05:00

add manual and automatic backend loggers (#54372)

Co-authored-by: Kevin Heis <heiskr@users.noreply.github.com>
This commit is contained in:
Evan Bonsignori
2025-07-23 11:25:42 -07:00
committed by GitHub
parent 642be22f8a
commit 2816948783
20 changed files with 1941 additions and 75 deletions

View File

@@ -2,6 +2,8 @@ import fs from 'fs'
import path from 'path'
import frontmatter from 'gray-matter'
import { getLogLevelNumber } from '#src/observability/logger/lib/log-levels.js'
// Replace imports with hardcoded values
const ROOT = process.env.ROOT || '.'
@@ -35,6 +37,9 @@ export default {
'mixed-decls',
],
},
// Don't use automatic Next.js logging in dev unless the log level is `debug` or higher
// See `src/observability/logger/README.md` for log levels
logging: getLogLevelNumber() < 3 ? false : {},
async rewrites() {
const DEFAULT_VERSION = 'free-pro-team@latest'
return productIds.map((productId) => {
@@ -47,7 +52,7 @@ export default {
webpack: (config) => {
config.experiments = config.experiments || {}
config.experiments.topLevelAwait = true
config.resolve.fallback = { fs: false }
config.resolve.fallback = { fs: false, async_hooks: false }
return config
},

48
package-lock.json generated
View File

@@ -68,7 +68,6 @@
"mdast-util-to-hast": "^13.2.0",
"mdast-util-to-markdown": "2.1.2",
"mdast-util-to-string": "^4.0.0",
"morgan": "^1.10.1",
"next": "^15.3.3",
"ora": "^8.0.1",
"parse5": "7.1.2",
@@ -123,7 +122,6 @@
"@types/lodash": "^4.17.16",
"@types/lodash-es": "4.17.12",
"@types/mdast": "^4.0.4",
"@types/morgan": "1.9.9",
"@types/react": "18.3.20",
"@types/react-dom": "^18.3.6",
"@types/semver": "^7.5.8",
@@ -4702,15 +4700,6 @@
"version": "3.0.5",
"license": "MIT"
},
"node_modules/@types/morgan": {
"version": "1.9.9",
"resolved": "https://registry.npmjs.org/@types/morgan/-/morgan-1.9.9.tgz",
"integrity": "sha512-iRYSDKVaC6FkGSpEVVIvrRGw0DfJMiQzIn3qr2G5B3C//AWkulhXgaBd7tS9/J79GWSYMTHGs7PfI5b3Y8m+RQ==",
"dev": true,
"dependencies": {
"@types/node": "*"
}
},
"node_modules/@types/ms": {
"version": "0.7.31",
"resolved": "https://registry.npmjs.org/@types/ms/-/ms-0.7.31.tgz",
@@ -5954,16 +5943,6 @@
"version": "1.0.2",
"license": "MIT"
},
"node_modules/basic-auth": {
"version": "2.0.1",
"license": "MIT",
"dependencies": {
"safe-buffer": "5.1.2"
},
"engines": {
"node": ">= 0.8"
}
},
"node_modules/before-after-hook": {
"version": "4.0.0",
"resolved": "https://registry.npmjs.org/before-after-hook/-/before-after-hook-4.0.0.tgz",
@@ -12526,33 +12505,6 @@
"dev": true,
"license": "MIT"
},
"node_modules/morgan": {
"version": "1.10.1",
"resolved": "https://registry.npmjs.org/morgan/-/morgan-1.10.1.tgz",
"integrity": "sha512-223dMRJtI/l25dJKWpgij2cMtywuG/WiUKXdvwfbhGKBhy1puASqXwFzmWZ7+K73vUPoR7SS2Qz2cI/g9MKw0A==",
"license": "MIT",
"dependencies": {
"basic-auth": "~2.0.1",
"debug": "2.6.9",
"depd": "~2.0.0",
"on-finished": "~2.3.0",
"on-headers": "~1.1.0"
},
"engines": {
"node": ">= 0.8.0"
}
},
"node_modules/morgan/node_modules/debug": {
"version": "2.6.9",
"license": "MIT",
"dependencies": {
"ms": "2.0.0"
}
},
"node_modules/morgan/node_modules/ms": {
"version": "2.0.0",
"license": "MIT"
},
"node_modules/mri": {
"version": "1.2.0",
"resolved": "https://registry.npmjs.org/mri/-/mri-1.2.0.tgz",

View File

@@ -306,7 +306,6 @@
"mdast-util-to-hast": "^13.2.0",
"mdast-util-to-markdown": "2.1.2",
"mdast-util-to-string": "^4.0.0",
"morgan": "^1.10.1",
"next": "^15.3.3",
"ora": "^8.0.1",
"parse5": "7.1.2",
@@ -361,7 +360,6 @@
"@types/lodash": "^4.17.16",
"@types/lodash-es": "4.17.12",
"@types/mdast": "^4.0.4",
"@types/morgan": "1.9.9",
"@types/react": "18.3.20",
"@types/react-dom": "^18.3.6",
"@types/semver": "^7.5.8",

View File

@@ -1,6 +1,9 @@
import statsd from '@/observability/lib/statsd'
import { loadUnversionedTree, loadSiteTree, loadPages, loadPageMap } from './page-data'
import loadRedirects from '@/redirects/lib/precompile'
import { createLogger } from '@/observability/logger'
const logger = createLogger(import.meta.url)
// Instrument these functions so that
// it's wrapped in a timer that reports to Datadog
@@ -19,12 +22,9 @@ let promisedWarmServer: any
async function warmServer(languagesOnly = []) {
const startTime = Date.now()
if (process.env.NODE_ENV !== 'test') {
console.log(
'Priming context information...',
languagesOnly && languagesOnly.length ? `${languagesOnly.join(',')} only` : '',
)
}
logger.debug(
`Priming context information...${languagesOnly && languagesOnly.length ? ` ${languagesOnly.join(',')} only` : ''}`,
)
const unversionedTree = await dog.loadUnversionedTree(languagesOnly)
const siteTree = await dog.loadSiteTree(unversionedTree, languagesOnly)
@@ -34,9 +34,7 @@ async function warmServer(languagesOnly = []) {
statsd.gauge('memory_heap_used', process.memoryUsage().heapUsed, ['event:warm-server'])
if (process.env.NODE_ENV !== 'test') {
console.log(`Context primed in ${Date.now() - startTime} ms`)
}
logger.debug(`Context primed in ${Date.now() - startTime} ms`)
return {
pages: pageMap,

View File

@@ -17,6 +17,7 @@ import productNames from '@/products/lib/product-names'
import warmServer from '@/frame/lib/warm-server'
import nonEnterpriseDefaultVersion from '@/versions/lib/non-enterprise-default-version'
import { getDataByLanguage, getUIDataMerged } from '@/data-directory/lib/get-data'
import { updateLoggerContext } from '@/observability/logger/lib/logger-context'
// This doesn't change just because the request changes, so compute it once.
const enterpriseServerVersions = Object.keys(allVersions).filter((version) =>
@@ -107,5 +108,10 @@ export default async function contextualize(
}
}
updateLoggerContext({
version: req.context.currentVersion,
pagePath: req.pagePath,
})
return next()
}

View File

@@ -7,7 +7,6 @@ import timeout from 'connect-timeout'
import { haltOnDroppedConnection } from './halt-on-dropped-connection'
import abort from './abort'
import morgan from 'morgan'
import helmet from './helmet'
import cookieParser from './cookie-parser'
import {
@@ -64,17 +63,12 @@ import dynamicAssets from '@/assets/middleware/dynamic-assets'
import generalSearchMiddleware from '@/search/middleware/general-search-middleware'
import shielding from '@/shielding/middleware'
import { MAX_REQUEST_TIMEOUT } from '@/frame/lib/constants'
import { initLoggerContext } from '@/observability/logger/lib/logger-context'
import { getAutomaticRequestLogger } from '@/observability/logger/middleware/get-automatic-request-logger'
const { NODE_ENV } = process.env
const isTest = NODE_ENV === 'test' || process.env.GITHUB_ACTIONS === 'true'
// By default, logging each request (with morgan), is on. And by default
// it's off if you're in a production environment or running automated tests.
// But if you set the env var, that takes precedence.
const ENABLE_DEV_LOGGING = Boolean(
process.env.ENABLE_DEV_LOGGING ? JSON.parse(process.env.ENABLE_DEV_LOGGING) : !isTest,
)
const ENABLE_FASTLY_TESTING = JSON.parse(process.env.ENABLE_FASTLY_TESTING || 'false')
// Catch unhandled promise rejections and passing them to Express's error handler
@@ -104,10 +98,9 @@ export default function (app: Express) {
//
app.set('trust proxy', true)
// *** Request logging ***
if (ENABLE_DEV_LOGGING) {
app.use(morgan('dev'))
}
// *** Logging ***
app.use(initLoggerContext) // Context for both inline logs (e.g. logger.info) and automatic logs
app.use(getAutomaticRequestLogger()) // Automatic logging for all requests e.g. "GET /path 200"
// Put this early to make it as fast as possible because it's used
// to check the health of each cluster.

View File

@@ -1,7 +1,10 @@
import { main } from './start-server'
import { createLogger } from '@/observability/logger'
const logger = createLogger(import.meta.url)
try {
await main()
} catch (error) {
console.error(error)
logger.error('Uncaught top-level error', { error })
}

View File

@@ -5,6 +5,7 @@ import type { Language as parserLanguage } from 'accept-language-parser'
import languages, { languageKeys } from '@/languages/lib/languages'
import { USER_LANGUAGE_COOKIE_NAME } from '@/frame/lib/constants'
import type { ExtendedRequest, Languages } from '@/types'
import { updateLoggerContext } from '@/observability/logger/lib/logger-context'
const chineseRegions = [
'CN', // Mainland
@@ -70,5 +71,9 @@ export default function detectLanguage(req: ExtendedRequest, res: Response, next
if (!req.userLanguage) {
req.userLanguage = getLanguageCodeFromHeader(req)
}
updateLoggerContext({
language: req.language,
userLanguage: req.userLanguage,
})
return next()
}

View File

@@ -1,7 +1,11 @@
# Observability
Observability, for lack of simpler term, is our ability to collect data about how the Docs operates. These tools allow us to monitor the health of our systems, catch any errors, and get paged if a system stops working.
Observability, for lack of simpler term, is our ability to collect data about how the Docs operates. These tools allow us to monitor the health of our systems, catch any errors, and get paged if a system stops working.
In this directory we have files that connect us to our observability tools, as well as high-level error handling that helps keep our systems resilient.
We collect data in our observability systems to track the health of the Docs systems, not to track user behaviors. User behavior data collection is under the `src/events` directory.
## Logging
Please see the [logger README](./logger/README.md).

View File

@@ -1,5 +1,6 @@
import got, { type OptionsOfTextResponseBody, type Method } from 'got'
import { Failbot, HTTPBackend } from '@github/failbot'
import { getLoggerContext } from '@/observability/logger/lib/logger-context'
const HAYSTACK_APP = 'docs'
@@ -62,7 +63,15 @@ export function report(error: Error, metadata?: Record<string, unknown>) {
backends,
})
return failbot.report(error, metadata)
// Add the request id from the logger context to the metadata
// Per https://github.com/github/failbotg/blob/main/docs/api.md#additional-data
// Metadata can only be a flat object with string & number values, so only add the requestUuid
const loggerContext = getLoggerContext()
return failbot.report(error, {
...metadata,
requestUuid: loggerContext.requestUuid || 'unknown',
})
}
// Kept for legacy so you can continue to do:

View File

@@ -0,0 +1,126 @@
# Logging
Instead of using `console.<method>` e.g. `console.log` in our server-side code, we use `logger.<method>` e.g. `logger.info`.
## TOC
- [Benefits of using a central logger over `console.log`](#benefits-of-using-a-central-logger-over-consolelog)
- [How to use our logger](#how-to-use-our-logger)
- [Automatic logging](#automatic-logging)
- [Querying server logs with Splunk](#querying-server-logs-with-splunk)
- [Accessing logs in Splunk by requestUuid](#accessing-logs-in-splunk-by-requestuuid)
- [How we pass context to logs](#how-we-pass-context-to-logs)
## Benefits of using a central logger over `console.log`
1. Logs are formatting in [logfmt](https://brandur.org/logfmt) in production. This allows us to easily provide additional context to the log and query them in Splunk. However, we only log strings in development, to visually simplify them since `logfmt` can be difficult to read.
2. Application logs can be grouped by their log level. You can use `logger.<log-level>`, like `logger.debug('Success')` to group logs into a certain level. We have 4 levels:
1. `error` -> `logger.error()`
2. `warn` -> `logger.warn()`
3. `info` -> `logger.info()`
4. `debug` -> `logger.debug()`
3. You can enable / disable groups of logs by their log level using the `LOG_LEVEL` environment variable. In development, this lets you reduce logging noise by filtering out logs lower than the level you set. For instance, `LOG_LEVEL=info` will filter out `debug` level logs. In production, log levels help us query the most important logs. For instance, if you wanted to see all `error` logs, you could do so in Splunk with `level=error`.
4. Each log will include additional context in production, like the `path` the request was originated from, and a `requestUuid` that can tie all logs from a single request together.
5. Errors caught by Sentry include a `requestUuid`. We can use Splunk to see all the relevant logs from the same request where the error arose using the `requestUuid`.
## How to use our logger
Create a logger at the top of the file,
```typescript
import { createLogger } from "@/observability/logger";
// We pass `import.meta.url` so we can see the filename that the log originated from
const logger = createLogger(import.meta.url);
```
Then call the relevant methods for the log,
```typescript
function foo() {
logger.debug("Performing foo");
try {
const information = bar();
// "extraContext" will be included with the log in production
logger.info("Bar ${information.thing}", {
extraContext: information.context,
});
} catch (error) {
// The `error` will be formatted with stack trace in production
logger.error("Error calling bar()", { error });
}
}
```
The first argument to `logger.<method>` will always be a message string. The second argument is an optional object whose keys and values will be included as context in production in `logfmt` format.
## Automatic logging
In addition to application logging, e.g. `logger.info` we use a custom Express middleware for "automatic" request logging.
In local development, this will shows logs like `GET /en 200 2ms` when the `/en` route is visited.
Our custom request logger is configured in [get-automatic-request-logger.ts](./logger/middleware/get-automatic-request-logger.ts) to include useful log strings in development. In production, it logs in `logfmt` format that includes the full context used by our `logger`, including `requestUuid`.
The `requestUuid` of automatic logs can be tied to any application logs (`logger.info`) made in the same request.
## Querying server logs with Splunk
We use [Splunk](https://splunk.githubapp.com/en-US/app/gh_reference_app/search) to query our logs.
All queries should specify the index as `docs-internal`,
```splunk
index=docs-internal
```
For production logs, specify `gh_app` to `docs-internal`
```splunk
index=docs-internal gh_app=docs-internal
```
For staging logs, specify `kube_namespace` to `docs-internal-staging-<env>`
```splunk
index=docs-internal gh_app=docs-internal kube_namespace=docs-internal-staging-cedar
```
### Accessing logs in Splunk by requestUuid
You can access all log by a specific `requestUuid`,
```
index=docs-internal gh_app=docs-internal requestUuid="<>"
```
This pattern applies for all contextual fields sent to Splunk, like `level`, `method`, `path`, `status`, `query`, `body`, `language`, `version`, etc.
## How we pass context to logs
We use [async_hooks](https://nodejs.org/api/async_hooks.html#overview), a newer native library in Node.js to capture context from each request in logs without having to pass down context as arguments to each child function in a chain.
If you have experience with a Redux store, `async_hooks` are similar, but for the backend.
During an early middleware, we call `asyncLocalStorage.run(store, () => { next() })`
This ensures that all downstream middleware can access `store` from the asyncLocalStorage, using `asyncLocalStorage.getStore()`.
We can update the `store` object like we'd update any other mutable object,
```typescript
export function updateLoggerContext(newContext: Partial<LoggerContext>): void {
const store = asyncLocalStorage.getStore()
if (!store) {
return
}
Object.assign(store, newContext)
}
```

View File

@@ -0,0 +1,178 @@
import path from 'path'
import { getLoggerContext } from '@/observability/logger/lib/logger-context'
import {
getLogLevelNumber,
LOG_LEVELS,
useProductionLogging,
} from '@/observability/logger/lib/log-levels'
import { toLogfmt } from '@/observability/logger/lib/to-logfmt'
type IncludeContext = { [key: string]: any }
// Type definitions for logger methods with overloads
interface LoggerMethod {
// Pattern 1: Just a message e.g. `logger.info('Hello world')`
(message: string): void
// Pattern 2: Message with extraData object e.g. `logger.info('Hello world', { userId: 123 })`
(message: string, extraData: IncludeContext): void
// Pattern 3: Multiple message parts e.g. `logger.info('Hello', 'world', 123, true)`
(message: string, ...messageParts: (string | number | boolean)[]): void
// Pattern 4: Multiple message parts followed by extraData object e.g.
// `logger.info('Hello', 'world', 123, true, { userId: 123 })`
// Note: The extraData object must be the last argument
(
message: string,
...args: [...messageParts: (string | number | boolean)[], extraData: IncludeContext]
): void
// Pattern 5: Message with Error object (automatically handled) e.g.
// `logger.error('Database error', error)`
// Note: This will append the error message to the final log message
(message: string, error: Error): void
// Pattern 6: Message with multiple parts and Error objects
// e.g. `logger.error('Multiple failures', error1, error2)`
(message: string, ...args: (string | number | boolean | Error | IncludeContext)[]): void
}
/*
Call this function with `import.meta.url` as the argument to create a logger for a specific file.
e.g. `const logger = createLogger(import.meta.url)`
Logs will be output to the console in development, and in `logfmt` format to stdout in production.
*/
export function createLogger(filePath: string) {
if (!filePath) {
throw new Error('createLogger must be called with the import.meta.url argument')
}
// Helper function to check if a value is a plain object (not Array, Error, Date, etc.)
function isPlainObject(value: any): boolean {
return (
value !== null &&
typeof value === 'object' &&
value.constructor === Object &&
!(value instanceof Error) &&
!(value instanceof Array) &&
!(value instanceof Date)
)
}
// The actual log function used by each level-specific method.
function logMessage(level: keyof typeof LOG_LEVELS, message: string, ...args: any[]) {
// Determine if we have extraData or additional message parts
let finalMessage: string
let includeContext: IncludeContext = {}
// First, extract any Error objects from the arguments and handle them specially
const errorObjects: Error[] = []
const nonErrorArgs: any[] = []
for (const arg of args) {
if (arg instanceof Error) {
errorObjects.push(arg)
} else {
nonErrorArgs.push(arg)
}
}
// Handle the non-error arguments for message building and extraData
if (nonErrorArgs.length > 0 && isPlainObject(nonErrorArgs[nonErrorArgs.length - 1])) {
// Last non-error argument is a plain object - treat as extraData
includeContext = { ...nonErrorArgs[nonErrorArgs.length - 1] }
const messageParts = nonErrorArgs.slice(0, -1)
if (messageParts.length > 0) {
// There are message parts before the extraData object
const allMessageParts = [
message,
...messageParts.map((arg) => (typeof arg === 'string' ? arg : String(arg))),
]
finalMessage = allMessageParts.join(' ')
} else {
// Only the extraData object, no additional message parts
finalMessage = message
}
} else if (nonErrorArgs.length > 0) {
// Multiple arguments or non-plain-object - concatenate as message parts
const allMessageParts = [
message,
...nonErrorArgs.map((arg) => (typeof arg === 'string' ? arg : String(arg))),
]
finalMessage = allMessageParts.join(' ')
} else {
// No additional non-error arguments
finalMessage = message
}
// Add Error objects to includeContext and optionally to the message
if (errorObjects.length > 0) {
if (errorObjects.length === 1) {
// Single error - use 'error' key and append error message to final message
includeContext.error = errorObjects[0]
finalMessage = `${finalMessage}: ${errorObjects[0].message}`
} else {
// Multiple errors - use indexed keys and append all error messages
errorObjects.forEach((error, index) => {
includeContext[`error_${index + 1}`] = error
})
const errorMessages = errorObjects.map((err) => err.message).join(', ')
finalMessage = `${finalMessage}: ${errorMessages}`
}
}
// Compare the requested level's priority to current environment's level
const currentLogLevel = getLogLevelNumber()
if (LOG_LEVELS[level] > currentLogLevel) {
return // Do not log if the requested level is lower priority
}
const loggerContext = getLoggerContext()
const timestamp = new Date().toISOString()
if (useProductionLogging()) {
// Logfmt logging in production
const logObject: IncludeContext = {
...loggerContext,
timestamp,
level,
file: path.relative(process.cwd(), new URL(filePath).pathname),
message: finalMessage,
}
// Add any included context to the log object
const includedContextWithFormattedError = {} as IncludeContext
for (const [key, value] of Object.entries(includeContext)) {
if (typeof value === 'object' && value instanceof Error) {
// Errors don't serialize well to JSON, so just log the message + stack trace
includedContextWithFormattedError[key] = value.message
includedContextWithFormattedError[`${key}_stack`] = value.stack
} else {
includedContextWithFormattedError[key] = value
}
}
// Add extra context to its own key in the log object to prevent conflicts with loggerContext keys
logObject.included = includedContextWithFormattedError
console.log(toLogfmt(logObject))
} else {
// If the log includes an error, log to console.error in local dev
let wasErrorLog = false
for (const [, value] of Object.entries(includeContext)) {
if (typeof value === 'object' && value instanceof Error) {
wasErrorLog = true
console.log(`[${level.toUpperCase()}] ${finalMessage}`)
console.error(value)
}
}
if (!wasErrorLog) {
console.log(`[${level.toUpperCase()}] ${finalMessage}`)
}
}
}
return {
error: logMessage.bind(null, 'error') as LoggerMethod,
warn: logMessage.bind(null, 'warn') as LoggerMethod,
info: logMessage.bind(null, 'info') as LoggerMethod,
debug: logMessage.bind(null, 'debug') as LoggerMethod,
}
}

View File

@@ -0,0 +1,39 @@
/*
The log level is controlled by the `LOG_LEVEL` environment variable, where lower log levels = more verbose
examples:
if log level is 'info', only 'info', 'warn', and 'error' logs will be output
if log level is 'debug', all logs will be output
if log level is 'error', only 'error' logs will be output
NOTE: This file is `.js` because next.config.js does not yet support importing
*/
export const LOG_LEVELS = {
error: 0,
warn: 1,
info: 2,
debug: 3,
}
// We set the log level based on the LOG_LEVEL environment variable
// but default to:
// - 'info' in development
// - 'debug' in production
// - 'debug' in test - this is because `vitest` turns off logs unless --silent=false is passed
export function getLogLevelNumber() {
let defaultLogLevel = 'info'
if (
!process.env.LOG_LEVEL &&
(process.env.NODE_ENV === 'production' || process.env.NODE_ENV === 'test')
) {
defaultLogLevel = 'debug'
}
const logLevel = process.env.LOG_LEVEL?.toLowerCase() || defaultLogLevel
return LOG_LEVELS[logLevel]
}
export const useProductionLogging = () => {
return (
(process.env.NODE_ENV === 'production' && !process.env.CI) ||
process.env.LOG_LIKE_PRODUCTION === 'true'
)
}

View File

@@ -0,0 +1,92 @@
import { AsyncLocalStorage } from 'async_hooks'
import type { NextFunction, Request, Response } from 'express'
// Think of this like a Redux store, but for the backend
// During an early middleware, we call asyncLocalStorage.run(store, () => { next() })
// This ensures that all downstream middleware can access `store` from the asyncLocalStorage,
// using the `getLoggerContext` function.
export const asyncLocalStorage = new AsyncLocalStorage()
export type LoggerContext = {
requestUuid: string
path: string
method: string
headers: any
query?: any
body?: any
language?: string
userLanguage?: string
version?: string
pagePath?: string
}
export function getLoggerContext(): LoggerContext {
const store = asyncLocalStorage.getStore() || {
requestUuid: '',
path: '',
method: '',
headers: '',
language: '',
userLanguage: '',
query: '',
body: '',
}
return store as LoggerContext
}
// Called in subsequent middleware to update the request context
export function updateLoggerContext(newContext: Partial<LoggerContext>): void {
const store = asyncLocalStorage.getStore()
if (!store) {
return
}
Object.assign(store, newContext)
}
const INCLUDE_HEADERS = [
// Device / UA
'user-agent',
'sec-ch-ua',
'sec-ch-ua-platform',
// Language
'x-user-language',
'accept-language',
// Host
'host',
'x-host',
// Cache control
'cache-control',
]
export function initLoggerContext(req: Request, res: Response, next: NextFunction) {
const requestUuid = crypto.randomUUID()
const headers = {} as Record<string, string>
// Only include the headers we care about
for (const [key, value] of Object.entries(req.headers)) {
if (INCLUDE_HEADERS.includes(key)) {
if (!value) {
headers[key] = 'unset'
} else if (Array.isArray(value)) {
headers[key] = value.join(',')
} else {
headers[key] = value
}
}
}
// This is all of the context we want to include for each logger.<method> call
const store: LoggerContext = {
requestUuid,
path: req.path,
method: req.method,
headers,
query: req.query,
body: req.body,
}
// Subsequent middleware and route handlers will have access to the { requestId } store
asyncLocalStorage.run(store, () => {
next()
})
}

View File

@@ -0,0 +1,106 @@
/*
Flattens a JSON object and converts it to a logfmt string
Nested objects are flattened with a dot separator, e.g. requestContext.path=/en
This is because Splunk doesn't support nested JSON objects.
Example
{
"a": 1,
"b": {
"c": 2
}
}
becomes
a=1 b.c=2
*/
/**
* Custom logfmt stringify implementation
* Based on the original node-logfmt library behavior
*/
function stringify(data: Record<string, any>): string {
let line = ''
for (const key in data) {
const value = data[key]
let is_null = false
let stringValue: string
if (value == null) {
is_null = true
stringValue = ''
} else {
stringValue = value.toString()
}
const needs_quoting = stringValue.indexOf(' ') > -1 || stringValue.indexOf('=') > -1
const needs_escaping = stringValue.indexOf('"') > -1 || stringValue.indexOf('\\') > -1
if (needs_escaping) {
stringValue = stringValue.replace(/["\\]/g, '\\$&')
}
if (needs_quoting || needs_escaping) {
stringValue = '"' + stringValue + '"'
}
if (stringValue === '' && !is_null) {
stringValue = '""'
}
line += key + '=' + stringValue + ' '
}
// trim trailing space
return line.substring(0, line.length - 1)
}
export function toLogfmt(jsonString: Record<string, any>): string {
// Helper function to flatten nested objects
const flattenObject = (
obj: any,
parentKey: string = '',
result: Record<string, any> = {},
seen: WeakSet<object> = new WeakSet(),
): Record<string, any> => {
Object.keys(obj).forEach((key) => {
const newKey = parentKey ? `${parentKey}.${key}` : key
const value = obj[key]
if (value && typeof value === 'object') {
// Handle circular references
if (seen.has(value)) {
result[newKey] = '[Circular]'
return
}
// Handle Date objects specially
if (value instanceof Date) {
result[newKey] = value.toISOString()
return
}
// Handle arrays
if (Array.isArray(value)) {
result[newKey] = value.join(',')
return
}
// Handle other objects - only flatten if not empty
const valueKeys = Object.keys(value)
if (valueKeys.length > 0) {
seen.add(value)
flattenObject(value, newKey, result, seen)
seen.delete(value)
}
} else {
// Convert undefined values to null, as they are not supported by logfmt
result[newKey] =
value === undefined || (typeof value === 'string' && value === '') ? null : value
}
})
return result
}
const flattened = flattenObject(jsonString)
return stringify(flattened)
}

View File

@@ -0,0 +1,88 @@
import chalk from 'chalk'
import { getLoggerContext } from '@/observability/logger/lib/logger-context'
import type { NextFunction, Request, Response } from 'express'
import { getLogLevelNumber, useProductionLogging } from '@/observability/logger/lib/log-levels'
import { toLogfmt } from '@/observability/logger/lib/to-logfmt'
/**
* Check if automatic development logging is enabled.
* We don't turn on automatic logging for tests & GitHub Actions by default,
* but you can override this using the ENABLE_DEV_LOGGING environment variable.
*/
function shouldEnableAutomaticDevLogging(): boolean {
const isTest = process.env.NODE_ENV === 'test' || process.env.GITHUB_ACTIONS === 'true'
return Boolean(
process.env.ENABLE_DEV_LOGGING ? JSON.parse(process.env.ENABLE_DEV_LOGGING) : !isTest,
)
}
/**
* Returns a custom middleware that automatically logs request details.
*
* e.g. `GET /path/to/resource 200 5.000 ms - 1234`
*
* In production, we include the logger context and print in logfmt format
* In development, we print colored strings for better readability
* In test, the request details are not logged.
*/
export function getAutomaticRequestLogger() {
return (req: Request, res: Response, next: NextFunction) => {
const startTime = Date.now()
// Store original end method to capture response completion
const originalEnd = res.end
// Override res.end to log when response completes
res.end = function (chunk?: any, encoding?: any) {
const responseTime = Date.now() - startTime
const status = res.statusCode || 200
const contentLength = res.getHeader('content-length') || '-'
const method = req.method
const url = req.originalUrl || req.url
if (useProductionLogging()) {
// Production: log in logfmt format with full context
const loggerContext = getLoggerContext()
console.log(
toLogfmt({
...loggerContext,
status,
responseTime: responseTime + ' ms',
contentLength: String(contentLength),
method,
url,
}),
)
} else if (shouldEnableAutomaticDevLogging()) {
// Development: log colored strings for readability
const logLevelNum = getLogLevelNumber()
// Don't log `/_next/` requests unless LOG_LEVEL is `debug` or higher
if (url?.startsWith('/_next/') && logLevelNum < 3) {
return originalEnd.call(this, chunk, encoding)
}
// Choose color based on status code
const color =
status >= 500 ? 'red' : status >= 400 ? 'yellow' : status >= 300 ? 'cyan' : 'green'
const logLine = [
'[AUTO]',
chalk.reset(method),
chalk.reset(url),
chalk[color](status),
chalk.reset(responseTime + ' ms'),
chalk.reset('-'),
chalk.reset(String(contentLength)),
].join(' ')
console.log(logLine)
}
// Call the original end method to complete the response
return originalEnd.call(this, chunk, encoding)
}
next()
}
}

View File

@@ -0,0 +1,394 @@
/* eslint-disable no-invalid-this */
/* eslint-disable prettier/prettier */
import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'
import { getAutomaticRequestLogger } from '@/observability/logger/middleware/get-automatic-request-logger'
import type { Request, Response, NextFunction } from 'express'
describe('getAutomaticRequestLogger', () => {
let originalEnv: typeof process.env
let originalConsoleLog: typeof console.log
const consoleLogs: string[] = []
let mockReq: Partial<Request>
let mockRes: Partial<Response>
let mockNext: NextFunction
beforeEach(() => {
// Store original environment and console methods
originalEnv = { ...process.env }
originalConsoleLog = console.log
// Mock console.log to capture output
console.log = vi.fn((message: string) => {
consoleLogs.push(message)
})
// Clear captured output
consoleLogs.length = 0
// Set up mock request, response, and next function
mockReq = {
method: 'GET',
url: '/test-path',
originalUrl: '/test-path',
}
let responseEnded = false
const originalEnd = vi.fn()
mockRes = {
statusCode: 200,
getHeader: vi.fn((name: string) => {
if (name === 'content-length') return '1234'
return undefined
}),
end: originalEnd,
}
// Override res.end to simulate response completion
const endOverride = function (this: any, chunk?: any, encoding?: any) {
if (!responseEnded) {
responseEnded = true
// Simulate a small delay for response time
setTimeout(() => {
originalEnd.call(this, chunk, encoding)
}, 10)
}
return this
}
;(mockRes as any).end = endOverride
mockNext = vi.fn()
// Set default environment with explicit values for CI stability
vi.stubEnv('NODE_ENV', 'development')
vi.stubEnv('LOG_LEVEL', 'debug')
vi.stubEnv('ENABLE_DEV_LOGGING', 'true')
vi.stubEnv('LOG_LIKE_PRODUCTION', '')
vi.stubEnv('GITHUB_ACTIONS', '')
})
afterEach(() => {
// Restore original environment and console methods
process.env = originalEnv
console.log = originalConsoleLog
vi.clearAllMocks()
})
describe('development environment', () => {
beforeEach(() => {
vi.stubEnv('NODE_ENV', 'development')
vi.stubEnv('LOG_LIKE_PRODUCTION', '')
})
it('should log requests in development format', async () => {
const middleware = getAutomaticRequestLogger()
// Call middleware
middleware(mockReq as Request, mockRes as Response, mockNext)
// Simulate response completion
;(mockRes as any).end()
// Wait for async logging
await new Promise((resolve) => setTimeout(resolve, 20))
expect(mockNext).toHaveBeenCalled()
expect(consoleLogs).toHaveLength(1)
const logOutput = consoleLogs[0]
expect(logOutput).toContain('[AUTO]')
expect(logOutput).toContain('GET')
expect(logOutput).toContain('/test-path')
expect(logOutput).toContain('200')
expect(logOutput).toContain('ms')
expect(logOutput).toContain('1234')
})
it('should apply color coding based on status codes', async () => {
// Test different status codes individually with completely isolated mocks
const testCases = [
{ status: 200, expectedInLog: '200' },
{ status: 404, expectedInLog: '404' },
{ status: 500, expectedInLog: '500' },
]
for (let i = 0; i < testCases.length; i++) {
const testCase = testCases[i]
// Create a completely isolated test environment for each iteration
const isolatedLogs: string[] = []
const originalConsoleLog = console.log
// Replace console.log with isolated capture
console.log = vi.fn((message: string) => {
isolatedLogs.push(message)
})
// Create completely fresh request and response mocks
const freshMockReq = {
method: 'GET',
url: '/test-path',
originalUrl: '/test-path',
}
let responseEnded = false
const originalEnd = vi.fn()
const freshMockRes = {
statusCode: testCase.status,
getHeader: vi.fn((name: string) => {
if (name === 'content-length') return '1234'
return undefined
}),
end: originalEnd,
}
// Override res.end to simulate response completion
const endOverride = function (this: any, chunk?: any, encoding?: any) {
if (!responseEnded) {
responseEnded = true
// Simulate a small delay for response time
setTimeout(() => {
originalEnd.call(this, chunk, encoding)
}, 10)
}
return this
}
;(freshMockRes as any).end = endOverride
const freshMockNext = vi.fn()
try {
const middleware = getAutomaticRequestLogger()
middleware(
freshMockReq as Request,
freshMockRes as Partial<Response> as Response,
freshMockNext,
)
;(freshMockRes as any).end()
// Wait for async logging with longer timeout for CI
await new Promise((resolve) => setTimeout(resolve, 50))
expect(isolatedLogs).toHaveLength(1)
expect(isolatedLogs[0]).toContain(testCase.expectedInLog)
} finally {
// Always restore console.log
console.log = originalConsoleLog
}
}
})
it('should filter out _next requests unless debug level', async () => {
vi.stubEnv('LOG_LEVEL', 'info') // info level = 2, debug = 3
mockReq.url = '/_next/static/file.js'
mockReq.originalUrl = '/_next/static/file.js'
const middleware = getAutomaticRequestLogger()
middleware(mockReq as Request, mockRes as Response, mockNext)
;(mockRes as any).end()
await new Promise((resolve) => setTimeout(resolve, 20))
expect(consoleLogs).toHaveLength(0) // Should be filtered out
})
it('should log _next requests when debug level is set', async () => {
vi.stubEnv('LOG_LEVEL', 'debug') // debug level = 3
mockReq.url = '/_next/static/file.js'
mockReq.originalUrl = '/_next/static/file.js'
const middleware = getAutomaticRequestLogger()
middleware(mockReq as Request, mockRes as Response, mockNext)
;(mockRes as any).end()
await new Promise((resolve) => setTimeout(resolve, 20))
expect(consoleLogs).toHaveLength(1)
expect(consoleLogs[0]).toContain('/_next/static/file.js')
})
it('should not log when ENABLE_DEV_LOGGING is false', async () => {
vi.stubEnv('ENABLE_DEV_LOGGING', 'false')
const middleware = getAutomaticRequestLogger()
middleware(mockReq as Request, mockRes as Response, mockNext)
;(mockRes as any).end()
await new Promise((resolve) => setTimeout(resolve, 20))
expect(consoleLogs).toHaveLength(0)
})
})
describe('production environment', () => {
beforeEach(() => {
vi.stubEnv('LOG_LIKE_PRODUCTION', 'true')
vi.stubEnv('NODE_ENV', 'production')
})
it('should log requests in logfmt format', async () => {
const middleware = getAutomaticRequestLogger()
middleware(mockReq as Request, mockRes as Response, mockNext)
;(mockRes as any).end()
await new Promise((resolve) => setTimeout(resolve, 20))
expect(consoleLogs).toHaveLength(1)
const logOutput = consoleLogs[0]
expect(logOutput).toContain('status=200')
expect(logOutput).toContain('method=GET')
expect(logOutput).toContain('url=/test-path')
expect(logOutput).toContain('responseTime=')
expect(logOutput).toContain('ms')
expect(logOutput).toContain('contentLength=1234')
})
it('should include logger context in production logs', async () => {
const middleware = getAutomaticRequestLogger()
middleware(mockReq as Request, mockRes as Response, mockNext)
;(mockRes as any).end()
await new Promise((resolve) => setTimeout(resolve, 20))
expect(consoleLogs).toHaveLength(1)
const logOutput = consoleLogs[0]
// Should include context fields (even if empty due to mocking)
expect(logOutput).toContain('requestUuid=')
expect(logOutput).toContain('path=')
})
})
describe('test environment', () => {
beforeEach(() => {
vi.stubEnv('NODE_ENV', 'test')
vi.stubEnv('LOG_LIKE_PRODUCTION', '')
// Explicitly clear any leftover ENABLE_DEV_LOGGING from previous tests
vi.stubEnv('ENABLE_DEV_LOGGING', '')
})
it('should not log in test environment by default', async () => {
// Be extremely explicit about the environment settings for CI
vi.stubEnv('NODE_ENV', 'test')
vi.stubEnv('ENABLE_DEV_LOGGING', '')
vi.stubEnv('LOG_LIKE_PRODUCTION', '')
// Create isolated log capture for this specific test
const isolatedLogs: string[] = []
const originalConsoleLog = console.log
console.log = vi.fn((message: string) => {
isolatedLogs.push(message)
})
try {
const middleware = getAutomaticRequestLogger()
middleware(mockReq as Request, mockRes as Response, mockNext)
;(mockRes as any).end()
// Wait for any potential async logging with longer timeout for CI
await new Promise((resolve) => setTimeout(resolve, 50))
expect(isolatedLogs).toHaveLength(0)
} finally {
// Always restore console.log
console.log = originalConsoleLog
}
})
it('should log in test environment when ENABLE_DEV_LOGGING is true', async () => {
vi.stubEnv('ENABLE_DEV_LOGGING', 'true')
const middleware = getAutomaticRequestLogger()
middleware(mockReq as Request, mockRes as Response, mockNext)
;(mockRes as any).end()
await new Promise((resolve) => setTimeout(resolve, 20))
expect(consoleLogs).toHaveLength(1)
expect(consoleLogs[0]).toContain('[AUTO]')
})
})
describe('edge cases', () => {
it('should handle missing content-length header', async () => {
;(mockRes as any).getHeader = vi.fn(() => undefined)
const middleware = getAutomaticRequestLogger()
middleware(mockReq as Request, mockRes as Response, mockNext)
;(mockRes as any).end()
await new Promise((resolve) => setTimeout(resolve, 20))
expect(consoleLogs).toHaveLength(1)
expect(consoleLogs[0]).toContain('-') // Should show '-' for missing content length
})
it('should handle missing status code', async () => {
delete (mockRes as any).statusCode
const middleware = getAutomaticRequestLogger()
middleware(mockReq as Request, mockRes as Response, mockNext)
;(mockRes as any).end()
await new Promise((resolve) => setTimeout(resolve, 20))
expect(consoleLogs).toHaveLength(1)
expect(consoleLogs[0]).toContain('200') // Should default to 200
})
it('should prefer originalUrl over url', async () => {
mockReq.url = '/different-path'
mockReq.originalUrl = '/original-path'
const middleware = getAutomaticRequestLogger()
middleware(mockReq as Request, mockRes as Response, mockNext)
;(mockRes as any).end()
await new Promise((resolve) => setTimeout(resolve, 20))
expect(consoleLogs).toHaveLength(1)
expect(consoleLogs[0]).toContain('/original-path')
expect(consoleLogs[0]).not.toContain('/different-path')
})
it('should measure response time accurately', async () => {
const middleware = getAutomaticRequestLogger()
const startTime = Date.now()
middleware(mockReq as Request, mockRes as Response, mockNext)
// Simulate some processing time
await new Promise((resolve) => setTimeout(resolve, 50))
;(mockRes as any).end()
await new Promise((resolve) => setTimeout(resolve, 20))
const endTime = Date.now()
const actualDuration = endTime - startTime
expect(consoleLogs).toHaveLength(1)
// Extract response time from log
const logOutput = consoleLogs[0]
const responseTimeMatch = logOutput.match(/(\d+)\s*ms/)
expect(responseTimeMatch).toBeTruthy()
if (responseTimeMatch) {
const loggedTime = parseInt(responseTimeMatch[1], 10)
// Should be reasonably close to actual duration (within 20ms tolerance)
expect(loggedTime).toBeGreaterThanOrEqual(40)
expect(loggedTime).toBeLessThanOrEqual(actualDuration + 20)
}
})
})
})

View File

@@ -0,0 +1,245 @@
/* eslint-disable prettier/prettier */
import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'
import { createLogger } from '@/observability/logger'
import { initLoggerContext, updateLoggerContext } from '@/observability/logger/lib/logger-context'
// Integration tests that use real dependencies without mocks
describe('logger integration tests', () => {
let originalConsoleLog: typeof console.log
let originalConsoleError: typeof console.error
let originalEnv: typeof process.env
const consoleLogs: string[] = []
const consoleErrors: any[] = []
beforeEach(() => {
// Store original console methods and environment
originalConsoleLog = console.log
originalConsoleError = console.error
originalEnv = { ...process.env }
// Mock console methods to capture output
console.log = vi.fn((message: string) => {
consoleLogs.push(message)
})
console.error = vi.fn((error: any) => {
consoleErrors.push(error)
})
// Clear captured output
consoleLogs.length = 0
consoleErrors.length = 0
})
afterEach(() => {
// Restore original console methods and environment
console.log = originalConsoleLog
console.error = originalConsoleError
process.env = originalEnv
// Clear all mocks
vi.clearAllMocks()
})
describe('logger context integration', () => {
it('should use empty context when no async local storage is set', () => {
// Set production mode to see the context in the output
vi.stubEnv('LOG_LIKE_PRODUCTION', 'true')
vi.stubEnv('NODE_ENV', 'development')
const logger = createLogger('file:///path/to/test.js')
logger.info('Test without context')
expect(consoleLogs).toHaveLength(1)
const logOutput = consoleLogs[0]
// Real getLoggerContext returns empty strings for fields when no context is set
// The logfmt output should include the basic fields
expect(logOutput).toContain('level=info')
expect(logOutput).toContain('message="Test without context"')
expect(logOutput).toContain('timestamp=')
expect(logOutput).toContain('file=')
})
it('should use context from async local storage when available', async () => {
// Set production mode to see the context in the output
vi.stubEnv('LOG_LIKE_PRODUCTION', 'true')
vi.stubEnv('NODE_ENV', 'development')
// Clear console logs before running the async context
consoleLogs.length = 0
// Create mock request and response objects that match what Express would provide
const mockReq = {
path: '/real/path',
method: 'POST',
body: { key: 'value' },
headers: {
'user-agent': 'real-agent',
host: 'example.com',
'accept-language': 'en-US,en;q=0.9',
},
query: { filter: 'active' },
} as any
const mockRes = {} as any
// Use a Promise to handle the async local storage execution
const result = await new Promise<void>((resolve, reject) => {
// Create a next function that will execute our test logic within the async context
const mockNext = () => {
try {
// Update the context with additional values (simulating subsequent middleware)
updateLoggerContext({
language: 'es',
userLanguage: 'es',
pagePath: '/real/page',
version: 'v1',
})
// Now create and use the logger within the async context
const logger = createLogger('file:///path/to/test.js')
logger.info('Test with real context')
// Verify the output within the async context
expect(consoleLogs).toHaveLength(1)
const logOutput = consoleLogs[0]
// Should have the actual context values
// Check that requestUuid matches a crypto.randomUUID() format
expect(logOutput).toMatch(
/requestUuid=[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}/,
)
expect(logOutput).toContain('path=/real/path')
expect(logOutput).toContain('method=POST')
expect(logOutput).toContain('language=es')
expect(logOutput).toContain('message="Test with real context"')
resolve()
} catch (error) {
reject(error)
}
}
// Initialize the logger context and execute the test within the async context
initLoggerContext(mockReq, mockRes, mockNext)
})
return result
})
})
describe('log levels integration', () => {
it('should use real log level filtering with explicit LOG_LEVEL=info', () => {
// Clear console logs before each test
consoleLogs.length = 0
consoleErrors.length = 0
// Set explicit log level to 'info' and development mode for readable logs
vi.stubEnv('LOG_LEVEL', 'info')
vi.stubEnv('NODE_ENV', 'development')
vi.stubEnv('LOG_LIKE_PRODUCTION', '')
const logger = createLogger('file:///path/to/test.js')
logger.debug('Debug message')
logger.info('Info message')
logger.warn('Warn message')
logger.error('Error message')
// With 'info' level, debug should be filtered out (debug=3, info=2, so debug > info)
expect(consoleLogs).not.toContain('[DEBUG] Debug message')
expect(consoleLogs).toContain('[INFO] Info message')
expect(consoleLogs).toContain('[WARN] Warn message')
expect(consoleLogs).toContain('[ERROR] Error message')
})
it('should use real log level filtering with explicit LOG_LEVEL=error', () => {
// Clear console logs before each test
consoleLogs.length = 0
consoleErrors.length = 0
// Set explicit log level to 'error' and development mode for readable logs
vi.stubEnv('LOG_LEVEL', 'error')
vi.stubEnv('NODE_ENV', 'development')
vi.stubEnv('LOG_LIKE_PRODUCTION', '')
const logger = createLogger('file:///path/to/test.js')
logger.debug('Debug message')
logger.info('Info message')
logger.warn('Warn message')
logger.error('Error message')
// With 'error' level (0), only error should be logged
expect(consoleLogs).not.toContain('[DEBUG] Debug message')
expect(consoleLogs).not.toContain('[INFO] Info message')
expect(consoleLogs).not.toContain('[WARN] Warn message')
expect(consoleLogs).toContain('[ERROR] Error message')
})
it('should use real production logging detection with LOG_LIKE_PRODUCTION=true', () => {
// Clear console logs before each test
consoleLogs.length = 0
consoleErrors.length = 0
// Test LOG_LIKE_PRODUCTION=true
vi.stubEnv('LOG_LIKE_PRODUCTION', 'true')
vi.stubEnv('NODE_ENV', 'development')
const logger = createLogger('file:///path/to/test.js')
logger.info('Production-like logging test')
expect(consoleLogs).toHaveLength(1)
const logOutput = consoleLogs[0]
// Should be in logfmt format (production-like)
expect(logOutput).toContain('level=info')
expect(logOutput).toContain('message="Production-like logging test"')
expect(logOutput).toContain('timestamp=')
})
it('should use real production logging in production environment', () => {
// Clear console logs before each test
consoleLogs.length = 0
consoleErrors.length = 0
// Test NODE_ENV=production (but not in CI)
vi.stubEnv('NODE_ENV', 'production')
vi.stubEnv('CI', '') // Ensure CI is not set
vi.stubEnv('LOG_LIKE_PRODUCTION', '') // Clear this to test production detection
const logger = createLogger('file:///path/to/test.js')
logger.info('Real production logging test')
expect(consoleLogs).toHaveLength(1)
const logOutput = consoleLogs[0]
// Should be in logfmt format (production)
expect(logOutput).toContain('level=info')
expect(logOutput).toContain('message="Real production logging test"')
expect(logOutput).toContain('timestamp=')
})
it('should use development logging format when production logging is disabled', () => {
// Clear console logs before each test
consoleLogs.length = 0
consoleErrors.length = 0
// Test development environment without LOG_LIKE_PRODUCTION
vi.stubEnv('NODE_ENV', 'development')
vi.stubEnv('LOG_LIKE_PRODUCTION', '')
vi.stubEnv('CI', '')
const logger = createLogger('file:///path/to/test.js')
logger.info('Development logging test')
expect(consoleLogs).toHaveLength(1)
const logOutput = consoleLogs[0]
// Should be in development format (not logfmt)
expect(logOutput).toBe('[INFO] Development logging test')
expect(logOutput).not.toContain('level=info')
expect(logOutput).not.toContain('timestamp=')
})
})
})

View File

@@ -0,0 +1,397 @@
/* eslint-disable prettier/prettier */
import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'
import { createLogger } from '@/observability/logger'
// Mock only the logger-context for most tests, but we'll test integration without mocks
vi.mock('@/observability/logger/lib/logger-context')
describe('createLogger', () => {
let originalEnv: typeof process.env
let originalConsoleLog: typeof console.log
let originalConsoleError: typeof console.error
const consoleLogs: string[] = []
const consoleErrors: any[] = []
beforeEach(() => {
// Store original environment and console methods
originalEnv = { ...process.env }
originalConsoleLog = console.log
originalConsoleError = console.error
// Mock console methods to capture output
console.log = vi.fn((message: string) => {
consoleLogs.push(message)
})
console.error = vi.fn((error: any) => {
consoleErrors.push(error)
})
// Clear captured output
consoleLogs.length = 0
consoleErrors.length = 0
// Set default environment
vi.stubEnv('NODE_ENV', 'development')
vi.stubEnv('LOG_LEVEL', 'debug')
})
afterEach(() => {
// Restore original environment and console methods
process.env = originalEnv
console.log = originalConsoleLog
console.error = originalConsoleError
vi.clearAllMocks()
})
describe('constructor validation', () => {
it('should throw error when filePath is not provided', () => {
expect(() => createLogger('')).toThrow(
'createLogger must be called with the import.meta.url argument',
)
})
it('should throw error when filePath is null or undefined', () => {
expect(() => createLogger(null as any)).toThrow(
'createLogger must be called with the import.meta.url argument',
)
expect(() => createLogger(undefined as any)).toThrow(
'createLogger must be called with the import.meta.url argument',
)
})
it('should create logger successfully with valid filePath', () => {
const logger = createLogger('file:///path/to/test.js')
expect(logger).toHaveProperty('error')
expect(logger).toHaveProperty('warn')
expect(logger).toHaveProperty('info')
expect(logger).toHaveProperty('debug')
})
})
describe('logging patterns in development mode', () => {
let logger: ReturnType<typeof createLogger>
beforeEach(() => {
vi.stubEnv('NODE_ENV', 'development')
logger = createLogger('file:///path/to/test.js')
})
it('should log simple messages (Pattern 1)', () => {
logger.info('Hello world')
expect(consoleLogs).toContain('[INFO] Hello world')
})
it('should log messages with extra data (Pattern 2)', () => {
logger.info('User logged in', { userId: 123, email: 'test@example.com' })
expect(consoleLogs).toContain('[INFO] User logged in')
})
it('should log multiple message parts (Pattern 3)', () => {
logger.info('User', 'action', 123, true)
expect(consoleLogs).toContain('[INFO] User action 123 true')
})
it('should log multiple message parts with extra data (Pattern 4)', () => {
logger.info('User', 'login', 'success', { userId: 123 })
expect(consoleLogs).toContain('[INFO] User login success')
})
it('should log messages with Error objects (Pattern 5)', () => {
const error = new Error('Database connection failed')
logger.error('Database error', error)
expect(consoleLogs).toContain('[ERROR] Database error: Database connection failed')
expect(consoleErrors).toContain(error)
})
it('should log messages with multiple errors and parts (Pattern 6)', () => {
const error1 = new Error('First error')
const error2 = new Error('Second error')
logger.error('Multiple failures', error1, error2)
expect(consoleLogs).toContain('[ERROR] Multiple failures: First error, Second error')
expect(consoleErrors).toContain(error1)
expect(consoleErrors).toContain(error2)
})
it('should handle mixed arguments with errors and extra data', () => {
const error = new Error('Test error')
logger.error('Operation failed', 'with code', 500, error, { operation: 'delete' })
expect(consoleLogs).toContain('[ERROR] Operation failed with code 500: Test error')
expect(consoleErrors).toContain(error)
})
it('should log all levels in development', () => {
logger.debug('Debug message')
logger.info('Info message')
logger.warn('Warning message')
logger.error('Error message')
expect(consoleLogs).toContain('[DEBUG] Debug message')
expect(consoleLogs).toContain('[INFO] Info message')
expect(consoleLogs).toContain('[WARN] Warning message')
expect(consoleLogs).toContain('[ERROR] Error message')
})
})
describe('logging with mocked context', () => {
let logger: ReturnType<typeof createLogger>
beforeEach(() => {
logger = createLogger('file:///path/to/test.js')
})
it('should use development format when context is mocked', () => {
logger.info('Test message')
// Check that a log was output in development format
expect(consoleLogs).toHaveLength(1)
const logOutput = consoleLogs[0]
expect(logOutput).toBe('[INFO] Test message')
})
it('should include extra data in development logs', () => {
logger.info('User action', { userId: 123, action: 'login' })
expect(consoleLogs).toHaveLength(1)
const logOutput = consoleLogs[0]
expect(logOutput).toBe('[INFO] User action')
})
it('should format errors properly in development logs', () => {
const error = new Error('Test error')
error.stack = 'Error: Test error\n at test.js:1:1'
logger.error('Something failed', error)
expect(consoleLogs).toHaveLength(1)
expect(consoleErrors).toHaveLength(1)
const logOutput = consoleLogs[0]
expect(logOutput).toBe('[ERROR] Something failed: Test error')
expect(consoleErrors[0]).toBe(error)
})
it('should handle multiple errors in development logs', () => {
const error1 = new Error('First error')
const error2 = new Error('Second error')
error1.stack = 'Error: First error\n at test.js:1:1'
error2.stack = 'Error: Second error\n at test.js:2:1'
logger.error('Multiple errors', error1, error2)
// In development mode, each error triggers a separate console.log + console.error
expect(consoleLogs).toHaveLength(2)
expect(consoleErrors).toHaveLength(2)
// Both log entries should have the same message
expect(consoleLogs[0]).toBe('[ERROR] Multiple errors: First error, Second error')
expect(consoleLogs[1]).toBe('[ERROR] Multiple errors: First error, Second error')
expect(consoleErrors[0]).toBe(error1)
expect(consoleErrors[1]).toBe(error2)
})
})
describe('log level filtering', () => {
let logger: ReturnType<typeof createLogger>
beforeEach(() => {
// Clear console logs before each test
consoleLogs.length = 0
consoleErrors.length = 0
})
it('should respect LOG_LEVEL=error setting', () => {
// Mock the function to return error level (0) and dynamically import logger
vi.stubEnv('LOG_LEVEL', 'error')
logger = createLogger('file:///path/to/test.js')
logger.debug('Debug message')
logger.info('Info message')
logger.warn('Warn message')
logger.error('Error message')
expect(consoleLogs).not.toContain('[DEBUG] Debug message')
expect(consoleLogs).not.toContain('[INFO] Info message')
expect(consoleLogs).not.toContain('[WARN] Warn message')
expect(consoleLogs).toContain('[ERROR] Error message')
})
it('should respect LOG_LEVEL=warn setting', () => {
vi.stubEnv('LOG_LEVEL', 'warn')
logger = createLogger('file:///path/to/test.js')
logger.debug('Debug message')
logger.info('Info message')
logger.warn('Warn message')
logger.error('Error message')
expect(consoleLogs).not.toContain('[DEBUG] Debug message')
expect(consoleLogs).not.toContain('[INFO] Info message')
expect(consoleLogs).toContain('[WARN] Warn message')
expect(consoleLogs).toContain('[ERROR] Error message')
})
it('should respect LOG_LEVEL=info setting', () => {
vi.stubEnv('LOG_LEVEL', 'info')
logger = createLogger('file:///path/to/test.js')
logger.debug('Debug message')
logger.info('Info message')
logger.warn('Warn message')
logger.error('Error message')
expect(consoleLogs).not.toContain('[DEBUG] Debug message')
expect(consoleLogs).toContain('[INFO] Info message')
expect(consoleLogs).toContain('[WARN] Warn message')
expect(consoleLogs).toContain('[ERROR] Error message')
})
})
describe('edge cases and error handling', () => {
let logger: ReturnType<typeof createLogger>
beforeEach(() => {
// Clear console logs before each test
consoleLogs.length = 0
consoleErrors.length = 0
logger = createLogger('file:///path/to/test.js')
})
it('should handle null and undefined values in extra data', () => {
logger.info('Test message', { nullValue: null, undefinedValue: undefined })
expect(consoleLogs).toContain('[INFO] Test message')
})
it('should handle arrays in extra data', () => {
logger.info('Test message', { items: [1, 2, 3] })
expect(consoleLogs).toContain('[INFO] Test message')
})
it('should handle Date objects in extra data', () => {
const date = new Date('2023-01-01T00:00:00.000Z')
logger.info('Test message', { timestamp: date })
expect(consoleLogs).toContain('[INFO] Test message')
})
it('should handle nested objects properly', () => {
logger.info('Test message', {
user: {
id: 123,
profile: { name: 'John', age: 30 },
},
})
expect(consoleLogs).toContain('[INFO] Test message')
})
it('should distinguish between plain objects and class instances', () => {
class CustomClass {
constructor(public value: string) {}
}
const instance = new CustomClass('test')
logger.info('Custom object', instance)
expect(consoleLogs).toContain('[INFO] Custom object [object Object]')
})
it('should handle empty arguments gracefully', () => {
logger.info('Just a message')
expect(consoleLogs).toContain('[INFO] Just a message')
})
it('should handle boolean and number arguments', () => {
logger.info('Values:', true, false, 42, 0, -1)
expect(consoleLogs).toContain('[INFO] Values: true false 42 0 -1')
})
})
describe('file path handling in development', () => {
it('should log file paths in development format', () => {
const logger = createLogger('file:///Users/test/project/src/test.js')
logger.info('Test message')
expect(consoleLogs).toHaveLength(1)
const logOutput = consoleLogs[0]
expect(logOutput).toBe('[INFO] Test message')
})
it('should handle relative paths in development logs', () => {
const logger = createLogger('file:///absolute/path/to/src/component/test.ts')
logger.info('Test message')
expect(consoleLogs).toHaveLength(1)
const logOutput = consoleLogs[0]
expect(logOutput).toBe('[INFO] Test message')
})
})
describe('logger context integration with mocks', () => {
let logger: ReturnType<typeof createLogger>
beforeEach(() => {
logger = createLogger('file:///path/to/test.js')
})
it('should include logger context in production logs', () => {
// TODO
})
it('should handle missing logger context gracefully in development', () => {
logger.info('No context test')
expect(consoleLogs).toHaveLength(1)
const logOutput = consoleLogs[0]
expect(logOutput).toBe('[INFO] No context test')
})
})
describe('complex argument combinations', () => {
let logger: ReturnType<typeof createLogger>
beforeEach(() => {
// Clear console logs before each test
consoleLogs.length = 0
consoleErrors.length = 0
logger = createLogger('file:///path/to/test.js')
})
it('should handle error at the beginning of arguments', () => {
const error = new Error('First error')
logger.error('Error occurred', error, 'additional', 'info', { extra: 'data' })
expect(consoleLogs).toContain('[ERROR] Error occurred additional info: First error')
expect(consoleErrors).toContain(error)
})
it('should handle error in the middle of arguments', () => {
const error = new Error('Middle error')
logger.error('Error', 'in', error, 'middle', { context: 'test' })
expect(consoleLogs).toContain('[ERROR] Error in middle: Middle error')
expect(consoleErrors).toContain(error)
})
it('should handle multiple data types in arguments', () => {
logger.info('Mixed', 123, true, 'string', { data: 'object' })
expect(consoleLogs).toContain('[INFO] Mixed 123 true string')
})
it('should prioritize plain objects as extra data over other objects', () => {
vi.stubEnv('LOG_LIKE_PRODUCTION', 'true')
// Create new logger instance
logger = createLogger('file:///path/to/test.js')
const date = new Date()
const plainObject = { key: 'value' }
logger.info('Test', date, 'string', plainObject)
expect(consoleLogs).toHaveLength(1)
const logOutput = consoleLogs[0]
// The message should contain the full string with date converted to string
expect(logOutput).toContain('message="Test')
expect(logOutput).toContain('string"')
// The plain object should be in the included context
expect(logOutput).toContain('included.key=value')
})
})
})

View File

@@ -0,0 +1,228 @@
import { describe, it, expect } from 'vitest'
import { toLogfmt } from '@/observability/logger/lib/to-logfmt'
describe('toLogfmt', () => {
describe('basic stringify functionality', () => {
it('should handle simple key value pairs', () => {
const data = { foo: 'bar', a: 14 }
expect(toLogfmt(data)).toBe('foo=bar a=14')
})
it('should handle true and false', () => {
const data = { foo: true, bar: false }
expect(toLogfmt(data)).toBe('foo=true bar=false')
})
it('should quote strings with spaces in them', () => {
const data = { foo: 'hello kitty' }
expect(toLogfmt(data)).toBe('foo="hello kitty"')
})
it('should quote strings with equals in them', () => {
const data = { foo: 'hello=kitty' }
expect(toLogfmt(data)).toBe('foo="hello=kitty"')
})
it('should quote strings with quotes in them', () => {
const data = { foo: JSON.stringify({ bar: 'baz' }) }
expect(toLogfmt(data)).toBe('foo="{\\"bar\\":\\"baz\\"}"')
})
it('should escape quotes within strings with spaces in them', () => {
const data = { foo: 'hello my "friend"' }
expect(toLogfmt(data)).toBe('foo="hello my \\"friend\\""')
const data2 = { foo: 'hello my "friend" whom I "love"' }
expect(toLogfmt(data2)).toBe('foo="hello my \\"friend\\" whom I \\"love\\""')
})
it('should escape backslashes within strings', () => {
const data = { foo: 'why would you use \\LaTeX?' }
expect(toLogfmt(data)).toBe('foo="why would you use \\\\LaTeX?"')
})
it('should handle undefined as empty', () => {
const data = { foo: undefined }
expect(toLogfmt(data)).toBe('foo=')
})
it('should handle null as empty', () => {
const data = { foo: null }
expect(toLogfmt(data)).toBe('foo=')
})
it('should handle empty string with quotes', () => {
const data = { foo: '' }
expect(toLogfmt(data)).toBe('foo=')
})
it('should handle numbers', () => {
const data = { count: 42, pi: 3.14159 }
expect(toLogfmt(data)).toBe('count=42 pi=3.14159')
})
it('should handle arrays as strings', () => {
const data = { tags: ['web', 'api', 'rest'] }
expect(toLogfmt(data)).toBe('tags=web,api,rest')
})
})
describe('object flattening functionality', () => {
it('should flatten nested objects with dot notation', () => {
const data = {
a: 1,
b: {
c: 2,
d: 'test',
},
}
expect(toLogfmt(data)).toBe('a=1 b.c=2 b.d=test')
})
it('should flatten deeply nested objects', () => {
const data = {
level1: {
level2: {
level3: {
value: 'deep',
},
},
},
}
expect(toLogfmt(data)).toBe('level1.level2.level3.value=deep')
})
it('should handle mixed flat and nested properties', () => {
const data = {
simple: 'value',
nested: {
prop: 'nested-value',
},
another: 42,
}
expect(toLogfmt(data)).toBe('simple=value nested.prop=nested-value another=42')
})
it('should handle arrays within nested objects', () => {
const data = {
config: {
tags: ['tag1', 'tag2'],
enabled: true,
},
}
expect(toLogfmt(data)).toBe('config.tags=tag1,tag2 config.enabled=true')
})
it('should handle null and undefined in nested objects', () => {
const data = {
user: {
name: 'john',
email: null,
phone: undefined,
},
}
expect(toLogfmt(data)).toBe('user.name=john user.email= user.phone=')
})
})
describe('real-world logging scenarios', () => {
it('should handle typical request logging data', () => {
const data = {
level: 'info',
message: 'Request completed',
timestamp: '2023-01-01T00:00:00.000Z',
requestUuid: '123e4567-e89b-12d3-a456-426614174000',
method: 'GET',
path: '/api/users',
status: 200,
responseTime: '125 ms',
}
const result = toLogfmt(data)
expect(result).toContain('level=info')
expect(result).toContain('message="Request completed"')
expect(result).toContain('method=GET')
expect(result).toContain('path=/api/users')
expect(result).toContain('status=200')
expect(result).toContain('responseTime="125 ms"')
})
it('should handle logger context data with nested objects', () => {
const data = {
level: 'error',
message: 'Database connection failed',
timestamp: '2023-01-01T00:00:00.000Z',
requestContext: {
path: '/api/users',
method: 'POST',
headers: {
'user-agent': 'Mozilla/5.0',
},
},
error: {
name: 'ConnectionError',
message: 'Connection timeout',
},
}
const result = toLogfmt(data)
expect(result).toContain('level=error')
expect(result).toContain('message="Database connection failed"')
expect(result).toContain('requestContext.path=/api/users')
expect(result).toContain('requestContext.method=POST')
expect(result).toContain('requestContext.headers.user-agent=Mozilla/5.0')
expect(result).toContain('error.name=ConnectionError')
expect(result).toContain('error.message="Connection timeout"')
})
it('should handle special characters that need escaping', () => {
const data = {
message: 'User said: "Hello world!" with \\backslash',
path: '/search?q=hello world&sort=date',
}
const result = toLogfmt(data)
expect(result).toContain('message="User said: \\"Hello world!\\" with \\\\backslash"')
expect(result).toContain('path="/search?q=hello world&sort=date"')
})
})
describe('edge cases', () => {
it('should handle empty object', () => {
expect(toLogfmt({})).toBe('')
})
it('should handle object with only null/undefined values', () => {
const data = { a: null, b: undefined }
expect(toLogfmt(data)).toBe('a= b=')
})
it('should handle nested object with empty nested object', () => {
const data = { config: {} }
// Empty nested objects should not produce any keys
expect(toLogfmt(data)).toBe('')
})
it('should handle circular references gracefully by treating them as strings', () => {
const obj: any = { name: 'test' }
obj.self = obj
// The circular reference should be converted to a string representation
const result = toLogfmt(obj)
expect(result).toContain('name=test')
expect(result).toContain('self=[Circular]') // Our implementation marks circular refs
})
it('should handle Date objects', () => {
const data = { timestamp: new Date('2023-01-01T00:00:00.000Z') }
expect(toLogfmt(data)).toBe('timestamp=2023-01-01T00:00:00.000Z')
})
it('should handle very long strings', () => {
const longString = 'a'.repeat(1000)
const data = { longField: longString }
const result = toLogfmt(data)
expect(result).toBe(`longField=${longString}`)
})
})
})