test: advanced logger use case

Author: dreamorosi

packages/commons/src/Utility.ts

@@ -51,7 +51,10 @@
  * ```
  */
 export class Utility {
-  #initializationType: 'unknown' | 'on-demand' | 'provisioned-concurrency';
+  readonly #initializationType:
+    | 'unknown'
+    | 'on-demand'
+    | 'provisioned-concurrency';
   protected coldStart = true;
   protected readonly defaultServiceName: string = 'service_undefined';
 

packages/logger/package.json

@@ -62,6 +62,10 @@
       "types": [
         "lib/cjs/types/index.d.ts",
         "lib/esm/types/index.d.ts"
+      ],
+      "correlationId": [
+        "lib/cjs/correlationId.d.ts",
+        "lib/esm/correlationId.d.ts"
       ]
     }
   },

packages/logger/tests/e2e/advancedUses.test.FunctionCode.ts

@@ -0,0 +1,63 @@
+import { Logger } from '@aws-lambda-powertools/logger';
+import {
+  correlationPaths,
+  search,
+} from '@aws-lambda-powertools/logger/correlationId';
+import { injectLambdaContext } from '@aws-lambda-powertools/logger/middleware';
+import type { Context } from 'aws-lambda';
+import middy from 'middy5';
+
+const logger = new Logger({
+  logLevel: 'DEBUG',
+  logBufferOptions: {
+    enabled: true,
+    flushOnErrorLog: true,
+  },
+  correlationIdSearchFn: search,
+});
+
+logger.debug('a never buffered debug log');
+
+export const handlerManual = async (event: unknown) => {
+  logger.addContext({} as Context); // we want only the cold start value
+  logger.setCorrelationId(event, correlationPaths.EVENT_BRIDGE);
+
+  logger.debug('a buffered debug log');
+  logger.info('an info log');
+  try {
+    throw new Error('ops');
+  } catch (error) {
+    logger.error('Uncaught error detected, flushing log buffer before exit', {
+      error,
+    });
+  } finally {
+    logger.clearBuffer();
+  }
+};
+
+export const handlerMiddy = middy()
+  .use(
+    injectLambdaContext(logger, {
+      correlationIdPath: correlationPaths.EVENT_BRIDGE,
+      flushBufferOnUncaughtError: true,
+    })
+  )
+  .handler(async () => {
+    logger.debug('a buffered debug log');
+    logger.info('an info log');
+    throw new Error('ops');
+  });
+
+class Lambda {
+  @logger.injectLambdaContext({
+    correlationIdPath: correlationPaths.EVENT_BRIDGE,
+    flushBufferOnUncaughtError: true,
+  })
+  public async handler(_event: unknown, _context: Context) {
+    logger.debug('a buffered debug log');
+    logger.info('an info log');
+    throw new Error('ops');
+  }
+}
+const lambda = new Lambda();
+export const handlerDecorator = lambda.handler.bind(lambda);

packages/logger/tests/e2e/advancedUses.test.ts

@@ -0,0 +1,177 @@
+import { join } from 'node:path';
+import {
+  TestInvocationLogs,
+  TestStack,
+  invokeFunction,
+} from '@aws-lambda-powertools/testing-utils';
+import { afterAll, beforeAll, describe, expect, it, vi } from 'vitest';
+import { LoggerTestNodejsFunction } from '../helpers/resources.js';
+import {
+  RESOURCE_NAME_PREFIX,
+  SETUP_TIMEOUT,
+  STACK_OUTPUT_LOG_GROUP,
+  TEARDOWN_TIMEOUT,
+  TEST_CASE_TIMEOUT,
+} from './constants.js';
+
+/**
+ * In this e2e test for Logger, we test a number of advanced use cases:
+ * - Log buffering enabled with flush on error (both manually on logger.error and automatically on uncaught error)
+ * - Correlation ID injection (both manually and automatically)
+ * - Cold start detection for provisioned concurrency (always false)
+ *
+ * The test is split into three cases:
+ * - Manual instrumentation
+ * - Middy middleware
+ * - Decorator
+ */
+describe('Logger E2E - Advanced uses', () => {
+  const testStack = new TestStack({
+    stackNameProps: {
+      stackNamePrefix: RESOURCE_NAME_PREFIX,
+      testName: 'Advanced',
+    },
+  });
+
+  // Location of the lambda function code
+  const lambdaFunctionCodeFilePath = join(
+    __dirname,
+    'advancedUses.test.FunctionCode.ts'
+  );
+
+  const invocationCount = 2;
+  const invocationLogs = new Map<string, TestInvocationLogs[]>();
+  const manualCase = 'Manual';
+  const middyCase = 'Middy';
+  const decoratorCase = 'Decorator';
+
+  beforeAll(async () => {
+    invocationLogs.set(manualCase, []);
+    invocationLogs.set(middyCase, []);
+    invocationLogs.set(decoratorCase, []);
+    for (const caseKey of invocationLogs.keys()) {
+      new LoggerTestNodejsFunction(
+        testStack,
+        {
+          entry: lambdaFunctionCodeFilePath,
+          handler: `handler${caseKey}`,
+        },
+        {
+          logGroupOutputKey: STACK_OUTPUT_LOG_GROUP,
+          nameSuffix: caseKey,
+          createAlias: true,
+        }
+      );
+    }
+
+    await testStack.deploy();
+
+    for (const caseKey of invocationLogs.keys()) {
+      const functionArn = testStack.findAndGetStackOutputValue(caseKey);
+      const logs = await invokeFunction({
+        functionName: functionArn,
+        times: invocationCount,
+        invocationMode: 'SEQUENTIAL',
+        payload: [
+          {
+            id: 1,
+          },
+          {
+            id: 2,
+          },
+        ],
+      });
+      invocationLogs.set(caseKey, logs);
+    }
+  }, SETUP_TIMEOUT);
+
+  it.each([
+    {
+      caseKey: manualCase,
+    },
+    {
+      caseKey: middyCase,
+    },
+    {
+      caseKey: decoratorCase,
+    },
+  ])(
+    '$caseKey instrumentation',
+    ({ caseKey }) => {
+      for (let i = 0; i < invocationCount; i++) {
+        const isFirstInvocation = i === 0;
+        // Get log messages of the i-th invocation
+        const fnLogs = invocationLogs.get(caseKey)?.at(i)?.getFunctionLogs();
+        if (!fnLogs || fnLogs.length === 0) {
+          throw new Error(`Failed to get logs for ${caseKey} invocation ${i}`);
+        }
+        // When using decorator & middleware, we are actually throwing an error
+        // which is logged by the runtime, so we need to filter out the logs that are
+        // not JSON formatted
+        const logs = fnLogs.filter((log) => {
+          try {
+            JSON.parse(log);
+            return true;
+          } catch (error) {
+            return false;
+          }
+        });
+
+        if (isFirstInvocation) {
+          // Logs outside of the function handler are only present on the first invocation
+          expect(TestInvocationLogs.parseFunctionLog(logs[0])).toEqual(
+            expect.objectContaining({
+              level: 'DEBUG',
+              message: 'a never buffered debug log',
+            })
+          );
+        }
+        // Since we have an extra log (above) on the first invocation, we need to
+        // adjust the index of the logs we are checking
+        const logIndexOffset = isFirstInvocation ? 1 : 0;
+        const correlationId = i + 1;
+        expect(
+          TestInvocationLogs.parseFunctionLog(logs[0 + logIndexOffset])
+        ).toEqual(
+          expect.objectContaining({
+            level: 'INFO',
+            message: 'an info log',
+            cold_start: false,
+            correlation_id: correlationId,
+          })
+        );
+        expect(
+          TestInvocationLogs.parseFunctionLog(logs[1 + logIndexOffset])
+        ).toEqual(
+          expect.objectContaining({
+            level: 'DEBUG',
+            message: 'a buffered debug log',
+            cold_start: false,
+            correlation_id: correlationId,
+          })
+        );
+        expect(
+          TestInvocationLogs.parseFunctionLog(logs.at(-1) as string)
+        ).toEqual(
+          expect.objectContaining({
+            level: 'ERROR',
+            message: 'Uncaught error detected, flushing log buffer before exit',
+            cold_start: false,
+            correlation_id: correlationId,
+            error: expect.objectContaining({
+              name: 'Error',
+              message: 'ops',
+            }),
+          })
+        );
+      }
+    },
+    TEST_CASE_TIMEOUT
+  );
+
+  afterAll(async () => {
+    if (!process.env.DISABLE_TEARDOWN) {
+      await testStack.destroy();
+    }
+  }, TEARDOWN_TIMEOUT);
+});

packages/testing/src/TestInvocationLogs.ts

@@ -4,6 +4,7 @@ import type { FunctionLog } from './types.js';
 const CloudWatchLogKeywords = {
   END: 'END RequestId',
   INIT_START: 'INIT_START',
+  INIT_REPORT: 'INIT_REPORT',
   REPORT: 'REPORT RequestId',
   START: 'START RequestId',
   XRAY: 'XRAY TraceId',
@@ -99,13 +100,15 @@ class TestInvocationLogs {
   }
 
   /**
-   * Return the index of the log that contains `INIT_START`
-   * @param logs
-   * @returns {number} index of the log that contains `INIT_START`
+   * Return the index of the log that contains `INIT_START` or `INIT_REPORT`
+   *
+   * @param logs - Array of logs
    */
   public static getInitLogIndex(logs: string[]): number {
-    return logs.findIndex((log) =>
-      log.startsWith(CloudWatchLogKeywords.INIT_START)
+    return logs.findIndex(
+      (log) =>
+        log.startsWith(CloudWatchLogKeywords.INIT_START) ||
+        log.startsWith(CloudWatchLogKeywords.INIT_REPORT)
     );
   }
 

packages/testing/src/resources/TestNodejsFunction.ts

@@ -1,6 +1,6 @@
 import { randomUUID } from 'node:crypto';
-import { CfnOutput, type CfnResource, Duration } from 'aws-cdk-lib';
-import { Tracing } from 'aws-cdk-lib/aws-lambda';
+import { CfnOutput, Duration } from 'aws-cdk-lib';
+import { Alias, Tracing } from 'aws-cdk-lib/aws-lambda';
 import { NodejsFunction, OutputFormat } from 'aws-cdk-lib/aws-lambda-nodejs';
 import { LogGroup, RetentionDays } from 'aws-cdk-lib/aws-logs';
 import type { TestStack } from '../TestStack.js';
@@ -56,8 +56,18 @@ class TestNodejsFunction extends NodejsFunction {
       logGroup,
     });
 
+    let outputValue = this.functionName;
+    if (extraProps.createAlias) {
+      const dev = new Alias(this, 'dev', {
+        aliasName: 'dev',
+        version: this.currentVersion,
+        provisionedConcurrentExecutions: 1,
+      });
+      outputValue = dev.functionArn;
+    }
+
     new CfnOutput(this, extraProps.nameSuffix, {
-      value: this.functionName,
+      value: outputValue,
     });
   }
 }

packages/testing/src/types.ts

@@ -19,6 +19,12 @@ interface ExtraTestProps {
    * @default 'CJS'
    */
   outputFormat?: 'CJS' | 'ESM';
+  /**
+   * Whether to create an alias for the function.
+   *
+   * @default false
+   */
+  createAlias?: boolean;
 }
 
 type TestDynamodbTableProps = Omit<