feat(RequestLogging): Add createContextStorage (#153)

README.md

@@ -2,7 +2,7 @@
 
 [![GitHub Release](https://github.com/seek-oss/koala/workflows/Release/badge.svg?branch=master)](https://github.com/seek-oss/koala/actions?query=workflow%3ARelease)
 [![GitHub Validate](https://github.com/seek-oss/koala/workflows/Validate/badge.svg?branch=master)](https://github.com/seek-oss/koala/actions?query=workflow%3AValidate)
-[![Node.js version](https://img.shields.io/badge/node-%3E%3D%2010-brightgreen)](https://nodejs.org/en/)
+[![Node.js version](https://img.shields.io/badge/node-%3E%3D%2012.17-brightgreen)](https://nodejs.org/en/)
 [![npm package](https://img.shields.io/npm/v/seek-koala)](https://www.npmjs.com/package/seek-koala)
 [![Powered by skuba](https://img.shields.io/badge/🤿%20skuba-powered-009DC4)](https://github.com/seek-oss/skuba)
 

package.json

@@ -10,6 +10,7 @@
     "@koa/router": "10.1.1",
     "@types/koa": "2.13.4",
     "@types/koa__router": "8.0.11",
+    "@types/node": "16.0.0",
     "@types/supertest": "2.0.12",
     "@types/uuid": "8.3.4",
     "hot-shots": "9.0.0",
@@ -18,7 +19,7 @@
     "supertest": "6.2.2"
   },
   "engines": {
-    "node": ">=10.7"
+    "node": ">=12.17"
   },
   "files": [
     "lib*/**/*.d.ts",

src/requestLogging/README.md

@@ -5,25 +5,32 @@
 This add-on facilitates logging information about requests and responses.
 It's intended to work with an app-provided logger such as [pino](http://getpino.io/) or [Bunyan](https://github.com/trentm/node-bunyan).
 
-It provides two main features:
+It provides three main features:
 
+- [`createContextStorage`](#context-logging) returns a logger context storage instance.
 - [`contextFields`](#context-fields) returns log fields related to the incoming request.
-
 - [`createMiddleware`](#request-log) creates a Koa middleware for logging request and response information
 
-## Context Fields
+## Context Logging
 
-`contextFields` returns an object containing key-value pairs for the request method, route, URL, [`X-Request-Id`] and ad-hoc `X-Session-Id`.
-This is intended to provide the essential information about the request;
-the full request details can be correlated with the request log via `x-request-id`.
+`createContextStorage` returns a logger context storage instance with two methods: `createContextMiddleware` and `mixin`. This is simply a wrapper over an [AsyncLocalStorage](https://nodejs.org/docs/latest-v16.x/api/async_context.html#class-asynclocalstorage) instance. Please note: for performance reasons it is recommended that you use Node.js version v16.2.0+ if you intend to use this.
 
-The route properties assume use of `@koa/router`, and are omitted if the expected metadata is not present on context.
+`createContextMiddleware` is a function which returns a Koa Middleware that injects the logger context into an AsyncLocalStorage instance.
+It must be added early in the Koa Middleware chain if you want logger calls to contain request context fields. It also provides an optional
+`getFieldsFn` parameter if you wish to provide your own context fields alongside the default [`contextFields`](#context-fields).
 
-The returned object can be used to construct a child logger that annotates log entries with request-specific information.
-This can be accomplished using the `child` method of Bunyan or pino loggers.
+```typescript
+const contextMiddleware = createContextMiddleware();
 
-`contextFields` requires access to the Koa context to generate a stable [`X-Request-Id`].
-See the [TracingHeaders add-on](../tracingHeaders/README.md) for more information.
+const customContextMiddleware = createContextMiddleware((ctx, fields) => ({
+  advertiserId: ctx.state.advertiserId,
+  ...fields,
+}));
+```
+
+`mixin` is a function which returns the context fields from the storage. It returns an empty object if no context can be found. This should be called every time a logger is called. You can attach this to Pino's [mixin](https://github.com/pinojs/pino/blob/master/docs/api.md#mixin-function) field when you create a logger instance.
+
+Attaching the `contextMiddleware` to the Koa Middleware chain and `mixin` to the logger instance will enable you to import the logger instance in any file and still retain logger context.
 
 ### Usage
 
@@ -32,17 +39,19 @@ See the [TracingHeaders add-on](../tracingHeaders/README.md) for more informatio
 import pino from 'pino';
 import { RequestLogging } from 'seek-koala';
 
-// Create a root logger with the app name and version
-const rootLogger = pino({
+const { createContextMiddleware, mixin } = createLoggerContextStorage();
+
+const contextMiddleware = createContextMiddleware();
+
+const logger = pino({
   name: appConfig.name,
   base: {
     version: appConfig.version,
   },
+  mixin,
 });
 
 const helloWorldHandler = async (ctx: Koa.Context) => {
-  // Create a request-specific logger
-  const logger = rootLogger.child(RequestLogging.contextFields(ctx));
   logger.info('About to return Hello World!');
 
   ctx.body = 'Hello world';
@@ -54,9 +63,34 @@ const router = new Router().get(
   helloWorldHandler,
 );
 
-const app = new Koa().use(router.routes()).use(router.allowedMethods());
+const app = new Koa()
+  .use(contextMiddleware);
+  .use(router.routes())
+  .use(router.allowedMethods())
+```
+
+## Context Fields
+
+`contextFields` returns an object containing key-value pairs for the request method, route, URL, [`X-Request-Id`] and ad-hoc `X-Session-Id`.
+This is intended to provide the essential information about the request;
+the full request details can be correlated with the request log via `x-request-id`.
+
+The route properties assume use of `@koa/router`, and are omitted if the expected metadata is not present on context.
+
+The returned object can be used to construct a child logger that annotates log entries with request-specific information.
+This can be accomplished using the `child` method of Bunyan or pino loggers.
+
+You may override or supply your own fields using the optional `fields` parameter.
+
+```typescript
+const fields = contextFields(ctx);
+
+const customFields = contextFields(ctx, { myField: 'hello world!' });
 ```
 
+`contextFields` requires access to the Koa context to generate a stable [`X-Request-Id`].
+See the [TracingHeaders add-on](../tracingHeaders/README.md) for more information.
+
 ### Example Log Entry
 
 ```jsonc
@@ -77,6 +111,39 @@ const app = new Koa().use(router.routes()).use(router.allowedMethods());
 }
 ```
 
+### Usage
+
+```typescript
+// This example uses pino. See the next section for a Bunyan example.
+import pino from 'pino';
+import { RequestLogging } from 'seek-koala';
+
+// Create a root logger with the app name and version
+const rootLogger = pino({
+  name: appConfig.name,
+  base: {
+    version: appConfig.version,
+  },
+});
+
+const helloWorldHandler = async (ctx: Koa.Context) => {
+  // Create a request-specific logger
+  // NB: This is not required if you are using the logger context storage implementation
+  const logger = rootLogger.child(RequestLogging.contextFields(ctx));
+  logger.info('About to return Hello World!');
+
+  ctx.body = 'Hello world';
+};
+
+const router = new Router().get(
+  'readGreeting',
+  '/internal/:greeting',
+  helloWorldHandler,
+);
+
+const app = new Koa().use(router.routes()).use(router.allowedMethods());
+```
+
 ## Request Log
 
 `createMiddleware` records information incoming requests and outgoing responses.

src/requestLogging/requestLogging.test.ts

@@ -2,7 +2,12 @@ import Router, { Middleware } from '@koa/router';
 import Koa, { Context, Next } from 'koa';
 import request from 'supertest';
 
-import { contextFields, createMiddleware } from './requestLogging';
+import {
+  Fields,
+  contextFields,
+  createContextStorage,
+  createMiddleware,
+} from './requestLogging';
 
 describe('RequestLogging', () => {
   const createAgent = (...middlewares: Middleware[]) => {
@@ -77,6 +82,41 @@ describe('RequestLogging', () => {
         .set('user-agent', 'Safari')
         .expect(200, 'hello');
     });
+
+    it('returns extra fields along with the context data when the fields parameter is provided', () => {
+      const router = new Router().get(
+        'getRoute',
+        '/route/:segment',
+        jest.fn((ctx: Context) => {
+          ctx.status = 200;
+          ctx.body = 'hello';
+
+          const fields = contextFields(ctx, { extra: 'field!' });
+
+          expect(fields).toMatchInlineSnapshot(
+            {
+              'x-request-id': expect.any(String),
+              extra: 'field!',
+            },
+            `
+            Object {
+              "extra": "field!",
+              "method": "GET",
+              "route": "/route/:segment",
+              "routeName": "getRoute",
+              "url": "/route/foo?bar",
+              "x-request-id": Any<String>,
+            }
+          `,
+          );
+        }),
+      );
+
+      return createAgent(router.routes())
+        .get('/route/foo?bar')
+        .set('user-agent', 'Safari')
+        .expect(200, 'hello');
+    });
   });
 
   describe('createMiddleware', () => {
@@ -221,4 +261,85 @@ describe('RequestLogging', () => {
       expect(err).toBe(expectedError);
     });
   });
+
+  describe('createContextStorage', () => {
+    it('returns both a createContextMiddleware and mixin function', () => {
+      const { createContextMiddleware, mixin } = createContextStorage();
+
+      expect(createContextMiddleware).toBeInstanceOf(Function);
+      expect(mixin).toBeInstanceOf(Function);
+    });
+
+    it('should return an empty object if the context storage is empty', () => {
+      const { mixin } = createContextStorage();
+
+      expect(mixin()).toStrictEqual({});
+    });
+
+    it('should set the context and return the current contents of a context storage', async () => {
+      const { createContextMiddleware, mixin } = createContextStorage();
+
+      const contextMiddleware = createContextMiddleware();
+
+      // We need to grab the result from within the run() chain
+      let result: Fields = {};
+      const setResultMiddleware = jest.fn(async (_ctx: Context, next: Next) => {
+        result = mixin();
+        await next();
+      });
+
+      const handler = jest.fn((ctx: Context) => {
+        ctx.status = 201;
+      });
+
+      await createAgent(contextMiddleware, setResultMiddleware, handler)
+        .post('/my/test/service')
+        .set('Authenticated-User', 'somesercret')
+        .set('user-agent', 'Safari')
+        .set('x-session-id', '8f859d2a-46a7-4b2d-992b-3da4a18b7ab5')
+        .expect(201);
+
+      expect(result).toStrictEqual({
+        method: 'POST',
+        url: '/my/test/service',
+        'x-request-id': expect.any(String),
+        'x-session-id': '8f859d2a-46a7-4b2d-992b-3da4a18b7ab5',
+      });
+    });
+
+    it('should allow for custom fields in the context', async () => {
+      const { createContextMiddleware, mixin } = createContextStorage();
+
+      const contextMiddleware = createContextMiddleware((_ctx, fields) => ({
+        extra: 'field',
+        ...fields,
+      }));
+
+      // We need to grab the result from within the run() chain
+      let result: Fields = {};
+      const setResultMiddleware = jest.fn(async (_ctx: Context, next: Next) => {
+        result = mixin();
+        await next();
+      });
+
+      const handler = jest.fn((ctx: Context) => {
+        ctx.status = 201;
+      });
+
+      await createAgent(contextMiddleware, setResultMiddleware, handler)
+        .post('/my/test/service')
+        .set('Authenticated-User', 'somesercret')
+        .set('user-agent', 'Safari')
+        .set('x-session-id', '8f859d2a-46a7-4b2d-992b-3da4a18b7ab5')
+        .expect(201);
+
+      expect(result).toStrictEqual({
+        method: 'POST',
+        extra: 'field',
+        url: '/my/test/service',
+        'x-request-id': expect.any(String),
+        'x-session-id': '8f859d2a-46a7-4b2d-992b-3da4a18b7ab5',
+      });
+    });
+  });
 });

src/requestLogging/requestLogging.ts

@@ -1,3 +1,5 @@
+import { AsyncLocalStorage } from 'async_hooks';
+
 import Koa from 'koa';
 
 import { thrown } from '../errorMiddleware/errorMiddleware';
@@ -66,6 +68,14 @@ const replaceHeaders = (
   return cleanedHeaders;
 };
 
+/**
+ * Returns context fields for the passed Koa context
+ */
+export type ContextFields = (
+  ctx: Koa.Context,
+  fields?: Fields,
+) => Record<string, unknown>;
+
 /**
  * Returns an object of request-specific log fields
  *
@@ -75,8 +85,11 @@ const replaceHeaders = (
  *
  * The route properties assume use of `@koa/router`, and are omitted if the
  * expected metadata is not present on context.
+ *
+ * @param ctx - Koa Context
+ * @param fields - Optional fields to add to the object
  */
-export const contextFields = (ctx: Koa.Context): Fields => {
+export const contextFields: ContextFields = (ctx, fields): Fields => {
   const { adhocSessionID, requestID } = tracingFromContext(ctx);
 
   return {
@@ -92,6 +105,7 @@ export const contextFields = (ctx: Koa.Context): Fields => {
     ...(typeof adhocSessionID === 'string' && {
       'x-session-id': adhocSessionID,
     }),
+    ...fields,
   };
 };
 
@@ -160,3 +174,27 @@ export const createMiddleware = <StateT extends State, CustomT>(
       throw err;
     }
   };
+
+/*
+ * Creates a logger context storage instance
+ *
+ */
+export const createContextStorage = () => {
+  const loggerContext = new AsyncLocalStorage<Fields>();
+
+  return {
+    /**
+     * Koa Middleware that injects the logger context into an AsyncLocalStorage instance
+     * @param getFieldsFn - Optional function to return a set of fields to include in context. Defaults to `contextFields`
+     */
+    createContextMiddleware:
+      (getFieldsFn: ContextFields = contextFields): Koa.Middleware =>
+      async (ctx, next) => {
+        await loggerContext.run(getFieldsFn(ctx, contextFields(ctx)), next);
+      },
+    /**
+     * Returns fields from the logger context store
+     */
+    mixin: () => loggerContext.getStore() ?? {},
+  };
+};

yarn.lock

@@ -1271,6 +1271,11 @@
   resolved "https://registry.yarnpkg.com/@types/node/-/node-17.0.23.tgz#3b41a6e643589ac6442bdbd7a4a3ded62f33f7da"
   integrity sha512-UxDxWn7dl97rKVeVS61vErvw086aCYhDLyvRQZ5Rk65rZKepaFdm53GeqXaKBuOhED4e9uWq34IC3TdSdJJ2Gw==
 
+"@types/node@16.0.0":
+  version "16.0.0"
+  resolved "https://registry.yarnpkg.com/@types/node/-/node-16.0.0.tgz#067a6c49dc7a5c2412a505628e26902ae967bf6f"
+  integrity sha512-TmCW5HoZ2o2/z2EYi109jLqIaPIi9y/lc2LmDCWzuCi35bcaQ+OtUh6nwBiFK7SOu25FAU5+YKdqFZUwtqGSdg==
+
 "@types/normalize-package-data@^2.4.0":
   version "2.4.1"
   resolved "https://registry.yarnpkg.com/@types/normalize-package-data/-/normalize-package-data-2.4.1.tgz#d3357479a0fdfdd5907fe67e17e0a85c906e1301"