fix(logger): POWERTOOLS_LOGGER_LOG_EVENT precedence is respected (#1015)

* fix: POWERTOOLS_LOGGER_LOG_EVENT precedence is respected

* fix: decorator logic

* chore: added unit test cases for decorator

* chore: added e2e test cases

* chore: address review comments

packages/logger/src/Logger.ts

@@ -292,9 +292,11 @@ class Logger extends Utility implements ClassThatLogs {
         }
 
         this.addContext(context);
-        if (options) {
-          this.logEventIfEnabled(event, options.logEvent);
+        let shouldLogEvent = undefined;
+        if ( options && options.hasOwnProperty('logEvent') ) {
+          shouldLogEvent = options.logEvent;
         }
+        this.logEventIfEnabled(event, shouldLogEvent);
 
         /* eslint-disable  @typescript-eslint/no-non-null-assertion */
         const result = originalMethod!.apply(target, [ event, context, callback ]);
@@ -636,6 +638,19 @@ class Logger extends Utility implements ClassThatLogs {
     this.envVarsService = new EnvironmentVariablesService();
   }
 
+  /**
+   * If the log event feature is enabled via env variable, it sets a property that tracks whether
+   * the event passed to the Lambda function handler should be logged or not.
+   *
+   * @private
+   * @returns {void}
+   */
+  private setLogEvent(): void {
+    if (this.getEnvVarsService().getLogEvent()) {
+      this.logEvent = true;
+    }
+  }
+
   /**
    * It sets the log formatter instance, in charge of giving a custom format
    * to the structured logs
@@ -716,7 +731,8 @@ class Logger extends Utility implements ClassThatLogs {
     this.setLogsSampled();
     this.setLogFormatter(logFormatter);
     this.setPowertoolLogData(serviceName, environment);
-
+    this.setLogEvent();
+
     this.addPersistentLogAttributes(persistentLogAttributes);
 
     return this;

packages/logger/src/middleware/middy.ts

@@ -38,9 +38,12 @@ const injectLambdaContext = (target: Logger | Logger[], options?: HandlerOptions
       if (options && options.clearState === true) {
         persistentAttributes.push({ ...logger.getPersistentLogAttributes() });
       }
-      if (options) {
-        logger.logEventIfEnabled(request.event, options.logEvent);
+
+      let shouldLogEvent = undefined;
+      if ( options && options.hasOwnProperty('logEvent') ) {
+        shouldLogEvent = options.logEvent;
       }
+      logger.logEventIfEnabled(request.event, shouldLogEvent);
     });
   };
 

packages/logger/tests/e2e/logEventEnvVarSetting.middy.test.FunctionCode.ts

@@ -0,0 +1,16 @@
+import { injectLambdaContext, Logger } from '../../src';
+import { Context } from 'aws-lambda';
+import middy from '@middy/core';
+
+type LambdaEvent = {
+  invocation: number
+};
+
+const logger = new Logger();
+
+const testFunction = async (event: LambdaEvent, context: Context): Promise<{requestId: string}> => ({
+  requestId: context.awsRequestId,
+});
+
+export const handler = middy(testFunction)
+  .use(injectLambdaContext(logger));

packages/logger/tests/e2e/logEventEnvVarSetting.middy.test.ts

@@ -0,0 +1,110 @@
+// Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved.
+// SPDX-License-Identifier: MIT-0
+
+/**
+ * Test logger basic features
+ *
+ * @group e2e/logger/logEventEnvVarSetting
+ */
+
+import path from 'path';
+import { App, Stack } from 'aws-cdk-lib';
+import { v4 } from 'uuid';
+import {
+  createStackWithLambdaFunction,
+  generateUniqueName,
+  invokeFunction,
+  isValidRuntimeKey
+} from '../../../commons/tests/utils/e2eUtils';
+import { InvocationLogs } from '../../../commons/tests/utils/InvocationLogs';
+import { deployStack, destroyStack } from '../../../commons/tests/utils/cdk-cli';
+import {
+  RESOURCE_NAME_PREFIX,
+  STACK_OUTPUT_LOG_GROUP,
+  SETUP_TIMEOUT,
+  TEST_CASE_TIMEOUT,
+  TEARDOWN_TIMEOUT
+} from './constants';
+
+const runtime: string = process.env.RUNTIME || 'nodejs16x';
+
+if (!isValidRuntimeKey(runtime)) {
+  throw new Error(`Invalid runtime key value: ${runtime}`);
+}
+
+const uuid = v4();
+const stackName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'LogEventEnvVarSetting-Middy');
+const functionName = generateUniqueName(RESOURCE_NAME_PREFIX, uuid, runtime, 'LogEventEnvVarSetting-Middy');
+const lambdaFunctionCodeFile = 'logEventEnvVarSetting.middy.test.FunctionCode.ts';
+
+const integTestApp = new App();
+let logGroupName: string; // We do not know it until deployment
+let stack: Stack;
+
+describe(`logger E2E tests log event via env var setting (middy) for runtime: ${runtime}`, () => {
+
+  let invocationLogs: InvocationLogs[];
+
+  beforeAll(async () => {
+    // Create and deploy a stack with AWS CDK
+    stack = createStackWithLambdaFunction({
+      app: integTestApp,
+      stackName: stackName,
+      functionName: functionName,
+      functionEntry: path.join(__dirname, lambdaFunctionCodeFile),
+      environment: {
+        LOG_LEVEL: 'INFO',
+        POWERTOOLS_SERVICE_NAME: 'logger-e2e-testing',
+        UUID: uuid,
+
+        // Enabling the logger to log events via env var
+        POWERTOOLS_LOGGER_LOG_EVENT: 'true',
+      },
+      logGroupOutputKey: STACK_OUTPUT_LOG_GROUP,
+      runtime: runtime,
+    });
+
+    const result = await deployStack(integTestApp, stack);
+    logGroupName = result.outputs[STACK_OUTPUT_LOG_GROUP];
+
+    // Invoke the function twice (one for cold start, another for warm start)
+    invocationLogs = await invokeFunction(functionName, 2, 'SEQUENTIAL');
+
+    console.log('logGroupName', logGroupName);
+
+  }, SETUP_TIMEOUT);
+
+  describe('Log event', () => {
+
+    it('should log the event at both invocations', async () => {
+      const firstInvocationMessages = invocationLogs[0].getAllFunctionLogs();
+      let eventLoggedInFirstInvocation = false;
+      for (const message of firstInvocationMessages) {
+        if (message.includes(`event`)) {
+          eventLoggedInFirstInvocation = true;
+          expect(message).toContain(`"event":{"invocation":0}`);
+        }
+      }
+
+      const secondInvocationMessages = invocationLogs[1].getAllFunctionLogs();
+      let eventLoggedInSecondInvocation = false;
+      for (const message of secondInvocationMessages) {
+        if (message.includes(`event`)) {
+          eventLoggedInSecondInvocation = true;
+          expect(message).toContain(`"event":{"invocation":1}`);
+        }
+      }
+
+      expect(eventLoggedInFirstInvocation).toBe(true);
+      expect(eventLoggedInSecondInvocation).toBe(true);
+
+    }, TEST_CASE_TIMEOUT);
+
+  });
+
+  afterAll(async () => {
+    if (!process.env.DISABLE_TEARDOWN) {
+      await destroyStack(integTestApp, stack);
+    }
+  }, TEARDOWN_TIMEOUT);
+});

packages/logger/tests/unit/Logger.test.ts

@@ -982,6 +982,93 @@ describe('Class: Logger', () => {
 
     });
 
+    test('when used as decorator with the log event flag enabled, it logs the event', async () => {
+
+      // Prepare
+      const logger = new Logger({
+        logLevel: 'DEBUG',
+      });
+      const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation();
+
+      type CustomEvent = { user_id: string };
+
+      class LambdaFunction implements LambdaInterface {
+
+        @logger.injectLambdaContext({ logEvent: true })
+        // eslint-disable-next-line @typescript-eslint/ban-ts-comment
+        // @ts-ignore
+        public handler<TResult>(_event: CustomEvent, _context: Context, _callback: Callback<TResult>): void | Promise<TResult> {
+          return;
+        }
+      }
+
+      // Act
+      await new LambdaFunction().handler({ user_id: '123456' }, dummyContext, () => console.log('Lambda invoked!'));
+
+      // Assess
+      expect(consoleSpy).toBeCalledTimes(1);
+      expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
+        cold_start: true,
+        function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function',
+        function_memory_size: 128,
+        function_name: 'foo-bar-function',
+        function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678',
+        level: 'INFO',
+        message: 'Lambda invocation event',
+        service: 'hello-world',
+        timestamp: '2016-06-20T12:08:10.000Z',
+        xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793',
+        event: {
+          user_id: '123456'
+        }
+      }));
+
+    });
+
+    test('when used as decorator without options, but POWERTOOLS_LOGGER_LOG_EVENT env var is set to true, it logs the event', async () => {
+
+      // Prepare
+      process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'true';
+      const logger = new Logger({
+        logLevel: 'DEBUG',
+      });
+      const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation();
+
+      type CustomEvent = { user_id: string };
+
+      class LambdaFunction implements LambdaInterface {
+
+        @logger.injectLambdaContext()
+        // eslint-disable-next-line @typescript-eslint/ban-ts-comment
+        // @ts-ignore
+        public handler<TResult>(_event: CustomEvent, _context: Context, _callback: Callback<TResult>): void | Promise<TResult> {
+          return;
+        }
+      }
+
+      // Act
+      await new LambdaFunction().handler({ user_id: '123456' }, dummyContext, () => console.log('Lambda invoked!'));
+
+      // Assess
+      expect(consoleSpy).toBeCalledTimes(1);
+      expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
+        cold_start: true,
+        function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function',
+        function_memory_size: 128,
+        function_name: 'foo-bar-function',
+        function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678',
+        level: 'INFO',
+        message: 'Lambda invocation event',
+        service: 'hello-world',
+        timestamp: '2016-06-20T12:08:10.000Z',
+        xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793',
+        event: {
+          user_id: '123456'
+        }
+      }));
+
+    });
+
   });
 
   describe('Method: refreshSampleRateCalculation', () => {