More logs (#154)

* More logs

* Store deployment ID in context

Author: AaronMoat

.changeset/social-houses-pull.md

@@ -0,0 +1,5 @@
+---
+'@seek/aws-codedeploy-infra': minor
+---
+
+Enhance logs with additional context

packages/infra/src/handlers/framework/context.test.ts

@@ -1,17 +1,12 @@
 import { setTimeout } from 'timers/promises';
 import { inspect } from 'util';
 
-import {
-  getAbortSignal,
-  getContext,
-  getRequestId,
-  storage,
-  withTimeout,
-} from './context.js';
+import { getAbortSignal, getContext, storage, withTimeout } from './context.js';
 
 const context = {
   abortSignal: new AbortController().signal,
   requestId: 'mock-request-id',
+  deploymentId: 'mock-deployment-id',
 };
 
 describe('getAbortSignal', () => {
@@ -29,11 +24,6 @@ describe('getContext', () => {
     expect(getContext()).toStrictEqual({}));
 });
 
-describe('getRequestId', () => {
-  it('returns the current request ID where available', () =>
-    storage.run(context, () => expect(getRequestId()).toBe(context.requestId)));
-});
-
 describe('withTimeout', () => {
   it('returns task result on happy path', async () => {
     const result = 'mock-result';

packages/infra/src/handlers/framework/context.ts

@@ -3,6 +3,7 @@ import { AsyncLocalStorage } from 'async_hooks';
 type Context = {
   abortSignal?: AbortSignal;
   requestId?: string;
+  deploymentId?: string;
 };
 
 export const storage = new AsyncLocalStorage<Context>();
@@ -11,8 +12,6 @@ export const getContext = (): Context => storage.getStore() ?? {};
 
 export const getAbortSignal = () => storage.getStore()?.abortSignal;
 
-export const getRequestId = () => storage.getStore()?.requestId;
-
 export const withTimeout = async <T>(
   task: () => Promise<T>,
   timeoutMs: number,

packages/infra/src/handlers/framework/logging.ts

@@ -2,7 +2,7 @@ import createLogger from '@seek/logger';
 
 import { config } from '../config.js';
 
-import { getRequestId } from './context.js';
+import { getContext } from './context.js';
 
 export const testLogs: unknown[] = [];
 
@@ -14,7 +14,14 @@ export const logger = createLogger(
   {
     base: null,
 
-    mixin: () => ({ awsRequestId: getRequestId() }),
+    mixin: () => {
+      const context = getContext();
+
+      return {
+        awsRequestId: context.requestId,
+        deploymentId: context.deploymentId,
+      };
+    },
 
     transport:
       config.environment === 'local' ? { target: 'pino-pretty' } : undefined,

packages/infra/src/handlers/index.test.ts

@@ -10,17 +10,26 @@ import {
 import { mockClient } from 'aws-sdk-client-mock';
 
 import { testLogs } from './framework/logging.js';
-import { processEvent } from './process/process.js';
+import { getDeploymentInfo, process } from './process/process.js';
 
 import { handler } from './index.js';
 
 const codeDeploy = mockClient(CodeDeployClient);
 
-const processEventMock = jest.mocked(processEvent);
+const getDeploymentInfoMock = jest.mocked(getDeploymentInfo);
+const processMock = jest.mocked(process);
+
+beforeEach(() => {
+  getDeploymentInfoMock.mockResolvedValue({
+    applicationName: 'beep',
+    revision: { string: { content: 'stuff' } },
+  });
+});
 
 afterEach(() => {
   codeDeploy.reset();
-  processEventMock.mockReset();
+  getDeploymentInfoMock.mockReset();
+  processMock.mockReset();
   testLogs.length = 0;
 });
 
@@ -39,13 +48,13 @@ describe('handler', () => {
   };
 
   it('reports a success back to CodeDeploy', async () => {
-    processEventMock.mockResolvedValue(undefined);
+    processMock.mockResolvedValue(undefined);
 
     codeDeploy.on(PutLifecycleEventHookExecutionStatusCommand).resolves({});
 
     await expect(handler(event, context)).resolves.toBeUndefined();
 
-    expect(processEventMock).toHaveBeenCalledTimes(1);
+    expect(processMock).toHaveBeenCalledTimes(1);
 
     expect(codeDeploy).toHaveReceivedNthCommandWith(
       1,
@@ -59,9 +68,14 @@ describe('handler', () => {
 
     expect(testLogs).toStrictEqual([
       {
+        applicationName: 'beep',
         awsRequestId: context.awsRequestId,
+        deploymentId: 'mock-deployment-id',
         level: 30,
         msg: 'Reported lifecycle event status',
+        revision: {
+          string: { content: 'stuff' },
+        },
         status: LifecycleEventStatus.SUCCEEDED,
         timestamp: expect.any(String),
       },
@@ -80,13 +94,13 @@ describe('handler', () => {
       },
     );
 
-    processEventMock.mockRejectedValue(err);
+    processMock.mockRejectedValue(err);
 
     codeDeploy.on(PutLifecycleEventHookExecutionStatusCommand).resolves({});
 
     await expect(handler(event, context)).resolves.toBeUndefined();
 
-    expect(processEventMock).toHaveBeenCalledTimes(1);
+    expect(processMock).toHaveBeenCalledTimes(1);
 
     expect(codeDeploy).toHaveReceivedNthCommandWith(
       1,
@@ -100,7 +114,9 @@ describe('handler', () => {
 
     expect(testLogs).toStrictEqual([
       {
+        applicationName: 'beep',
         awsRequestId: context.awsRequestId,
+        deploymentId: 'mock-deployment-id',
         err: {
           message: err.message,
           payload: err.payload,
@@ -109,12 +125,20 @@ describe('handler', () => {
         },
         level: 50,
         msg: 'Failed to process lifecycle event',
+        revision: {
+          string: { content: 'stuff' },
+        },
         timestamp: expect.any(String),
       },
       {
+        applicationName: 'beep',
         awsRequestId: context.awsRequestId,
+        deploymentId: 'mock-deployment-id',
         level: 30,
         msg: 'Reported lifecycle event status',
+        revision: {
+          string: { content: 'stuff' },
+        },
         status: LifecycleEventStatus.FAILED,
         timestamp: expect.any(String),
       },
@@ -124,7 +148,7 @@ describe('handler', () => {
   it('throws on failure to report a success', async () => {
     const err = new Error('mock-error');
 
-    processEventMock.mockResolvedValue(undefined);
+    processMock.mockResolvedValue(undefined);
 
     codeDeploy.on(PutLifecycleEventHookExecutionStatusCommand).rejects(err);
 
@@ -134,7 +158,7 @@ describe('handler', () => {
       `"Failed to report lifecycle event status"`,
     );
 
-    expect(processEventMock).toHaveBeenCalledTimes(1);
+    expect(processMock).toHaveBeenCalledTimes(1);
 
     expect(codeDeploy).toHaveReceivedNthCommandWith(
       1,
@@ -148,11 +172,16 @@ describe('handler', () => {
 
     expect(testLogs).toStrictEqual([
       {
+        applicationName: 'beep',
         awsRequestId: context.awsRequestId,
+        deploymentId: 'mock-deployment-id',
         err: expect.objectContaining({ message: err.message }),
         level: 50,
         msg: 'Failed to report lifecycle event status',
         status: LifecycleEventStatus.SUCCEEDED,
+        revision: {
+          string: { content: 'stuff' },
+        },
         timestamp: expect.any(String),
       },
     ]);
@@ -166,15 +195,15 @@ describe('handler', () => {
       .on(PutLifecycleEventHookExecutionStatusCommand)
       .rejects(reportError);
 
-    processEventMock.mockRejectedValue(processError);
+    processMock.mockRejectedValue(processError);
 
     await expect(
       handler(event, context),
     ).rejects.toThrowErrorMatchingInlineSnapshot(
       `"Failed to report lifecycle event status"`,
     );
 
-    expect(processEventMock).toHaveBeenCalledTimes(1);
+    expect(processMock).toHaveBeenCalledTimes(1);
 
     expect(codeDeploy).toHaveReceivedNthCommandWith(
       1,
@@ -188,17 +217,27 @@ describe('handler', () => {
 
     expect(testLogs).toStrictEqual([
       {
+        applicationName: 'beep',
         awsRequestId: context.awsRequestId,
+        deploymentId: 'mock-deployment-id',
         err: expect.objectContaining({ message: processError.message }),
         level: 50,
         msg: 'Failed to process lifecycle event',
+        revision: {
+          string: { content: 'stuff' },
+        },
         timestamp: expect.any(String),
       },
       {
+        applicationName: 'beep',
         awsRequestId: context.awsRequestId,
+        deploymentId: 'mock-deployment-id',
         err: expect.objectContaining({ message: reportError.message }),
         level: 50,
         msg: 'Failed to report lifecycle event status',
+        revision: {
+          string: { content: 'stuff' },
+        },
         status: LifecycleEventStatus.FAILED,
         timestamp: expect.any(String),
       },

packages/infra/src/handlers/index.ts

@@ -3,36 +3,54 @@ import type { Context } from 'aws-lambda';
 
 import { storage, withTimeout } from './framework/context.js';
 import { logger } from './framework/logging.js';
-import { processEvent } from './process/process.js';
+import {
+  type DeploymentInfo,
+  getDeploymentInfo,
+  process,
+} from './process/process.js';
 import { reportEventStatus } from './report.js';
 import type { CodeDeployLifecycleHookEvent } from './types.js';
 
 export const handler = (
   event: CodeDeployLifecycleHookEvent,
   context: Pick<Context, 'awsRequestId' | 'getRemainingTimeInMillis'>,
 ): Promise<void> =>
-  storage.run({ requestId: context.awsRequestId }, async () => {
-    // Reserve a generous 30 seconds to report the status back to CodeDeploy.
-    const timeoutMs = context.getRemainingTimeInMillis() - 30_000;
-
-    let status: LifecycleEventStatus = LifecycleEventStatus.FAILED;
-    try {
-      await withTimeout(() => processEvent(event), timeoutMs);
-
-      status = LifecycleEventStatus.SUCCEEDED;
-    } catch (err) {
-      logger.error({ err }, 'Failed to process lifecycle event');
-    }
-
-    try {
-      await reportEventStatus(event, status);
-
-      logger.info({ status }, 'Reported lifecycle event status');
-    } catch (err) {
-      const message = 'Failed to report lifecycle event status';
-
-      logger.error({ err, status }, message);
-
-      throw new Error(message);
-    }
-  });
+  storage.run(
+    { requestId: context.awsRequestId, deploymentId: event.DeploymentId },
+    async () => {
+      // Reserve a generous 30 seconds to report the status back to CodeDeploy.
+      const timeoutMs = context.getRemainingTimeInMillis() - 30_000;
+
+      let status: LifecycleEventStatus = LifecycleEventStatus.FAILED;
+      let deploymentInfo: DeploymentInfo | undefined;
+
+      try {
+        await withTimeout(async () => {
+          deploymentInfo = await getDeploymentInfo(event);
+          return process(deploymentInfo);
+        }, timeoutMs);
+
+        status = LifecycleEventStatus.SUCCEEDED;
+      } catch (err) {
+        logger.error(
+          { err, ...deploymentInfo },
+          'Failed to process lifecycle event',
+        );
+      }
+
+      try {
+        await reportEventStatus(event, status);
+
+        logger.info(
+          { status, ...deploymentInfo },
+          'Reported lifecycle event status',
+        );
+      } catch (err) {
+        const message = 'Failed to report lifecycle event status';
+
+        logger.error({ err, status, ...deploymentInfo }, message);
+
+        throw new Error(message);
+      }
+    },
+  );