diff --git a/.changeset/olive-worms-run.md b/.changeset/olive-worms-run.md index 290ae15f1..8e6e1da90 100644 --- a/.changeset/olive-worms-run.md +++ b/.changeset/olive-worms-run.md @@ -10,13 +10,17 @@ Before: ```typescript import createLogger from '@seek/logger'; -import Koa from 'koa'; +import Koa, { Context } from 'koa'; import { RequestLogging } from 'seek-koala'; + const rootLogger = createLogger(); + const contextLogger = (ctx: Context) => rootLogger.child(RequestLogging.contextFields(ctx)); + const app = new Koa().use((ctx) => { rootLogger.info('Has no context'); + contextLogger(ctx).info('Has context'); }); ``` @@ -27,10 +31,14 @@ After: import createLogger from '@seek/logger'; import Koa from 'koa'; import { RequestLogging } from 'seek-koala'; + const { createContextMiddleware, mixin } = RequestLogging.createContextStorage(); + const contextMiddleware = createContextMiddleware(); + const logger = createLogger({ mixin }); + const app = new Koa().use(contextMiddleware).use((ctx) => { logger.info('Has context'); }); diff --git a/.changeset/pink-flowers-vanish.md b/.changeset/pink-flowers-vanish.md new file mode 100644 index 000000000..515c5caa0 --- /dev/null +++ b/.changeset/pink-flowers-vanish.md @@ -0,0 +1,45 @@ +--- +'skuba': patch +--- + +template/lambda-sqs-worker: Use [AsyncLocalStorage](https://nodejs.org/docs/latest-v16.x/api/async_context.html#asynchronous-context-tracking) to track logger context + +We now employ this Node.js API to thread logging context through the handler of your Lambda function. This enables use of a singleton `logger` instance instead of manually propagating Lambda context and juggling `rootLogger`s and `contextLogger`s, and is equivalent to #864. + +Before: + +```typescript +import createLogger from '@seek/logger'; +import { Context } from 'aws-lambda'; + +const rootLogger = createLogger(); + +const contextLogger = ({ awsRequestId }: Context) => + rootLogger.child({ awsRequestId }); + +const handler = async (_event: unknown, ctx: Context) => { + rootLogger.info('Has no context'); + + contextLogger(ctx).info('Has context'); +}; +``` + +After: + +```typescript +import { AsyncLocalStorage } from 'async_hooks'; + +import createLogger from '@seek/logger'; +import { Context } from 'aws-lambda'; + +const loggerContext = new AsyncLocalStorage<{ awsRequestId: string }>(); + +const logger = createLogger({ + mixin: () => loggerContext.getStore() ?? {}, +}); + +const handler = (_event: unknown, { awsRequestId }: Context) => + loggerContext.run({ awsRequestId }, async () => { + logger.info('Has context'); + }); +``` diff --git a/template/lambda-sqs-worker/src/app.test.ts b/template/lambda-sqs-worker/src/app.test.ts index 5568b01db..b5d7b6e4b 100644 --- a/template/lambda-sqs-worker/src/app.test.ts +++ b/template/lambda-sqs-worker/src/app.test.ts @@ -1,6 +1,6 @@ import { metricsClient } from 'src/framework/metrics'; import { createCtx, createSqsEvent } from 'src/testing/handler'; -import { contextLogger } from 'src/testing/logging'; +import { logger } from 'src/testing/logging'; import { scoringService, sns } from 'src/testing/services'; import { chance, mockJobPublishedEvent } from 'src/testing/types'; @@ -19,7 +19,7 @@ describe('handler', () => { const increment = jest.spyOn(metricsClient, 'increment').mockReturnValue(); - beforeAll(contextLogger.spy); + beforeAll(logger.spy); beforeAll(scoringService.spy); beforeAll(sns.spy); @@ -31,7 +31,7 @@ describe('handler', () => { }); afterEach(() => { - contextLogger.clear(); + logger.clear(); increment.mockClear(); scoringService.clear(); sns.clear(); @@ -44,9 +44,9 @@ describe('handler', () => { expect(scoringService.request).toBeCalledTimes(1); - expect(contextLogger.error).not.toBeCalled(); + expect(logger.error).not.toBeCalled(); - expect(contextLogger.info.mock.calls).toEqual([ + expect(logger.info.mock.calls).toEqual([ [{ count: 1 }, 'received jobs'], [{ snsMessageId: expect.any(String) }, 'scored job'], ['request'], @@ -75,7 +75,7 @@ describe('handler', () => { await expect(app.handler(event, ctx)).rejects.toThrow('invoke error'); - expect(contextLogger.error).toBeCalledWith({ err }, 'request'); + expect(logger.error).toBeCalledWith({ err }, 'request'); }); it('bubbles up SNS error', async () => { @@ -87,7 +87,7 @@ describe('handler', () => { await expect(app.handler(event, ctx)).rejects.toThrow('invoke error'); - expect(contextLogger.error).toBeCalledWith({ err }, 'request'); + expect(logger.error).toBeCalledWith({ err }, 'request'); }); it('throws on zero records', async () => { @@ -97,7 +97,7 @@ describe('handler', () => { await expect(app.handler(event, ctx)).rejects.toThrow('invoke error'); - expect(contextLogger.error).toBeCalledWith({ err }, 'request'); + expect(logger.error).toBeCalledWith({ err }, 'request'); }); it('throws on multiple records', async () => { @@ -110,6 +110,6 @@ describe('handler', () => { await expect(app.handler(event, ctx)).rejects.toThrow('invoke error'); - expect(contextLogger.error).toBeCalledWith({ err }, 'request'); + expect(logger.error).toBeCalledWith({ err }, 'request'); }); }); diff --git a/template/lambda-sqs-worker/src/app.ts b/template/lambda-sqs-worker/src/app.ts index f1c0cb17f..927e28a9e 100644 --- a/template/lambda-sqs-worker/src/app.ts +++ b/template/lambda-sqs-worker/src/app.ts @@ -3,6 +3,7 @@ import 'skuba-dive/register'; import { SQSEvent } from 'aws-lambda'; import { createHandler } from 'src/framework/handler'; +import { logger } from 'src/framework/logging'; import { metricsClient } from 'src/framework/metrics'; import { validateJson } from 'src/framework/validation'; import { scoreJobPublishedEvent, scoringService } from 'src/services/jobScorer'; @@ -16,7 +17,7 @@ const smokeTest = async () => { await Promise.all([scoringService.smokeTest(), sendPipelineEvent({}, true)]); }; -export const handler = createHandler(async (event, { logger }) => { +export const handler = createHandler(async (event) => { // Treat an empty object as our smoke test event. if (!Object.keys(event).length) { logger.info('received smoke test request'); diff --git a/template/lambda-sqs-worker/src/framework/handler.test.ts b/template/lambda-sqs-worker/src/framework/handler.test.ts index f818278f7..f0876ef65 100644 --- a/template/lambda-sqs-worker/src/framework/handler.test.ts +++ b/template/lambda-sqs-worker/src/framework/handler.test.ts @@ -1,5 +1,5 @@ import { createCtx } from 'src/testing/handler'; -import { contextLogger } from 'src/testing/logging'; +import { logger } from 'src/testing/logging'; import { chance } from 'src/testing/types'; import { createHandler } from './handler'; @@ -8,14 +8,14 @@ describe('createHandler', () => { const ctx = createCtx(); const input = chance.paragraph(); - beforeAll(contextLogger.spy); + beforeAll(logger.spy); - afterEach(contextLogger.clear); + afterEach(logger.clear); it('handles happy path', async () => { const output = chance.paragraph(); - const handler = createHandler((event, { logger }) => { + const handler = createHandler((event) => { expect(event).toBe(input); logger.info('hello from handler'); @@ -25,9 +25,9 @@ describe('createHandler', () => { await expect(handler(input, ctx)).resolves.toBe(output); - expect(contextLogger.error).not.toBeCalled(); + expect(logger.error).not.toBeCalled(); - expect(contextLogger.info.mock.calls).toEqual([ + expect(logger.info.mock.calls).toEqual([ ['hello from handler'], ['request'], ]); @@ -40,9 +40,9 @@ describe('createHandler', () => { await expect(handler(input, ctx)).rejects.toThrow('invoke error'); - expect(contextLogger.error.mock.calls).toEqual([[{ err }, 'request']]); + expect(logger.error.mock.calls).toEqual([[{ err }, 'request']]); - expect(contextLogger.info).not.toBeCalled(); + expect(logger.info).not.toBeCalled(); }); it('handles sync error', async () => { @@ -54,8 +54,8 @@ describe('createHandler', () => { await expect(handler(input, ctx)).rejects.toThrow('invoke error'); - expect(contextLogger.error.mock.calls).toEqual([[{ err }, 'request']]); + expect(logger.error.mock.calls).toEqual([[{ err }, 'request']]); - expect(contextLogger.info).not.toBeCalled(); + expect(logger.info).not.toBeCalled(); }); }); diff --git a/template/lambda-sqs-worker/src/framework/handler.ts b/template/lambda-sqs-worker/src/framework/handler.ts index 8c4d76df9..3d3edb9eb 100644 --- a/template/lambda-sqs-worker/src/framework/handler.ts +++ b/template/lambda-sqs-worker/src/framework/handler.ts @@ -1,23 +1,20 @@ -import { Logger } from '@seek/logger'; import { Context } from 'aws-lambda'; -import { contextLogger } from 'src/framework/logging'; +import { logger, loggerContext } from 'src/framework/logging'; -export const createHandler = ( - fn: (event: Event, ctx: { logger: Logger }) => Promise, -) => - async function lambdaHandler(event: Event, ctx: Context) { - const logger = contextLogger(ctx); +export const createHandler = + (fn: (event: Event) => Promise) => + (event: Event, { awsRequestId }: Context) => + loggerContext.run({ awsRequestId }, async () => { + try { + const output = await fn(event); - try { - const output = await fn(event, { logger }); + logger.info('request'); - logger.info('request'); + return output; + } catch (err) { + logger.error({ err }, 'request'); - return output; - } catch (err) { - logger.error({ err }, 'request'); - - throw new Error('invoke error'); - } - }; + throw new Error('invoke error'); + } + }); diff --git a/template/lambda-sqs-worker/src/framework/logging.ts b/template/lambda-sqs-worker/src/framework/logging.ts index 529cc432c..bc9ccd6d1 100644 --- a/template/lambda-sqs-worker/src/framework/logging.ts +++ b/template/lambda-sqs-worker/src/framework/logging.ts @@ -1,9 +1,16 @@ +import { AsyncLocalStorage } from 'async_hooks'; + import createLogger from '@seek/logger'; -import { Context } from 'aws-lambda'; import { config } from 'src/config'; -export const rootLogger = createLogger({ +interface LoggerContext { + awsRequestId: string; +} + +export const loggerContext = new AsyncLocalStorage(); + +export const logger = createLogger({ base: { environment: config.environment, version: config.version, @@ -11,12 +18,10 @@ export const rootLogger = createLogger({ level: config.logLevel, + mixin: () => loggerContext.getStore() ?? {}, + name: config.name, transport: config.environment === 'local' ? { target: 'pino-pretty' } : undefined, }); - -/* istanbul ignore next: @seek/logger interface */ -export const contextLogger = ({ awsRequestId }: Context) => - rootLogger.child({ awsRequestId }); diff --git a/template/lambda-sqs-worker/src/testing/logging.ts b/template/lambda-sqs-worker/src/testing/logging.ts index 999abe6c1..998a9b957 100644 --- a/template/lambda-sqs-worker/src/testing/logging.ts +++ b/template/lambda-sqs-worker/src/testing/logging.ts @@ -1,14 +1,16 @@ import * as logging from 'src/framework/logging'; -export const contextLogger = { +export const logger = { error: jest.fn(), info: jest.fn(), clear: () => { - contextLogger.error.mockClear(); - contextLogger.info.mockClear(); + logger.error.mockClear(); + logger.info.mockClear(); }, - spy: () => - jest.spyOn(logging, 'contextLogger').mockReturnValue(contextLogger as any), + spy: () => { + jest.spyOn(logging.logger, 'error').mockImplementation(logger.error); + jest.spyOn(logging.logger, 'info').mockImplementation(logger.info); + }, };