From d03551515caff233017d7f416712916348844810 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?William=20Chuang=20Sk=C3=B6ld?= Date: Tue, 5 Nov 2024 14:04:58 +0100 Subject: [PATCH 1/6] WIP: Restructuring log middleware --- .gitignore | 1 + README.md | 19 +++-- index.ts | 3 +- lib/gcp.ts | 23 ++---- lib/http.ts | 5 +- lib/logging.ts | 33 ++++---- lib/middleware.ts | 52 ++++++++++--- package-lock.json | 195 +++++++++++++++++++++++++--------------------- package.json | 23 ++++-- 9 files changed, 200 insertions(+), 154 deletions(-) diff --git a/.gitignore b/.gitignore index 18f2b36..6f1bc5c 100644 --- a/.gitignore +++ b/.gitignore @@ -1,3 +1,4 @@ coverage dist node_modules +.eslintcache diff --git a/README.md b/README.md index fa4776b..45fe84e 100644 --- a/README.md +++ b/README.md @@ -12,21 +12,18 @@ Here is an example server with log tracing enabled. ```js import { - fetchGcpProjectId, getHttpTraceHeader, middleware, - logger as BNLogger + logger as buildLogger } from "@bonniernews/logger"; import express from "express"; -const logger = BNLogger(); +const logger = buildLogger(); const app = express(); -app.use(middleware); - -// Fetches the project ID from the GCP metadata server in the background on startup. -// This is only necessary if you don't set the `GCP_PROJECT` environment variable. -fetchGcpProjectId(); +// This middleware will create a request context and +// automatically decorate all logs with tracing data: +app.use(middleware()); app.get("/", async (req, res) => { logger.info("Hello, world!"); @@ -39,6 +36,12 @@ app.get("/", async (req, res) => { }); ``` +The `middleware` should be put as early as possible, since only logs after this middleware will get the tracing data. The middleware will lookup the active project ID from GCP. Alternatively, you can set the `GCP_PROJECT` environment variable for this purpose. + +Use the `getHttpTraceHeader` function to pass tracing headers to downstream services. + +If you want to decorate logs with custom data, use the exported `decorateLogs` function. In order to use this, the middleware needs to be installed first. + ### Logger Interface #### Options diff --git a/index.ts b/index.ts index 2e3c3a8..a5a18a4 100644 --- a/index.ts +++ b/index.ts @@ -1,5 +1,4 @@ -export { fetchGcpProjectId } from "./lib/gcp"; export { getHttpTraceHeader } from "./lib/http"; -export { getLoggingTraceData, logger } from "./lib/logging"; +export { decorateLogs, logger } from "./lib/logging"; export { middleware } from "./lib/middleware"; export { createTraceparent } from "./lib/traceparent"; diff --git a/lib/gcp.ts b/lib/gcp.ts index 8293b27..77c78fd 100644 --- a/lib/gcp.ts +++ b/lib/gcp.ts @@ -1,26 +1,17 @@ import gcpMetaData from "gcp-metadata"; -let gcpProjectId: string | undefined = undefined; - -export function getGcpProjectId() { - return process.env.GCP_PROJECT || gcpProjectId; -} - /** * Fetches the Google Cloud Platform (GCP) project ID from the GCP metadata server. * - * You only need to call this function if you're not setting the `GCP_PROJECT` environment variable. + * You can alternatively set the `GCP_PROJECT` environment variable, which takes precedence. */ -export async function fetchGcpProjectId() { +export async function getGcpProjectId(): Promise { + if (process.env.GCP_PROJECT) { + return process.env.GCP_PROJECT; + } + const isAvailable = await gcpMetaData.isAvailable(); if (!isAvailable) return; - gcpProjectId = await gcpMetaData.project("project-id"); -} - -/** - * Resets the GCP project ID, for testing. - */ -export function reset() { - gcpProjectId = undefined; + return await gcpMetaData.project("project-id"); } diff --git a/lib/http.ts b/lib/http.ts index 8d481f2..9c4285f 100644 --- a/lib/http.ts +++ b/lib/http.ts @@ -1,7 +1,6 @@ import { getStore } from "./middleware"; export function getHttpTraceHeader() { - const { traceparent } = getStore(); - if (traceparent) return { traceparent }; - return {}; + const { traceparent } = getStore() || {}; + return traceparent ? { traceparent } : {}; } diff --git a/lib/logging.ts b/lib/logging.ts index 53e4aaa..0809e9c 100644 --- a/lib/logging.ts +++ b/lib/logging.ts @@ -1,26 +1,23 @@ import pino, { DestinationStream, LoggerOptions } from "pino"; -import { getGcpProjectId } from "./gcp"; import { getStore } from "./middleware"; -import { getTraceFromTraceparent } from "./traceparent"; -export function getLoggingTraceData() { - const { traceparent, ...rest } = getStore(); - if (!traceparent) return rest; - - const trace = getTraceFromTraceparent(traceparent); - if (!trace) return rest; +function getLoggingData() { + const store = getStore(); + return store ? store.logFields : {}; +} - const logData = { traceId: trace.traceId, spanId: trace.parentId, ...rest }; +/** + * Add any additional log data to the request context. To use this feature, you must enable the + * request storage by initializing the built-in middleware. + */ +export function decorateLogs(obj: Record) { + const store = getStore(); - const gcpProjectId = getGcpProjectId(); - if (!gcpProjectId) return logData; + if (!store) throw new Error("@bonniernews/logger middleware has not been initialized"); - return { - ...logData, - "logging.googleapis.com/trace": `projects/${gcpProjectId}/traces/${trace.traceId}`, - "logging.googleapis.com/spanId": trace.parentId, - "logging.googleapis.com/trace_sampled": trace.isSampled, - }; + for (const key in obj) { + store.logFields[key] = obj[key]; + } } type BnLoggerOptions = Omit & { @@ -68,7 +65,7 @@ export function logger(options: BnLoggerOptions = {}, stream?: DestinationStream ...(formatLog && { log: formatLog }), }, transport, - mixin: (...args) => ({ ...getLoggingTraceData(), ...mixin?.(...args) }), + mixin: (...args) => ({ ...getLoggingData(), ...mixin?.(...args) }), ...rest, }, stream diff --git a/lib/middleware.ts b/lib/middleware.ts index 5073a46..cb05241 100644 --- a/lib/middleware.ts +++ b/lib/middleware.ts @@ -1,23 +1,55 @@ import type { RequestHandler } from "express"; import { AsyncLocalStorage } from "node:async_hooks"; -import { createTraceparent } from "./traceparent"; +import { getGcpProjectId } from "./gcp"; +import { getTraceFromTraceparent, createTraceparent } from "./traceparent"; + +type LogFields = { + traceId?: string; + "logging.googleapis.com/trace"?: string; + "logging.googleapis.com/spanId"?: string; + "logging.googleapis.com/trace_sampled"?: boolean; + [key: string]: unknown; +}; type Store = { traceparent?: string; - clientServiceAccount?: string; - [key: string]: unknown; + logFields: LogFields; }; const storage = new AsyncLocalStorage(); -export const middleware: RequestHandler = (req, _res, next) => { - const traceparent = req.header("traceparent") || createTraceparent(); +export type Middleware = () => RequestHandler; + +export const middleware: Middleware = () => { + let initialized = false; + let projectId: string | undefined; + + return async (req, _res, next) => { + if (!initialized) { + initialized = true; + projectId = await getGcpProjectId(); + } + + const traceparent = req.header("traceparent") || createTraceparent(); + const trace = getTraceFromTraceparent(traceparent); + const logFields: LogFields = {}; + + if (trace) { + logFields.traceId = trace.traceId; + + if (projectId) { + logFields["logging.googleapis.com/trace"] = `projects/${projectId}/traces/${trace.traceId}`; + logFields["logging.googleapis.com/spanId"] = trace.parentId; + logFields["logging.googleapis.com/trace_sampled"] = trace.isSampled; + } + } - storage.run({ traceparent }, () => { - next(); - }); + storage.run({ traceparent, logFields }, () => { + next(); + }); + }; }; -export function getStore() { - return storage.getStore() || {}; +export function getStore(): Store | undefined { + return storage.getStore(); } diff --git a/package-lock.json b/package-lock.json index ff83337..648a199 100644 --- a/package-lock.json +++ b/package-lock.json @@ -11,7 +11,7 @@ "dependencies": { "gcp-metadata": "^6.1.0", "pino": "^9.5.0", - "pino-pretty": "^11.3.0" + "pino-pretty": "^12.1.0" }, "devDependencies": { "@bonniernews/tsconfig": "^0.0.2", @@ -19,19 +19,22 @@ "@types/eslint__js": "^8.42.3", "@types/express": "^5.0.0", "@types/mocha": "^10.0.8", - "@types/node": "^22.7.3", + "@types/node": "^22.9.0", "@types/sinon": "^17.0.3", "c8": "^10.1.2", "chai": "^5.1.1", - "eslint": "^9.13.0", + "eslint": "^9.14.0", "express": "^4.21.0", - "mocha": "^10.7.3", + "mocha": "^10.8.2", "mocha-cakes-2": "^3.3.0", "prettier": "^3.3.3", "sinon": "^19.0.2", "tsx": "^4.19.1", "typescript": "^5.6.3", - "typescript-eslint": "^8.12.1" + "typescript-eslint": "^8.13.0" + }, + "engines": { + "node": ">=18" } }, "node_modules/@bcoe/v8-coverage": { @@ -551,9 +554,9 @@ } }, "node_modules/@eslint/js": { - "version": "9.13.0", - "resolved": "https://registry.npmjs.org/@eslint/js/-/js-9.13.0.tgz", - "integrity": "sha512-IFLyoY4d72Z5y/6o/BazFBezupzI/taV8sGumxTAVw3lXG9A6md1Dc34T9s1FoD/an9pJH8RHbAxsaEbBed9lA==", + "version": "9.14.0", + "resolved": "https://registry.npmjs.org/@eslint/js/-/js-9.14.0.tgz", + "integrity": "sha512-pFoEtFWCPyDOl+C6Ift+wC7Ro89otjigCf5vcuWqWgqNSQbRrpjSvdeE6ofLz4dHmyxD5f7gIdGT4+p36L6Twg==", "dev": true, "license": "MIT", "engines": { @@ -1002,9 +1005,9 @@ "license": "MIT" }, "node_modules/@types/node": { - "version": "22.8.2", - "resolved": "https://registry.npmjs.org/@types/node/-/node-22.8.2.tgz", - "integrity": "sha512-NzaRNFV+FZkvK/KLCsNdTvID0SThyrs5SHB6tsD/lajr22FGC73N2QeDPM2wHtVde8mgcXuSsHQkH5cX1pbPLw==", + "version": "22.9.0", + "resolved": "https://registry.npmjs.org/@types/node/-/node-22.9.0.tgz", + "integrity": "sha512-vuyHg81vvWA1Z1ELfvLko2c8f34gyA0zaic0+Rllc5lbCnbSyuvb2Oxpm6TAUAC/2xZN3QGqxBNggD1nNR2AfQ==", "dev": true, "license": "MIT", "dependencies": { @@ -1066,17 +1069,17 @@ "license": "MIT" }, "node_modules/@typescript-eslint/eslint-plugin": { - "version": "8.12.1", - "resolved": "https://registry.npmjs.org/@typescript-eslint/eslint-plugin/-/eslint-plugin-8.12.1.tgz", - "integrity": "sha512-gNg/inLRcPoBsKKIe4Vv38SVSOhk4BKWNO0T56sVff33gRqtTpOsrhHtiOKD1lmIOmCtZMPaW2x/h2FlM+sCEg==", + "version": "8.13.0", + "resolved": "https://registry.npmjs.org/@typescript-eslint/eslint-plugin/-/eslint-plugin-8.13.0.tgz", + "integrity": "sha512-nQtBLiZYMUPkclSeC3id+x4uVd1SGtHuElTxL++SfP47jR0zfkZBJHc+gL4qPsgTuypz0k8Y2GheaDYn6Gy3rg==", "dev": true, "license": "MIT", "dependencies": { "@eslint-community/regexpp": "^4.10.0", - "@typescript-eslint/scope-manager": "8.12.1", - "@typescript-eslint/type-utils": "8.12.1", - "@typescript-eslint/utils": "8.12.1", - "@typescript-eslint/visitor-keys": "8.12.1", + "@typescript-eslint/scope-manager": "8.13.0", + "@typescript-eslint/type-utils": "8.13.0", + "@typescript-eslint/utils": "8.13.0", + "@typescript-eslint/visitor-keys": "8.13.0", "graphemer": "^1.4.0", "ignore": "^5.3.1", "natural-compare": "^1.4.0", @@ -1100,16 +1103,16 @@ } }, "node_modules/@typescript-eslint/parser": { - "version": "8.12.1", - "resolved": "https://registry.npmjs.org/@typescript-eslint/parser/-/parser-8.12.1.tgz", - "integrity": "sha512-I/I9Bg7qFa8rOgBnUUHIWTgzbB5wVkSLX+04xGUzTcJUtdq/I2uHWR9mbW6qUYJG/UmkuDcTax5JHvoEWOAHOQ==", + "version": "8.13.0", + "resolved": "https://registry.npmjs.org/@typescript-eslint/parser/-/parser-8.13.0.tgz", + "integrity": "sha512-w0xp+xGg8u/nONcGw1UXAr6cjCPU1w0XVyBs6Zqaj5eLmxkKQAByTdV/uGgNN5tVvN/kKpoQlP2cL7R+ajZZIQ==", "dev": true, "license": "BSD-2-Clause", "dependencies": { - "@typescript-eslint/scope-manager": "8.12.1", - "@typescript-eslint/types": "8.12.1", - "@typescript-eslint/typescript-estree": "8.12.1", - "@typescript-eslint/visitor-keys": "8.12.1", + "@typescript-eslint/scope-manager": "8.13.0", + "@typescript-eslint/types": "8.13.0", + "@typescript-eslint/typescript-estree": "8.13.0", + "@typescript-eslint/visitor-keys": "8.13.0", "debug": "^4.3.4" }, "engines": { @@ -1129,14 +1132,14 @@ } }, "node_modules/@typescript-eslint/scope-manager": { - "version": "8.12.1", - "resolved": "https://registry.npmjs.org/@typescript-eslint/scope-manager/-/scope-manager-8.12.1.tgz", - "integrity": "sha512-bma6sD1iViTt+y9MAwDlBdPTMCqoH/BNdcQk4rKhIZWv3eM0xHmzeSrPJA663PAqFqfpOmtdugycpr0E1mZDVA==", + "version": "8.13.0", + "resolved": "https://registry.npmjs.org/@typescript-eslint/scope-manager/-/scope-manager-8.13.0.tgz", + "integrity": "sha512-XsGWww0odcUT0gJoBZ1DeulY1+jkaHUciUq4jKNv4cpInbvvrtDoyBH9rE/n2V29wQJPk8iCH1wipra9BhmiMA==", "dev": true, "license": "MIT", "dependencies": { - "@typescript-eslint/types": "8.12.1", - "@typescript-eslint/visitor-keys": "8.12.1" + "@typescript-eslint/types": "8.13.0", + "@typescript-eslint/visitor-keys": "8.13.0" }, "engines": { "node": "^18.18.0 || ^20.9.0 || >=21.1.0" @@ -1147,14 +1150,14 @@ } }, "node_modules/@typescript-eslint/type-utils": { - "version": "8.12.1", - "resolved": "https://registry.npmjs.org/@typescript-eslint/type-utils/-/type-utils-8.12.1.tgz", - "integrity": "sha512-zJzrvbDVjIzVKV2TGHcjembEhws8RWXJhmqfO9hS2gRXBN0gDwGhRPEdJ6AZglzfJ+YA1q09EWpSLSXjBJpIMQ==", + "version": "8.13.0", + "resolved": "https://registry.npmjs.org/@typescript-eslint/type-utils/-/type-utils-8.13.0.tgz", + "integrity": "sha512-Rqnn6xXTR316fP4D2pohZenJnp+NwQ1mo7/JM+J1LWZENSLkJI8ID8QNtlvFeb0HnFSK94D6q0cnMX6SbE5/vA==", "dev": true, "license": "MIT", "dependencies": { - "@typescript-eslint/typescript-estree": "8.12.1", - "@typescript-eslint/utils": "8.12.1", + "@typescript-eslint/typescript-estree": "8.13.0", + "@typescript-eslint/utils": "8.13.0", "debug": "^4.3.4", "ts-api-utils": "^1.3.0" }, @@ -1172,9 +1175,9 @@ } }, "node_modules/@typescript-eslint/types": { - "version": "8.12.1", - "resolved": "https://registry.npmjs.org/@typescript-eslint/types/-/types-8.12.1.tgz", - "integrity": "sha512-anMS4es5lxBe4UVcDXOkcDb3csnm5BvaNIbOFfvy/pJEohorsggdVB8MFbl5EZiEuBnZZ0ei1z7W5b6FdFiV1Q==", + "version": "8.13.0", + "resolved": "https://registry.npmjs.org/@typescript-eslint/types/-/types-8.13.0.tgz", + "integrity": "sha512-4cyFErJetFLckcThRUFdReWJjVsPCqyBlJTi6IDEpc1GWCIIZRFxVppjWLIMcQhNGhdWJJRYFHpHoDWvMlDzng==", "dev": true, "license": "MIT", "engines": { @@ -1186,14 +1189,14 @@ } }, "node_modules/@typescript-eslint/typescript-estree": { - "version": "8.12.1", - "resolved": "https://registry.npmjs.org/@typescript-eslint/typescript-estree/-/typescript-estree-8.12.1.tgz", - "integrity": "sha512-k/o9khHOckPeDXilFTIPsP9iAYhhdMh3OsOL3i2072PNpFqhqzRHx472/0DeC8H/WZee3bZG0z2ddGRSPgeOKw==", + "version": "8.13.0", + "resolved": "https://registry.npmjs.org/@typescript-eslint/typescript-estree/-/typescript-estree-8.13.0.tgz", + "integrity": "sha512-v7SCIGmVsRK2Cy/LTLGN22uea6SaUIlpBcO/gnMGT/7zPtxp90bphcGf4fyrCQl3ZtiBKqVTG32hb668oIYy1g==", "dev": true, "license": "BSD-2-Clause", "dependencies": { - "@typescript-eslint/types": "8.12.1", - "@typescript-eslint/visitor-keys": "8.12.1", + "@typescript-eslint/types": "8.13.0", + "@typescript-eslint/visitor-keys": "8.13.0", "debug": "^4.3.4", "fast-glob": "^3.3.2", "is-glob": "^4.0.3", @@ -1241,16 +1244,16 @@ } }, "node_modules/@typescript-eslint/utils": { - "version": "8.12.1", - "resolved": "https://registry.npmjs.org/@typescript-eslint/utils/-/utils-8.12.1.tgz", - "integrity": "sha512-sDv9yFHrhKe1WN8EYuzfhKCh/sFRupe9P+m/lZ5YgVvPoCUGHNN50IO4llSu7JAbftUM/QcCh+GeCortXPrBYQ==", + "version": "8.13.0", + "resolved": "https://registry.npmjs.org/@typescript-eslint/utils/-/utils-8.13.0.tgz", + "integrity": "sha512-A1EeYOND6Uv250nybnLZapeXpYMl8tkzYUxqmoKAWnI4sei3ihf2XdZVd+vVOmHGcp3t+P7yRrNsyyiXTvShFQ==", "dev": true, "license": "MIT", "dependencies": { "@eslint-community/eslint-utils": "^4.4.0", - "@typescript-eslint/scope-manager": "8.12.1", - "@typescript-eslint/types": "8.12.1", - "@typescript-eslint/typescript-estree": "8.12.1" + "@typescript-eslint/scope-manager": "8.13.0", + "@typescript-eslint/types": "8.13.0", + "@typescript-eslint/typescript-estree": "8.13.0" }, "engines": { "node": "^18.18.0 || ^20.9.0 || >=21.1.0" @@ -1264,13 +1267,13 @@ } }, "node_modules/@typescript-eslint/visitor-keys": { - "version": "8.12.1", - "resolved": "https://registry.npmjs.org/@typescript-eslint/visitor-keys/-/visitor-keys-8.12.1.tgz", - "integrity": "sha512-2RwdwnNGuOQKdGjuhujQHUqBZhEuodg2sLVPvOfWktvA9sOXOVqARjOyHSyhN2LiJGKxV6c8oOcmOtRcAnEeFw==", + "version": "8.13.0", + "resolved": "https://registry.npmjs.org/@typescript-eslint/visitor-keys/-/visitor-keys-8.13.0.tgz", + "integrity": "sha512-7N/+lztJqH4Mrf0lb10R/CbI1EaAMMGyF5y0oJvFoAhafwgiRA7TXyd8TFn8FC8k5y2dTsYogg238qavRGNnlw==", "dev": true, "license": "MIT", "dependencies": { - "@typescript-eslint/types": "8.12.1", + "@typescript-eslint/types": "8.13.0", "eslint-visitor-keys": "^3.4.3" }, "engines": { @@ -2119,22 +2122,22 @@ } }, "node_modules/eslint": { - "version": "9.13.0", - "resolved": "https://registry.npmjs.org/eslint/-/eslint-9.13.0.tgz", - "integrity": "sha512-EYZK6SX6zjFHST/HRytOdA/zE72Cq/bfw45LSyuwrdvcclb/gqV8RRQxywOBEWO2+WDpva6UZa4CcDeJKzUCFA==", + "version": "9.14.0", + "resolved": "https://registry.npmjs.org/eslint/-/eslint-9.14.0.tgz", + "integrity": "sha512-c2FHsVBr87lnUtjP4Yhvk4yEhKrQavGafRA/Se1ouse8PfbfC/Qh9Mxa00yWsZRlqeUB9raXip0aiiUZkgnr9g==", "dev": true, "license": "MIT", "dependencies": { "@eslint-community/eslint-utils": "^4.2.0", - "@eslint-community/regexpp": "^4.11.0", + "@eslint-community/regexpp": "^4.12.1", "@eslint/config-array": "^0.18.0", "@eslint/core": "^0.7.0", "@eslint/eslintrc": "^3.1.0", - "@eslint/js": "9.13.0", + "@eslint/js": "9.14.0", "@eslint/plugin-kit": "^0.2.0", - "@humanfs/node": "^0.16.5", + "@humanfs/node": "^0.16.6", "@humanwhocodes/module-importer": "^1.0.1", - "@humanwhocodes/retry": "^0.3.1", + "@humanwhocodes/retry": "^0.4.0", "@types/estree": "^1.0.6", "@types/json-schema": "^7.0.15", "ajv": "^6.12.4", @@ -2142,9 +2145,9 @@ "cross-spawn": "^7.0.2", "debug": "^4.3.2", "escape-string-regexp": "^4.0.0", - "eslint-scope": "^8.1.0", - "eslint-visitor-keys": "^4.1.0", - "espree": "^10.2.0", + "eslint-scope": "^8.2.0", + "eslint-visitor-keys": "^4.2.0", + "espree": "^10.3.0", "esquery": "^1.5.0", "esutils": "^2.0.2", "fast-deep-equal": "^3.1.3", @@ -2180,9 +2183,9 @@ } }, "node_modules/eslint-scope": { - "version": "8.1.0", - "resolved": "https://registry.npmjs.org/eslint-scope/-/eslint-scope-8.1.0.tgz", - "integrity": "sha512-14dSvlhaVhKKsa9Fx1l8A17s7ah7Ef7wCakJ10LYk6+GYmP9yDti2oq2SEwcyndt6knfcZyhyxwY3i9yL78EQw==", + "version": "8.2.0", + "resolved": "https://registry.npmjs.org/eslint-scope/-/eslint-scope-8.2.0.tgz", + "integrity": "sha512-PHlWUfG6lvPc3yvP5A4PNyBL1W8fkDUccmI21JUu/+GKZBoH/W5u6usENXUrWFRsyoW5ACUjFGgAFQp5gUlb/A==", "dev": true, "license": "BSD-2-Clause", "dependencies": { @@ -2197,9 +2200,9 @@ } }, "node_modules/eslint-visitor-keys": { - "version": "4.1.0", - "resolved": "https://registry.npmjs.org/eslint-visitor-keys/-/eslint-visitor-keys-4.1.0.tgz", - "integrity": "sha512-Q7lok0mqMUSf5a/AdAZkA5a/gHcO6snwQClVNNvFKCAVlxXucdU8pKydU5ZVZjBx5xr37vGbFFWtLQYreLzrZg==", + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/eslint-visitor-keys/-/eslint-visitor-keys-4.2.0.tgz", + "integrity": "sha512-UyLnSehNt62FFhSwjZlHmeokpRK59rcz29j+F1/aDgbkbRTk7wIc9XzdoasMUbRNKDM0qQt/+BJ4BrpFeABemw==", "dev": true, "license": "Apache-2.0", "engines": { @@ -2209,16 +2212,30 @@ "url": "https://opencollective.com/eslint" } }, + "node_modules/eslint/node_modules/@humanwhocodes/retry": { + "version": "0.4.1", + "resolved": "https://registry.npmjs.org/@humanwhocodes/retry/-/retry-0.4.1.tgz", + "integrity": "sha512-c7hNEllBlenFTHBky65mhq8WD2kbN9Q6gk0bTk8lSBvc554jpXSkST1iePudpt7+A/AQvuHs9EMqjHDXMY1lrA==", + "dev": true, + "license": "Apache-2.0", + "engines": { + "node": ">=18.18" + }, + "funding": { + "type": "github", + "url": "https://github.com/sponsors/nzakas" + } + }, "node_modules/espree": { - "version": "10.2.0", - "resolved": "https://registry.npmjs.org/espree/-/espree-10.2.0.tgz", - "integrity": "sha512-upbkBJbckcCNBDBDXEbuhjbP68n+scUd3k/U2EkyM9nw+I/jPiL4cLF/Al06CF96wRltFda16sxDFrxsI1v0/g==", + "version": "10.3.0", + "resolved": "https://registry.npmjs.org/espree/-/espree-10.3.0.tgz", + "integrity": "sha512-0QYC8b24HWY8zjRnDTL6RiHfDbAWn63qb4LMj1Z4b076A4une81+z03Kg7l7mn/48PUTqoLptSXez8oknU8Clg==", "dev": true, "license": "BSD-2-Clause", "dependencies": { - "acorn": "^8.12.0", + "acorn": "^8.14.0", "acorn-jsx": "^5.3.2", - "eslint-visitor-keys": "^4.1.0" + "eslint-visitor-keys": "^4.2.0" }, "engines": { "node": "^18.18.0 || ^20.9.0 || >=21.1.0" @@ -3440,9 +3457,9 @@ } }, "node_modules/mocha": { - "version": "10.7.3", - "resolved": "https://registry.npmjs.org/mocha/-/mocha-10.7.3.tgz", - "integrity": "sha512-uQWxAu44wwiACGqjbPYmjo7Lg8sFrS3dQe7PP2FQI+woptP4vZXSMcfMyFL/e1yFEeEpV4RtyTpZROOKmxis+A==", + "version": "10.8.2", + "resolved": "https://registry.npmjs.org/mocha/-/mocha-10.8.2.tgz", + "integrity": "sha512-VZlYo/WE8t1tstuRmqgeyBgCbJc/lEdopaa+axcKzTBJ+UIdlAB9XnmvTCAH4pwR4ElNInaedhEBmZD8iCSVEg==", "dev": true, "license": "MIT", "dependencies": { @@ -3868,9 +3885,9 @@ } }, "node_modules/pino-pretty": { - "version": "11.3.0", - "resolved": "https://registry.npmjs.org/pino-pretty/-/pino-pretty-11.3.0.tgz", - "integrity": "sha512-oXwn7ICywaZPHmu3epHGU2oJX4nPmKvHvB/bwrJHlGcbEWaVcotkpyVHMKLKmiVryWYByNp0jpgAcXpFJDXJzA==", + "version": "12.1.0", + "resolved": "https://registry.npmjs.org/pino-pretty/-/pino-pretty-12.1.0.tgz", + "integrity": "sha512-Z7JdCPqggoRyo0saJyCe1BN8At5qE+ZBElNbyx+znCaCVN+ohOqlWb+/WSYnamzfi2e6P6pXq/3H66KwFQHXWg==", "license": "MIT", "dependencies": { "colorette": "^2.0.7", @@ -4625,9 +4642,9 @@ "license": "MIT" }, "node_modules/ts-api-utils": { - "version": "1.3.0", - "resolved": "https://registry.npmjs.org/ts-api-utils/-/ts-api-utils-1.3.0.tgz", - "integrity": "sha512-UQMIo7pb8WRomKR1/+MFVLTroIvDVtMX3K6OUir8ynLyzB8Jeriont2bTAtmNPa1ekAgN7YPDyf6V+ygrdU+eQ==", + "version": "1.4.0", + "resolved": "https://registry.npmjs.org/ts-api-utils/-/ts-api-utils-1.4.0.tgz", + "integrity": "sha512-032cPxaEKwM+GT3vA5JXNzIaizx388rhsSW79vGRNGXfRRAdEAn2mvk36PvK5HnOchyWZ7afLEXqYCvPCrzuzQ==", "dev": true, "license": "MIT", "engines": { @@ -4709,15 +4726,15 @@ } }, "node_modules/typescript-eslint": { - "version": "8.12.1", - "resolved": "https://registry.npmjs.org/typescript-eslint/-/typescript-eslint-8.12.1.tgz", - "integrity": "sha512-SsKedZnq4TStkrpqnk+OqTnmkC9CkYBRNKjQ965CLpFruGcRkPF5UhKxbcbF6c/m2r6YAgKw/UtQxdlMjh3mug==", + "version": "8.13.0", + "resolved": "https://registry.npmjs.org/typescript-eslint/-/typescript-eslint-8.13.0.tgz", + "integrity": "sha512-vIMpDRJrQd70au2G8w34mPps0ezFSPMEX4pXkTzUkrNbRX+36ais2ksGWN0esZL+ZMaFJEneOBHzCgSqle7DHw==", "dev": true, "license": "MIT", "dependencies": { - "@typescript-eslint/eslint-plugin": "8.12.1", - "@typescript-eslint/parser": "8.12.1", - "@typescript-eslint/utils": "8.12.1" + "@typescript-eslint/eslint-plugin": "8.13.0", + "@typescript-eslint/parser": "8.13.0", + "@typescript-eslint/utils": "8.13.0" }, "engines": { "node": "^18.18.0 || ^20.9.0 || >=21.1.0" diff --git a/package.json b/package.json index 0b157a8..45836d2 100644 --- a/package.json +++ b/package.json @@ -10,11 +10,15 @@ ], "repository": { "type": "git", - "url": "github:BonnierNews/logger" + "url": "git+https://github.com/BonnierNews/logger.git" }, + "bugs": { + "url": "https://github.com/BonnierNews/logger/issues" + }, + "homepage": "https://github.com/BonnierNews/logger#readme", "scripts": { "build": "tsc", - "lint": "eslint .", + "lint": "eslint . --cache", "format": "prettier --write . && eslint --fix .", "typecheck": "tsc --noEmit", "test": "mocha --exit --reporter ${REPORTER:-spec}", @@ -22,12 +26,12 @@ "local-coverage": "c8 --reporter html npm test && c8 check-coverage || open ./coverage/index.html", "prepublishOnly": "npm run build" }, - "author": "", + "author": "Bonnier News", "license": "MIT", "dependencies": { "gcp-metadata": "^6.1.0", "pino": "^9.5.0", - "pino-pretty": "^11.3.0" + "pino-pretty": "^12.1.0" }, "devDependencies": { "@bonniernews/tsconfig": "^0.0.2", @@ -35,18 +39,21 @@ "@types/eslint__js": "^8.42.3", "@types/express": "^5.0.0", "@types/mocha": "^10.0.8", - "@types/node": "^22.7.3", + "@types/node": "^22.9.0", "@types/sinon": "^17.0.3", "c8": "^10.1.2", "chai": "^5.1.1", - "eslint": "^9.13.0", + "eslint": "^9.14.0", "express": "^4.21.0", - "mocha": "^10.7.3", + "mocha": "^10.8.2", "mocha-cakes-2": "^3.3.0", "prettier": "^3.3.3", "sinon": "^19.0.2", "tsx": "^4.19.1", "typescript": "^5.6.3", - "typescript-eslint": "^8.12.1" + "typescript-eslint": "^8.13.0" + }, + "engines": { + "node": ">=18" } } From 0a3999192b4036e3b24586058f1ffd413cbb7265 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?William=20Chuang=20Sk=C3=B6ld?= Date: Fri, 8 Nov 2024 17:36:22 +0100 Subject: [PATCH 2/6] WIP: Fixed most tests --- lib/middleware.ts | 6 ++--- test/feature/logging.test.ts | 45 ++++++++++++++++++------------------ test/unit/gcp.test.ts | 10 ++++---- test/unit/http.test.ts | 13 ++++++++--- test/unit/middleware.test.ts | 29 +++++++++++++++-------- 5 files changed, 58 insertions(+), 45 deletions(-) diff --git a/lib/middleware.ts b/lib/middleware.ts index cb05241..cd82227 100644 --- a/lib/middleware.ts +++ b/lib/middleware.ts @@ -11,15 +11,15 @@ type LogFields = { [key: string]: unknown; }; -type Store = { +export type Store = { traceparent?: string; logFields: LogFields; }; -const storage = new AsyncLocalStorage(); - export type Middleware = () => RequestHandler; +const storage = new AsyncLocalStorage(); + export const middleware: Middleware = () => { let initialized = false; let projectId: string | undefined; diff --git a/test/feature/logging.test.ts b/test/feature/logging.test.ts index a56728b..160f73c 100644 --- a/test/feature/logging.test.ts +++ b/test/feature/logging.test.ts @@ -1,9 +1,9 @@ +import type { RequestHandler } from "express"; import gcpMetaData from "gcp-metadata"; import pino from "pino"; import { createSandbox } from "sinon"; -import { fetchGcpProjectId, reset } from "../../lib/gcp"; import { logger as BNLogger } from "../../lib/logging"; -import { middleware } from "../../lib/middleware"; +import { middleware as createMiddleware } from "../../lib/middleware"; const logs: Record[] = []; const stream = { write: (data: string) => logs.push(JSON.parse(data)) }; @@ -17,22 +17,23 @@ const spanId = "b7ad6b7169203331"; const traceparent = `00-${traceId}-${spanId}-01`; Feature("Logging with tracing", () => { + let middleware: RequestHandler = createMiddleware(); + afterEachScenario(() => { logs.length = 0; sandbox.restore(); - reset(); + middleware = createMiddleware(); }); Scenario("Logging in the middleware context", () => { - Given("we can fetch the GCP project ID from the metadata server", async () => { + Given("we can fetch the GCP project ID from the metadata server", () => { sandbox.stub(gcpMetaData, "isAvailable").resolves(true); sandbox.stub(gcpMetaData, "project").resolves("test-project"); - await fetchGcpProjectId(); }); - When("logging in the middleware context", () => { + When("logging in the middleware context", async () => { // @ts-expect-error - We don't need the full Express Request object - middleware({ header: () => traceparent }, {}, () => { + await middleware({ header: () => traceparent }, {}, () => { logger.info("test"); }); }); @@ -51,15 +52,14 @@ Feature("Logging with tracing", () => { }); Scenario("Logging in the middleware context, but without traceparent header", () => { - Given("we can fetch the GCP project ID from the metadata server", async () => { + Given("we can fetch the GCP project ID from the metadata server", () => { sandbox.stub(gcpMetaData, "isAvailable").resolves(true); sandbox.stub(gcpMetaData, "project").resolves("test-project"); - await fetchGcpProjectId(); }); - When("logging in the middleware context", () => { + When("logging in the middleware context", async () => { // @ts-expect-error - We don't need the full Express Request object - middleware({ header: () => "" }, {}, () => { + await middleware({ header: () => "" }, {}, () => { logger.info("test"); }); }); @@ -78,15 +78,14 @@ Feature("Logging with tracing", () => { }); Scenario("Logging in the middleware context, but with invalid traceparent header", () => { - Given("we can fetch the GCP project ID from the metadata server", async () => { + Given("we can fetch the GCP project ID from the metadata server", () => { sandbox.stub(gcpMetaData, "isAvailable").resolves(true); sandbox.stub(gcpMetaData, "project").resolves("test-project"); - await fetchGcpProjectId(); }); - When("logging in the middleware context", () => { + When("logging in the middleware context", async () => { // @ts-expect-error - We don't need the full Express Request object - middleware({ header: () => "foo" }, {}, () => { + await middleware({ header: () => "foo" }, {}, () => { logger.info("test"); }); }); @@ -123,14 +122,13 @@ Feature("Logging with tracing", () => { }); Scenario("Logging in the middleware context, without metadata server", () => { - Given("we can't fetch the GCP project ID from the metadata server", async () => { + Given("we can't fetch the GCP project ID from the metadata server", () => { sandbox.stub(gcpMetaData, "isAvailable").resolves(false); - await fetchGcpProjectId(); }); - When("logging in the middleware context", () => { + When("logging in the middleware context", async () => { // @ts-expect-error - We don't need the full Express Request object - middleware({ header: () => traceparent }, {}, () => { + await middleware({ header: () => traceparent }, {}, () => { logger.info("test"); }); }); @@ -184,10 +182,12 @@ Feature("GCP logging severities", () => { }); Feature("Logging options", () => { + let middleware: RequestHandler = createMiddleware(); + afterEachScenario(() => { logs.length = 0; sandbox.restore(); - reset(); + middleware = createMiddleware(); }); Scenario("Logging with custom mixin", () => { @@ -218,12 +218,11 @@ Feature("Logging options", () => { And("we can fetch the GCP project ID from the metadata server", async () => { sandbox.stub(gcpMetaData, "isAvailable").resolves(true); sandbox.stub(gcpMetaData, "project").resolves("test-project"); - await fetchGcpProjectId(); }); - When("logging in the middleware context", () => { + When("logging in the middleware context", async () => { // @ts-expect-error - We don't need the full Express Request object - middleware({ header: () => traceparent }, {}, () => { + await middleware({ header: () => traceparent }, {}, () => { localLogger.info("test"); }); }); diff --git a/test/unit/gcp.test.ts b/test/unit/gcp.test.ts index ede58df..8eabb69 100644 --- a/test/unit/gcp.test.ts +++ b/test/unit/gcp.test.ts @@ -1,6 +1,6 @@ import gcpMetaData from "gcp-metadata"; import { createSandbox } from "sinon"; -import { fetchGcpProjectId, getGcpProjectId } from "../../lib/gcp"; +import { getGcpProjectId } from "../../lib/gcp"; const sandbox = createSandbox(); @@ -13,22 +13,20 @@ describe("GCP log fields", () => { sandbox.stub(gcpMetaData, "isAvailable").resolves(true); sandbox.stub(gcpMetaData, "project").resolves("test-project"); - await fetchGcpProjectId(); - expect(getGcpProjectId()).to.equal("test-project"); + expect(await getGcpProjectId()).to.equal("test-project"); }); it("should return `undefined` if the the GCP metadata server is not available", async () => { sandbox.stub(gcpMetaData, "isAvailable").resolves(false); - await fetchGcpProjectId(); - expect(getGcpProjectId()).to.equal("test-project"); + expect(await getGcpProjectId()).to.equal(undefined); }); it("should use the environment variable if provided", async () => { const oldGcpProject = process.env.GCP_PROJECT; process.env.GCP_PROJECT = "test-project-env"; - expect(getGcpProjectId()).to.equal("test-project-env"); + expect(await getGcpProjectId()).to.equal("test-project-env"); process.env.GCP_PROJECT = oldGcpProject; }); diff --git a/test/unit/http.test.ts b/test/unit/http.test.ts index d09ca79..e4e4a91 100644 --- a/test/unit/http.test.ts +++ b/test/unit/http.test.ts @@ -1,12 +1,19 @@ +import type { RequestHandler } from "express"; import { getHttpTraceHeader } from "../../lib/http"; -import { middleware } from "../../lib/middleware"; +import { middleware as createMiddleware } from "../../lib/middleware"; describe("HTTP helper", () => { - it("should get the traceparent header from the middleware context", () => { + let middleware: RequestHandler; + + beforeEach(() => { + middleware = createMiddleware(); + }); + + it("should get the traceparent header from the middleware context", async () => { const traceparent = "00-abcdef0123456789abcdef0123456789-abcdef0123456789-01"; // @ts-expect-error - We don't need the full Express Request object - middleware({ header: () => traceparent }, {}, () => { + await middleware({ header: () => traceparent }, {}, () => { expect(getHttpTraceHeader()).to.deep.equal({ traceparent }); }); }); diff --git a/test/unit/middleware.test.ts b/test/unit/middleware.test.ts index 31df15a..a110835 100644 --- a/test/unit/middleware.test.ts +++ b/test/unit/middleware.test.ts @@ -1,27 +1,36 @@ -import { getStore, middleware } from "../../lib/middleware"; +import type { RequestHandler } from "express"; +import { getStore, middleware as createMiddleware, Store } from "../../lib/middleware"; describe("Express middleware", () => { - it("should store the traceparent header in the store", () => { + let middleware: RequestHandler; + + beforeEach(() => { + middleware = createMiddleware(); + }); + + it("should store the traceparent header in the store", async () => { const traceparent = "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01"; const req = { header: () => traceparent }; // @ts-expect-error - We don't need the full Express Request object - middleware(req, {}, () => { - expect(getStore().traceparent).to.equal(traceparent); + await middleware(req, {}, () => { + expect(getStore()).to.have.property("traceparent").and.equal(traceparent); }); }); - it("should create a new traceparent and store it in the store if no traceparent header was provided", () => { + it("should create a new traceparent and store it in the store if no traceparent header was provided", async () => { const req = { header: () => {} }; // @ts-expect-error - We don't need the full Express Request object - middleware(req, {}, () => { - const traceparent = getStore().traceparent || ""; - expect(new RegExp(/^[\da-f-]{55}$/).test(traceparent)).to.equal(true); + await middleware(req, {}, () => { + const store = getStore() || ({} as Store); + expect(new RegExp(/^[\da-f-]{55}$/).test(store.traceparent as string)).to.equal(true); }); }); - it("should return an empty object if the middleware is not used", () => { - expect(getStore()).to.deep.equal({}); + it("should return undefined if the middleware is not used", () => { + expect(getStore()).to.deep.equal(undefined); }); + + // TODO MORE TESTS HERE }); From 2f5e462dcf8ca5163391d7263eba8845bbd39b98 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?William=20Chuang=20Sk=C3=B6ld?= Date: Mon, 11 Nov 2024 12:55:41 +0100 Subject: [PATCH 3/6] Export types from lib, and add span field outside GCP --- index.ts | 2 +- lib/http.ts | 2 +- lib/logging.ts | 10 ++++++---- lib/middleware.ts | 3 +++ 4 files changed, 11 insertions(+), 6 deletions(-) diff --git a/index.ts b/index.ts index a5a18a4..4bffe8a 100644 --- a/index.ts +++ b/index.ts @@ -1,4 +1,4 @@ export { getHttpTraceHeader } from "./lib/http"; -export { decorateLogs, logger } from "./lib/logging"; +export { decorateLogs, logger, Logger, LoggerOptions } from "./lib/logging"; export { middleware } from "./lib/middleware"; export { createTraceparent } from "./lib/traceparent"; diff --git a/lib/http.ts b/lib/http.ts index 9c4285f..82a8237 100644 --- a/lib/http.ts +++ b/lib/http.ts @@ -1,6 +1,6 @@ import { getStore } from "./middleware"; -export function getHttpTraceHeader() { +export function getHttpTraceHeader(): Record { const { traceparent } = getStore() || {}; return traceparent ? { traceparent } : {}; } diff --git a/lib/logging.ts b/lib/logging.ts index 0809e9c..a351351 100644 --- a/lib/logging.ts +++ b/lib/logging.ts @@ -1,4 +1,4 @@ -import pino, { DestinationStream, LoggerOptions } from "pino"; +import pino, { DestinationStream, LoggerOptions as PinoOptions, Logger as PinoLogger } from "pino"; import { getStore } from "./middleware"; function getLoggingData() { @@ -20,12 +20,14 @@ export function decorateLogs(obj: Record) { } } -type BnLoggerOptions = Omit & { +export type LoggerOptions = Omit & { logLevel?: "trace" | "debug" | "info" | "warn" | "error" | "fatal"; - formatLog?: NonNullable["log"]; + formatLog?: NonNullable["log"]; }; -export function logger(options: BnLoggerOptions = {}, stream?: DestinationStream | undefined) { +export type Logger = PinoLogger; + +export function logger(options: LoggerOptions = {}, stream?: DestinationStream | undefined): Logger { const env = process.env.NODE_ENV /* c8 ignore next */ || "development"; const shouldPrettyPrint = ["development", "test", "dev"].includes(env) && !stream; diff --git a/lib/middleware.ts b/lib/middleware.ts index cd82227..4fd62a8 100644 --- a/lib/middleware.ts +++ b/lib/middleware.ts @@ -5,6 +5,7 @@ import { getTraceFromTraceparent, createTraceparent } from "./traceparent"; type LogFields = { traceId?: string; + spanId?: string; "logging.googleapis.com/trace"?: string; "logging.googleapis.com/spanId"?: string; "logging.googleapis.com/trace_sampled"?: boolean; @@ -41,6 +42,8 @@ export const middleware: Middleware = () => { logFields["logging.googleapis.com/trace"] = `projects/${projectId}/traces/${trace.traceId}`; logFields["logging.googleapis.com/spanId"] = trace.parentId; logFields["logging.googleapis.com/trace_sampled"] = trace.isSampled; + } else { + logFields.spanId = trace.parentId; } } From 3e1e4074610f54feeddef1eb41dc9d55475cb1e2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?William=20Chuang=20Sk=C3=B6ld?= Date: Mon, 11 Nov 2024 14:00:20 +0100 Subject: [PATCH 4/6] Fixed tests --- index.ts | 2 +- lib/logging.ts | 10 ++- package-lock.json | 138 ++--------------------------------- package.json | 2 +- test/feature/logging.test.ts | 80 ++++++++++++++++---- test/unit/gcp.test.ts | 3 +- test/unit/middleware.test.ts | 15 +++- 7 files changed, 92 insertions(+), 158 deletions(-) diff --git a/index.ts b/index.ts index 4bffe8a..60c0c29 100644 --- a/index.ts +++ b/index.ts @@ -1,4 +1,4 @@ export { getHttpTraceHeader } from "./lib/http"; -export { decorateLogs, logger, Logger, LoggerOptions } from "./lib/logging"; +export { decorateLogs, logger, Logger, LoggerOptions, DestinationStream } from "./lib/logging"; export { middleware } from "./lib/middleware"; export { createTraceparent } from "./lib/traceparent"; diff --git a/lib/logging.ts b/lib/logging.ts index a351351..12b42fb 100644 --- a/lib/logging.ts +++ b/lib/logging.ts @@ -1,4 +1,8 @@ -import pino, { DestinationStream, LoggerOptions as PinoOptions, Logger as PinoLogger } from "pino"; +import pino, { + DestinationStream as PinoDestinationStream, + LoggerOptions as PinoOptions, + Logger as PinoLogger, +} from "pino"; import { getStore } from "./middleware"; function getLoggingData() { @@ -20,12 +24,14 @@ export function decorateLogs(obj: Record) { } } +export type Logger = PinoLogger; + export type LoggerOptions = Omit & { logLevel?: "trace" | "debug" | "info" | "warn" | "error" | "fatal"; formatLog?: NonNullable["log"]; }; -export type Logger = PinoLogger; +export type DestinationStream = PinoDestinationStream; export function logger(options: LoggerOptions = {}, stream?: DestinationStream | undefined): Logger { const env = process.env.NODE_ENV /* c8 ignore next */ || "development"; diff --git a/package-lock.json b/package-lock.json index 648a199..4f26efe 100644 --- a/package-lock.json +++ b/package-lock.json @@ -11,7 +11,7 @@ "dependencies": { "gcp-metadata": "^6.1.0", "pino": "^9.5.0", - "pino-pretty": "^12.1.0" + "pino-pretty": "^13.0.0" }, "devDependencies": { "@bonniernews/tsconfig": "^0.0.2", @@ -1297,18 +1297,6 @@ "url": "https://opencollective.com/eslint" } }, - "node_modules/abort-controller": { - "version": "3.0.0", - "resolved": "https://registry.npmjs.org/abort-controller/-/abort-controller-3.0.0.tgz", - "integrity": "sha512-h8lQ8tacZYnR3vNQTgibj+tODHI5/+l06Au2Pcriv/Gmet0eaj4TwWH41sO9wnHDiQsEj19q0drzdWdeAHtweg==", - "license": "MIT", - "dependencies": { - "event-target-shim": "^5.0.0" - }, - "engines": { - "node": ">=6.5" - } - }, "node_modules/accepts": { "version": "1.3.8", "resolved": "https://registry.npmjs.org/accepts/-/accepts-1.3.8.tgz", @@ -1465,26 +1453,6 @@ "dev": true, "license": "MIT" }, - "node_modules/base64-js": { - "version": "1.5.1", - "resolved": "https://registry.npmjs.org/base64-js/-/base64-js-1.5.1.tgz", - "integrity": "sha512-AKpaYlHn8t4SVbOHCy+b5+KKgvR4vrsD8vbvrbiQJps7fKDTkjkDry6ji0rUJjC0kzbNePLwzxq8iypo41qeWA==", - "funding": [ - { - "type": "github", - "url": "https://github.com/sponsors/feross" - }, - { - "type": "patreon", - "url": "https://www.patreon.com/feross" - }, - { - "type": "consulting", - "url": "https://feross.org/support" - } - ], - "license": "MIT" - }, "node_modules/bignumber.js": { "version": "9.1.2", "resolved": "https://registry.npmjs.org/bignumber.js/-/bignumber.js-9.1.2.tgz", @@ -1580,30 +1548,6 @@ "dev": true, "license": "ISC" }, - "node_modules/buffer": { - "version": "6.0.3", - "resolved": "https://registry.npmjs.org/buffer/-/buffer-6.0.3.tgz", - "integrity": "sha512-FTiCpNxtwiZZHEZbcbTIcZjERVICn9yq/pDFkTl95/AxzD1naBctN7YO68riM/gLSDY7sdrMby8hofADYuuqOA==", - "funding": [ - { - "type": "github", - "url": "https://github.com/sponsors/feross" - }, - { - "type": "patreon", - "url": "https://www.patreon.com/feross" - }, - { - "type": "consulting", - "url": "https://feross.org/support" - } - ], - "license": "MIT", - "dependencies": { - "base64-js": "^1.3.1", - "ieee754": "^1.2.1" - } - }, "node_modules/bytes": { "version": "3.1.2", "resolved": "https://registry.npmjs.org/bytes/-/bytes-3.1.2.tgz", @@ -2300,24 +2244,6 @@ "node": ">= 0.6" } }, - "node_modules/event-target-shim": { - "version": "5.0.1", - "resolved": "https://registry.npmjs.org/event-target-shim/-/event-target-shim-5.0.1.tgz", - "integrity": "sha512-i/2XbnSz/uxRCU6+NdVJgKWDTM427+MqYbkQzD321DuCQJUqOuJKIA0IM2+W2xtYHdKOmZ4dR6fExsd4SXL+WQ==", - "license": "MIT", - "engines": { - "node": ">=6" - } - }, - "node_modules/events": { - "version": "3.3.0", - "resolved": "https://registry.npmjs.org/events/-/events-3.3.0.tgz", - "integrity": "sha512-mQw+2fkQbALzQ7V0MY0IqdnXNOeTtP4r0lN9z7AAawCXgqea7bDii20AYrIBrFd/Hx0M2Ocz6S111CaFkUcb0Q==", - "license": "MIT", - "engines": { - "node": ">=0.8.x" - } - }, "node_modules/express": { "version": "4.21.1", "resolved": "https://registry.npmjs.org/express/-/express-4.21.1.tgz", @@ -2935,26 +2861,6 @@ "node": ">=0.10.0" } }, - "node_modules/ieee754": { - "version": "1.2.1", - "resolved": "https://registry.npmjs.org/ieee754/-/ieee754-1.2.1.tgz", - "integrity": "sha512-dcyqhDvX1C46lXZcVqCpK+FtMRQVdIMN6/Df5js2zouUsqG7I6sFxitIC+7KYK29KdXOLHdu9zL4sFnoVQnqaA==", - "funding": [ - { - "type": "github", - "url": "https://github.com/sponsors/feross" - }, - { - "type": "patreon", - "url": "https://www.patreon.com/feross" - }, - { - "type": "consulting", - "url": "https://feross.org/support" - } - ], - "license": "BSD-3-Clause" - }, "node_modules/ignore": { "version": "5.3.2", "resolved": "https://registry.npmjs.org/ignore/-/ignore-5.3.2.tgz", @@ -3885,9 +3791,9 @@ } }, "node_modules/pino-pretty": { - "version": "12.1.0", - "resolved": "https://registry.npmjs.org/pino-pretty/-/pino-pretty-12.1.0.tgz", - "integrity": "sha512-Z7JdCPqggoRyo0saJyCe1BN8At5qE+ZBElNbyx+znCaCVN+ohOqlWb+/WSYnamzfi2e6P6pXq/3H66KwFQHXWg==", + "version": "13.0.0", + "resolved": "https://registry.npmjs.org/pino-pretty/-/pino-pretty-13.0.0.tgz", + "integrity": "sha512-cQBBIVG3YajgoUjo1FdKVRX6t9XPxwB9lcNJVD5GCnNM4Y6T12YYx8c6zEejxQsU0wrg9TwmDulcE9LR7qcJqA==", "license": "MIT", "dependencies": { "colorette": "^2.0.7", @@ -3900,7 +3806,6 @@ "on-exit-leak-free": "^2.1.0", "pino-abstract-transport": "^2.0.0", "pump": "^3.0.0", - "readable-stream": "^4.0.0", "secure-json-parse": "^2.4.0", "sonic-boom": "^4.0.1", "strip-json-comments": "^3.1.1" @@ -3941,15 +3846,6 @@ "url": "https://github.com/prettier/prettier?sponsor=1" } }, - "node_modules/process": { - "version": "0.11.10", - "resolved": "https://registry.npmjs.org/process/-/process-0.11.10.tgz", - "integrity": "sha512-cdGef/drWFoydD1JsMzuFf8100nZl+GT+yacc2bEced5f9Rjk4z+WtFUTBu9PhOi9j/jfmBPu0mMEY4wIdAF8A==", - "license": "MIT", - "engines": { - "node": ">= 0.6.0" - } - }, "node_modules/process-warning": { "version": "4.0.0", "resolved": "https://registry.npmjs.org/process-warning/-/process-warning-4.0.0.tgz", @@ -4069,22 +3965,6 @@ "node": ">= 0.8" } }, - "node_modules/readable-stream": { - "version": "4.5.2", - "resolved": "https://registry.npmjs.org/readable-stream/-/readable-stream-4.5.2.tgz", - "integrity": "sha512-yjavECdqeZ3GLXNgRXgeQEdz9fvDDkNKyHnbHRFtOr7/LcfgBcmct7t/ET+HaCTqfh06OzoAxrkN/IfjJBVe+g==", - "license": "MIT", - "dependencies": { - "abort-controller": "^3.0.0", - "buffer": "^6.0.3", - "events": "^3.3.0", - "process": "^0.11.10", - "string_decoder": "^1.3.0" - }, - "engines": { - "node": "^12.22.0 || ^14.17.0 || >=16.0.0" - } - }, "node_modules/readdirp": { "version": "3.6.0", "resolved": "https://registry.npmjs.org/readdirp/-/readdirp-3.6.0.tgz", @@ -4176,6 +4056,7 @@ "version": "5.2.1", "resolved": "https://registry.npmjs.org/safe-buffer/-/safe-buffer-5.2.1.tgz", "integrity": "sha512-rp3So07KcdmmKbGvgaNxQSJr7bGVSVk5S9Eq1F+ppbRo70+YeaDxkw5Dd8NPN+GD6bjnYm2VuPuCXmpuYvmCXQ==", + "dev": true, "funding": [ { "type": "github", @@ -4442,15 +4323,6 @@ "node": ">= 0.8" } }, - "node_modules/string_decoder": { - "version": "1.3.0", - "resolved": "https://registry.npmjs.org/string_decoder/-/string_decoder-1.3.0.tgz", - "integrity": "sha512-hkRX8U1WjJFd8LsDJ2yQ/wWWxaopEsABU1XfkM8A+j0+85JAGppt16cr1Whg6KIbb4okU6Mql6BOj+uup/wKeA==", - "license": "MIT", - "dependencies": { - "safe-buffer": "~5.2.0" - } - }, "node_modules/string-width": { "version": "4.2.3", "resolved": "https://registry.npmjs.org/string-width/-/string-width-4.2.3.tgz", diff --git a/package.json b/package.json index 45836d2..4ae0851 100644 --- a/package.json +++ b/package.json @@ -31,7 +31,7 @@ "dependencies": { "gcp-metadata": "^6.1.0", "pino": "^9.5.0", - "pino-pretty": "^12.1.0" + "pino-pretty": "^13.0.0" }, "devDependencies": { "@bonniernews/tsconfig": "^0.0.2", diff --git a/test/feature/logging.test.ts b/test/feature/logging.test.ts index 160f73c..1738f2a 100644 --- a/test/feature/logging.test.ts +++ b/test/feature/logging.test.ts @@ -1,8 +1,7 @@ import type { RequestHandler } from "express"; import gcpMetaData from "gcp-metadata"; -import pino from "pino"; import { createSandbox } from "sinon"; -import { logger as BNLogger } from "../../lib/logging"; +import { logger as BNLogger, decorateLogs, Logger } from "../../lib/logging"; import { middleware as createMiddleware } from "../../lib/middleware"; const logs: Record[] = []; @@ -43,7 +42,6 @@ Feature("Logging with tracing", () => { expect(logs[0]).to.deep.include({ message: "test", traceId, - spanId, "logging.googleapis.com/trace": `projects/test-project/traces/${traceId}`, "logging.googleapis.com/spanId": spanId, "logging.googleapis.com/trace_sampled": true, @@ -64,12 +62,11 @@ Feature("Logging with tracing", () => { }); }); - Then("no trace data should be logged", () => { + Then("a trace should be automatically generated, and trace data should be logged", () => { expect(logs.length).to.equal(1); expect(logs[0]).to.deep.include({ message: "test" }); - expect(logs[0]).not.to.have.all.keys([ + expect(logs[0]).to.include.all.keys([ "traceId", - "spanId", "logging.googleapis.com/trace", "logging.googleapis.com/spanId", "logging.googleapis.com/trace_sampled", @@ -93,7 +90,7 @@ Feature("Logging with tracing", () => { Then("no trace data should be logged", () => { expect(logs.length).to.equal(1); expect(logs[0]).to.deep.include({ message: "test" }); - expect(logs[0]).not.to.have.all.keys([ + expect(logs[0]).to.not.have.any.keys([ "traceId", "spanId", "logging.googleapis.com/trace", @@ -111,7 +108,7 @@ Feature("Logging with tracing", () => { Then("no trace data should be logged", () => { expect(logs.length).to.equal(1); expect(logs[0]).to.deep.include({ message: "test" }); - expect(logs[0]).not.to.have.all.keys([ + expect(logs[0]).to.not.have.any.keys([ "traceId", "spanId", "logging.googleapis.com/trace", @@ -136,9 +133,8 @@ Feature("Logging with tracing", () => { Then("trace data should be logged", () => { expect(logs.length).to.equal(1); expect(logs[0]).to.deep.include({ message: "test" }); - expect(logs[0]).not.to.have.all.keys([ - "traceId", - "spanId", + expect(logs[0]).to.include.all.keys(["traceId", "spanId"]); + expect(logs[0]).to.not.have.any.keys([ "logging.googleapis.com/trace", "logging.googleapis.com/spanId", "logging.googleapis.com/trace_sampled", @@ -191,7 +187,7 @@ Feature("Logging options", () => { }); Scenario("Logging with custom mixin", () => { - let localLogger: pino.Logger; + let localLogger: Logger; Given("a logger with a custom mixin", () => { localLogger = BNLogger({ mixin: () => ({ foo: "bar" }) }, stream); }); @@ -210,7 +206,7 @@ Feature("Logging options", () => { }); Scenario("Logging with custom mixin and trace context", () => { - let localLogger: pino.Logger; + let localLogger: Logger; Given("a logger with a custom mixin", () => { localLogger = BNLogger({ mixin: () => ({ foo: "bar" }) }, stream); }); @@ -233,7 +229,6 @@ Feature("Logging options", () => { message: "test", foo: "bar", traceId, - spanId, "logging.googleapis.com/trace": `projects/test-project/traces/${traceId}`, "logging.googleapis.com/spanId": spanId, "logging.googleapis.com/trace_sampled": true, @@ -242,7 +237,7 @@ Feature("Logging options", () => { }); Scenario("Logging with `formatLog`", () => { - let localLogger: pino.Logger; + let localLogger: Logger; Given("a logger with a custom mixin", () => { localLogger = BNLogger( { @@ -266,3 +261,58 @@ Feature("Logging options", () => { }); }); }); + +Feature("Decorating logs", () => { + afterEachScenario(() => { + logs.length = 0; + sandbox.restore(); + }); + + Scenario("Decorate logs with improper initialization", () => { + Given("Middleware has not been initialized", () => { + // noop + }); + + Then("decorateLogs throws an error on use", () => { + expect(() => decorateLogs({ key: "value" })).to.throw(); + }); + }); + + Scenario("Decorated fields are tied to request scope", () => { + const middleware: RequestHandler = createMiddleware(); + let logger: Logger; + + Given("a logger", () => { + logger = BNLogger({}, stream); + }); + + When("using the logger in different contexts", async () => { + await new Promise((resolve) => { + // @ts-expect-error - We don't need the full Express Request object + middleware({ header: () => "" }, {}, () => { + decorateLogs({ one: "one", two: "two" }); + + logger.info("Request context"); + resolve(); + }); + }); + + logger.info("No context"); + }); + + Then("The log contains the decorated", () => { + expect(logs.length).to.equal(2); + expect(logs[0]).to.deep.include({ + message: "Request context", + one: "one", + two: "two", + }); + }); + + And("The log outside request context is without those fields", () => { + expect(logs.length).to.equal(2); + expect(logs[1]).to.deep.include({ message: "No context" }); + expect(logs[1]).to.not.have.any.keys(["one", "two"]); + }); + }); +}); diff --git a/test/unit/gcp.test.ts b/test/unit/gcp.test.ts index 8eabb69..26ff52a 100644 --- a/test/unit/gcp.test.ts +++ b/test/unit/gcp.test.ts @@ -23,11 +23,10 @@ describe("GCP log fields", () => { }); it("should use the environment variable if provided", async () => { - const oldGcpProject = process.env.GCP_PROJECT; process.env.GCP_PROJECT = "test-project-env"; expect(await getGcpProjectId()).to.equal("test-project-env"); - process.env.GCP_PROJECT = oldGcpProject; + delete process.env.GCP_PROJECT; }); }); diff --git a/test/unit/middleware.test.ts b/test/unit/middleware.test.ts index a110835..83be1fd 100644 --- a/test/unit/middleware.test.ts +++ b/test/unit/middleware.test.ts @@ -14,7 +14,12 @@ describe("Express middleware", () => { // @ts-expect-error - We don't need the full Express Request object await middleware(req, {}, () => { - expect(getStore()).to.have.property("traceparent").and.equal(traceparent); + const store = getStore(); + expect(store).to.have.property("traceparent").and.equal(traceparent); + expect(store).to.have.property("logFields").and.deep.equal({ + traceId: "0af7651916cd43dd8448eb211c80319c", + spanId: "b7ad6b7169203331", + }); }); }); @@ -25,12 +30,14 @@ describe("Express middleware", () => { await middleware(req, {}, () => { const store = getStore() || ({} as Store); expect(new RegExp(/^[\da-f-]{55}$/).test(store.traceparent as string)).to.equal(true); + const traceParts = store.traceparent?.split("-") || []; + expect(traceParts).to.be.of.length(4); + expect(store.logFields?.traceId).to.equal(traceParts[1]); + expect(store.logFields?.spanId).to.equal(traceParts[2]); }); }); - it("should return undefined if the middleware is not used", () => { + it("getStore should return undefined if the middleware is not used", () => { expect(getStore()).to.deep.equal(undefined); }); - - // TODO MORE TESTS HERE }); From c4bfabdbe0d1824e1f28d06b4134d0e7c4fc33d8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?William=20Chuang=20Sk=C3=B6ld?= Date: Mon, 11 Nov 2024 14:05:53 +0100 Subject: [PATCH 5/6] Bump package version --- package.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/package.json b/package.json index 4ae0851..1d601c1 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "@bonniernews/logger", - "version": "0.0.5", + "version": "0.0.6", "description": "Some simple functions to use Trace Context for correlating logs", "type": "module", "main": "dist/index.js", From cfb3998588001545ffefaeb2da7dfb4222c117d1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?William=20Chuang=20Sk=C3=B6ld?= Date: Mon, 11 Nov 2024 16:30:31 +0100 Subject: [PATCH 6/6] Always log spanId when trace exists --- lib/middleware.ts | 3 +-- test/feature/logging.test.ts | 3 +++ 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/lib/middleware.ts b/lib/middleware.ts index 4fd62a8..2fc100e 100644 --- a/lib/middleware.ts +++ b/lib/middleware.ts @@ -37,13 +37,12 @@ export const middleware: Middleware = () => { if (trace) { logFields.traceId = trace.traceId; + logFields.spanId = trace.parentId; if (projectId) { logFields["logging.googleapis.com/trace"] = `projects/${projectId}/traces/${trace.traceId}`; logFields["logging.googleapis.com/spanId"] = trace.parentId; logFields["logging.googleapis.com/trace_sampled"] = trace.isSampled; - } else { - logFields.spanId = trace.parentId; } } diff --git a/test/feature/logging.test.ts b/test/feature/logging.test.ts index 1738f2a..666cef4 100644 --- a/test/feature/logging.test.ts +++ b/test/feature/logging.test.ts @@ -42,6 +42,7 @@ Feature("Logging with tracing", () => { expect(logs[0]).to.deep.include({ message: "test", traceId, + spanId, "logging.googleapis.com/trace": `projects/test-project/traces/${traceId}`, "logging.googleapis.com/spanId": spanId, "logging.googleapis.com/trace_sampled": true, @@ -67,6 +68,7 @@ Feature("Logging with tracing", () => { expect(logs[0]).to.deep.include({ message: "test" }); expect(logs[0]).to.include.all.keys([ "traceId", + "spanId", "logging.googleapis.com/trace", "logging.googleapis.com/spanId", "logging.googleapis.com/trace_sampled", @@ -229,6 +231,7 @@ Feature("Logging options", () => { message: "test", foo: "bar", traceId, + spanId, "logging.googleapis.com/trace": `projects/test-project/traces/${traceId}`, "logging.googleapis.com/spanId": spanId, "logging.googleapis.com/trace_sampled": true,