From e4a98d487cfb89e3559eb4f2d481763cb982e339 Mon Sep 17 00:00:00 2001 From: Sam Chung Date: Sat, 21 May 2022 11:02:36 +1000 Subject: [PATCH] feat(RequestLogging): Add `createContextStorage` (#153) --- README.md | 2 +- package.json | 3 +- src/requestLogging/README.md | 99 ++++++++++++++--- src/requestLogging/requestLogging.test.ts | 123 +++++++++++++++++++++- src/requestLogging/requestLogging.ts | 40 ++++++- yarn.lock | 5 + 6 files changed, 252 insertions(+), 20 deletions(-) diff --git a/README.md b/README.md index 78b177b..08a9a01 100644 --- a/README.md +++ b/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) diff --git a/package.json b/package.json index c2a06eb..cade583 100644 --- a/package.json +++ b/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", diff --git a/src/requestLogging/README.md b/src/requestLogging/README.md index 5f4aa49..8ecd192 100644 --- a/src/requestLogging/README.md +++ b/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. diff --git a/src/requestLogging/requestLogging.test.ts b/src/requestLogging/requestLogging.test.ts index 9d6a045..80d352d 100644 --- a/src/requestLogging/requestLogging.test.ts +++ b/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, + } + `, + ); + }), + ); + + 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', + }); + }); + }); }); diff --git a/src/requestLogging/requestLogging.ts b/src/requestLogging/requestLogging.ts index df6151e..8618cc7 100644 --- a/src/requestLogging/requestLogging.ts +++ b/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; + /** * 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 = ( throw err; } }; + +/* + * Creates a logger context storage instance + * + */ +export const createContextStorage = () => { + const loggerContext = new AsyncLocalStorage(); + + 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() ?? {}, + }; +}; diff --git a/yarn.lock b/yarn.lock index 8f59314..b1da8fe 100644 --- a/yarn.lock +++ b/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"