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] 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 });