Merge pull request #58 from BonnierNews/feature/correlation-id-magic

Handle correlation IDs automagically

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 `<metricPrefix>_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 `<app root>/logs/<NODE_ENV>.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

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,11 +108,13 @@ const logger = winston.createLogger({
     format(logLevel)(),
     format(location)(),
     format(metaDataFormat)(),
+    format(debugMetaFormat)(),
     formatter
   ),
 });
 
 module.exports = {
   logger,
   buildLogger: logger.child.bind(logger),
+  debugMeta: { initMiddleware, getDebugMeta },
 };

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,
+};

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"

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" } });
+  });
 });