From aeceda964f6a676dc6d00a2536542f3da5d64e1a Mon Sep 17 00:00:00 2001 From: Mattias Olla Date: Wed, 4 Oct 2023 15:48:33 +0200 Subject: [PATCH 1/2] Handle correlation IDs automatically This is an attempt at automatically handling logging of correlation IDs and other debug metadata. This is implemented with inspiration from https://dev.to/elmatella/my-logging-strategy-for-express-1mk8. We store the metadata in an `AsyncLocalStorage`, which is local to each `async` context, and provide a middleware factory for Express which sets this from the request (which will be used in `lu-server`) and then logging it out automatically (currently under a temporary label `correlationIdTest`). --- index.js | 3 +++ lib/debug-meta.js | 38 ++++++++++++++++++++++++++++++++++++++ package.json | 2 +- test/meta-data-test.js | 27 +++++++++++++++++++++++++++ 4 files changed, 69 insertions(+), 1 deletion(-) create mode 100644 lib/debug-meta.js diff --git a/index.js b/index.js index 1cab8c7..89d80eb 100644 --- a/index.js +++ b/index.js @@ -11,6 +11,7 @@ const logLevels = require("./config/levels"); const splatEntry = require("./lib/splat-entry"); const cleanEntry = require("./lib/clean-entry"); const stringify = require("./lib/stringify"); +const { debugMetaFormat, initDebugMetaMiddleware: initMiddleware, getDebugMeta } = require("./lib/debug-meta"); const PromTransport = require("./lib/prom-transport"); const maxMessageLength = 60 * 1024; @@ -107,6 +108,7 @@ const logger = winston.createLogger({ format(logLevel)(), format(location)(), format(metaDataFormat)(), + format(debugMetaFormat)(), formatter ), }); @@ -114,4 +116,5 @@ const logger = winston.createLogger({ module.exports = { logger, buildLogger: logger.child.bind(logger), + debugMeta: { initMiddleware, getDebugMeta }, }; diff --git a/lib/debug-meta.js b/lib/debug-meta.js new file mode 100644 index 0000000..24fe761 --- /dev/null +++ b/lib/debug-meta.js @@ -0,0 +1,38 @@ +"use strict"; + +const { AsyncLocalStorage } = require("node:async_hooks"); + +const debugMetaStorage = new AsyncLocalStorage(); + +/** + * Generate an Express middleware that will add data from the request to be logged + * @param {(req) => object} getDebugMetaFromReq A function that takes the + * request and response objects and returns an object to be added to the debug meta + */ +function initDebugMetaMiddleware(getDebugMetaFromReq) { + return (req, res, next) => { + const debugMeta = getDebugMetaFromReq(req); + debugMetaStorage.run(debugMeta, () => { + next(); + }); + }; +} + +function debugMetaFormat(info) { + const debugMeta = { ...getDebugMeta(), ...info.metaData?.meta }; + if (Object.keys(debugMeta).length === 0) return info; + return { + ...info, + metaData: { meta: { ...getDebugMeta(), ...info.metaData?.meta } }, + }; +} + +function getDebugMeta() { + return debugMetaStorage.getStore() || {}; +} + +module.exports = { + initDebugMetaMiddleware, + debugMetaFormat, + getDebugMeta, +}; diff --git a/package.json b/package.json index 7f87bc7..2c62c61 100644 --- a/package.json +++ b/package.json @@ -8,7 +8,7 @@ "Markus Ekholm", "Jens Carlén" ], - "version": "7.0.3", + "version": "7.1.0", "engines": { "node": ">=16 <=18", "yarn": "please use npm" diff --git a/test/meta-data-test.js b/test/meta-data-test.js index 1d6f906..8a512e4 100644 --- a/test/meta-data-test.js +++ b/test/meta-data-test.js @@ -1,6 +1,7 @@ "use strict"; const transport = require("./helpers/test-transport"); +const debugMeta = require("../lib/debug-meta"); const proxyquire = require("proxyquire").noPreserveCache(); @@ -63,4 +64,30 @@ describe("logging messages with default metaData", () => { log.message.should.eql("some message one { true: false }"); log.location.should.include("test/meta-data-test.js"); }); + + it("should log data from debugMetaMiddleware automatically", () => { + const logger = winston.child(); + + const middleware = debugMeta.initDebugMetaMiddleware((req) => req.debugMeta); + + middleware({ debugMeta: { foo: "bar" } }, {}, () => { + logger.info("some message"); + }); + const log = transport.logs.shift(); + log.message.should.eql("some message"); + log.metaData.should.eql({ meta: { foo: "bar" } }); + }); + + it("should merge data from debugMetaMiddleware and passed metadata", () => { + const logger = winston.child(); + + const middleware = debugMeta.initDebugMetaMiddleware((req) => req.debugMeta); + + middleware({ debugMeta: { foo: "bar" } }, {}, () => { + logger.info("some message", { bar: "baz" }); + }); + const log = transport.logs.shift(); + log.message.should.eql("some message"); + log.metaData.should.eql({ meta: { foo: "bar", bar: "baz" } }); + }); }); From f487d1a27482473207cc42b3da6460723bf16666 Mon Sep 17 00:00:00 2001 From: Mattias Olla Date: Fri, 13 Oct 2023 16:50:47 +0200 Subject: [PATCH 2/2] Add debug metadata instructions to README --- README.md | 38 ++++++++++++++++++++++++++++++++++---- 1 file changed, 34 insertions(+), 4 deletions(-) diff --git a/README.md b/README.md index ff5477d..ebbf770 100644 --- a/README.md +++ b/README.md @@ -1,26 +1,31 @@ # lu-logger + ![Node.js CI](https://github.com/BonnierNews/lu-logger/actions/workflows/nodejs.yml/badge.svg) ## Purpose and features + File name and line number of the log caller is also added when logging in debug level. ## Configuration + A configuration object must be passed to the constructor when initiating the logger. ### Example + ```js const logger = require("lu-logger")({ - "log": "stdout", // Or file, required - "logLevel": "debug", // Minimum level to log - "logJson": true // Log JSON objects or string messages, defaults to true + log: "stdout", // Or file, required + logLevel: "debug", // Minimum level to log + logJson: true, // Log JSON objects or string messages, defaults to true }); ``` + ## Metrics + All log events will also increment a counter `_logged_total` with the level as label. The `metricPrefix` will be automatically resolved from the calling applications `name` in package.json. If there is no `name` in package.json the `metricPrefix` will be `undefined`; - Example of metrics produced: ``` @@ -32,12 +37,16 @@ orderapi_logged_total{level="debug"} 2 ``` ## Log output mode + When log mode `file` is enabled, the log will be written to a file at `/logs/.log` directory, where `app root` is the folder containing the `package.json` file. Log mode `stdout` will log to stdout. ### Example + ### #JSON object in the log + The JSON below is an example of a log entry when `logJson` is set to true (or omitted) and `logLevel` is set to debug. + ```json { "data": { @@ -53,6 +62,27 @@ The JSON below is an example of a log entry when `logJson` is set to true (or om } ``` +## Debug metadata + +This library provides a mechanism for automatically logging debug metadata (e.g. correlation IDs). +This is implemented with inspiration from [this article](https://dev.to/elmatella/my-logging-strategy-for-express-1mk8), +by using an [`AsyncLocalStorage`](https://nodejs.org/api/async_context.html#class-asynclocalstorage) variable, +which is local to each `async` context. +It then provides a middleware factory for Express which sets this from the request and then logs it out automatically. +The calling library is free to define how to get the metadata from the request. +As an example + +```js +const express = require("express"); + +const { debugMeta } = require("lu-logger"); + +const app = express(); + +app.use(debugMeta.initMiddleware((req) => req.debugMeta)); +``` + ## Version notes: + v2.x supports node 8,10 (but works at least to node 14) v3.x supports node 12,14,16