Steal #864 for lambda-sqs-worker (#871)

* Steal #864 for lambda-sqs-worker

* Add changeset

Author: 72636c

.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');
 });

.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');
+  });
+```

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');
   });
 });

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<SQSEvent>(async (event, { logger }) => {
+export const handler = createHandler<SQSEvent>(async (event) => {
   // Treat an empty object as our smoke test event.
   if (!Object.keys(event).length) {
     logger.info('received smoke test request');

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();
   });
 });

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 = <Event, Output = unknown>(
-  fn: (event: Event, ctx: { logger: Logger }) => Promise<Output>,
-) =>
-  async function lambdaHandler(event: Event, ctx: Context) {
-    const logger = contextLogger(ctx);
+export const createHandler =
+  <Event, Output = unknown>(fn: (event: Event) => Promise<Output>) =>
+  (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');
+      }
+    });

template/lambda-sqs-worker/src/framework/logging.ts

@@ -1,22 +1,27 @@
+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<LoggerContext>();
+
+export const logger = createLogger({
   base: {
     environment: config.environment,
     version: config.version,
   },
 
   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 });

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