Feat(logger): log event functionality

packages/logger/src/Logger.ts

@@ -119,6 +119,8 @@ class Logger extends Utility implements ClassThatLogs {
 
   private envVarsService?: EnvironmentVariablesService;
 
+  private logEvent: boolean = false;
+
   private logFormatter?: LogFormatterInterface;
 
   private logLevel?: LogLevel;
@@ -222,6 +224,16 @@ class Logger extends Utility implements ClassThatLogs {
     this.processLogItem('ERROR', input, extraInput);
   }
 
+  /**
+   * It returns a boolean value. True means that the Lambda invocation events
+   * are printed in the logs.
+   *
+   * @returns {boolean}
+   */
+  public getLogEvent(): boolean {
+    return this.logEvent;
+  }
+
   /**
    * It returns a boolean value, if true all the logs will be printed.
    *
@@ -280,6 +292,9 @@ class Logger extends Utility implements ClassThatLogs {
         }
 
         this.addContext(context);
+        if (options) {
+          this.logEventIfEnabled(event, options.logEvent);
+        }
 
         /* eslint-disable  @typescript-eslint/no-non-null-assertion */
         const result = originalMethod!.apply(target, [ event, context, callback ]);
@@ -293,6 +308,20 @@ class Logger extends Utility implements ClassThatLogs {
     };
   }
 
+  /**
+   * Logs a Lambda invocation event, if it *should*.
+   *
+   ** @param {unknown} event
+   * @param {boolean} [overwriteValue]
+   * @returns {void}
+   */
+  public logEventIfEnabled(event: unknown, overwriteValue?: boolean): void {
+    if (!this.shouldLogEvent(overwriteValue)) {
+      return;
+    }
+    this.info('Lambda invocation event', { event });
+  }
+
   /**
    * If the sample rate feature is enabled, the calculation that determines whether the logs
    * will actually be printed or not for this invocation is done when the Logger class is
@@ -353,6 +382,21 @@ class Logger extends Utility implements ClassThatLogs {
       this.getEnvVarsService().getSampleRateValue();
   }
 
+  /**
+   * It checks whether the current Lambda invocation event should be printed in the logs or not.
+   *
+   * @private
+   * @param {boolean} [overwriteValue]
+   * @returns {boolean}
+   */
+  public shouldLogEvent(overwriteValue?: boolean): boolean {
+    if (typeof overwriteValue === 'boolean') {
+      return overwriteValue;
+    }
+
+    return this.getLogEvent();
+  }
+
   /**
    * It prints a log item with level WARN.
    *
@@ -486,10 +530,10 @@ class Logger extends Utility implements ClassThatLogs {
 
   /**
    * It returns the current X-Ray Trace ID parsing the content of the `_X_AMZN_TRACE_ID` env variable.
-   * 
+   *
    * The X-Ray Trace data available in the environment variable has this format:
    * `Root=1-5759e988-bd862e3fe1be46a994272793;Parent=557abcec3ee5a047;Sampled=1`,
-   * 
+   *
    * The actual Trace ID is: `1-5759e988-bd862e3fe1be46a994272793`.
    *
    * @private

packages/logger/src/config/ConfigService.ts

@@ -19,6 +19,7 @@ abstract class ConfigService implements ConfigServiceInterface {
    * @protected
    */
   protected currentEnvironmentVariable = 'ENVIRONMENT';
+  protected logEventVariable = 'POWERTOOLS_LOGGER_LOG_EVENT';
   protected logLevelVariable = 'LOG_LEVEL';
   protected sampleRateValueVariable = 'POWERTOOLS_LOGGER_SAMPLE_RATE';
   protected serviceNameVariable = 'POWERTOOLS_SERVICE_NAME';
@@ -38,6 +39,13 @@ abstract class ConfigService implements ConfigServiceInterface {
    */
   public abstract getCurrentEnvironment(): string;
 
+  /**
+   * It returns the value of the POWERTOOLS_LOGGER_LOG_EVENT environment variable.
+   *
+   * @returns {boolean}
+   */
+  public abstract getLogEvent(): boolean;
+
   /**
    * It returns the value of the LOG_LEVEL environment variable.
    *
@@ -59,6 +67,17 @@ abstract class ConfigService implements ConfigServiceInterface {
    */
   public abstract getServiceName(): string;
 
+  /**
+   * It returns true if the string value represents a boolean true value.
+   *
+   * @param {string} value
+   * @returns boolean
+   * @protected
+   */
+  protected isValueTrue(value: string): boolean {
+    return value.toLowerCase() === 'true' || value === '1';
+  }
+
 }
 
 export {

packages/logger/src/config/ConfigServiceInterface.ts

@@ -22,6 +22,13 @@ interface ConfigServiceInterface {
    */
   getCurrentEnvironment(): string
 
+  /**
+   * It returns the value of the POWERTOOLS_LOGGER_LOG_EVENT environment variable.
+   *
+   * @returns {boolean}
+   */
+  getLogEvent(): boolean
+
   /**
    * It returns the value of the LOG_LEVEL environment variable.
    *

packages/logger/src/config/EnvironmentVariablesService.ts

@@ -79,6 +79,15 @@ class EnvironmentVariablesService extends ConfigService {
     return this.get(this.functionVersionVariable);
   }
 
+  /**
+   * It returns the value of the POWERTOOLS_LOGGER_LOG_EVENT environment variable.
+   *
+   * @returns {boolean}
+   */
+  public getLogEvent(): boolean {
+    return this.isValueTrue(this.get(this.logEventVariable));
+  }
+
   /**
    * It returns the value of the LOG_LEVEL environment variable.
    *

packages/logger/src/middleware/middy.ts

@@ -38,6 +38,9 @@ const injectLambdaContext = (target: Logger | Logger[], options?: HandlerOptions
       if (options && options.clearState === true) {
         persistentAttributes.push({ ...logger.getPersistentLogAttributes() });
       }
+      if (options) {
+        logger.logEventIfEnabled(request.event, options.logEvent);
+      }
     });
   };
 
@@ -48,7 +51,7 @@ const injectLambdaContext = (target: Logger | Logger[], options?: HandlerOptions
       });
     }
   };
-  
+
   return {
     before: injectLambdaContextBefore,
     after: injectLambdaContextAfter

packages/logger/src/types/Logger.ts

@@ -9,6 +9,7 @@ type ClassThatLogs = {
 };
 
 type HandlerOptions = {
+  logEvent?: boolean
   clearState?: boolean
 };
 

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

@@ -3,6 +3,7 @@ import { Context, APIGatewayAuthorizerResult } from 'aws-lambda';
 import middy from '@middy/core';
 
 const PERSISTENT_KEY = process.env.PERSISTENT_KEY;
+const PERSISTENT_KEY_FIRST_INVOCATION_ONLY = process.env.PERSISTENT_KEY_FIRST_INVOCATION_ONLY;
 const PERSISTENT_VALUE = process.env.PERSISTENT_VALUE;
 const REMOVABLE_KEY = process.env.REMOVABLE_KEY;
 const REMOVABLE_VALUE = process.env.REMOVABLE_VALUE;
@@ -33,7 +34,7 @@ const testFunction = async (event: LambdaEvent, context: Context): Promise<{requ
   const specialValue = event.invocation;
   if (specialValue === 0) {
     logger.appendKeys({
-      specialKey: specialValue
+      [PERSISTENT_KEY_FIRST_INVOCATION_ONLY]: specialValue
     });
   }
 
@@ -72,4 +73,5 @@ const testFunction = async (event: LambdaEvent, context: Context): Promise<{requ
   };
 };
 
-export const handler = middy(testFunction).use(injectLambdaContext(logger, { clearState: true }));
+export const handler = middy(testFunction)
+  .use(injectLambdaContext(logger, { clearState: true, logEvent: true }));

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

@@ -42,6 +42,7 @@ const lambdaFunctionCodeFile = 'basicFeatures.middy.test.FunctionCode.ts';
 
 // Text to be used by Logger in the Lambda function
 const PERSISTENT_KEY = 'persistentKey';
+const PERSISTENT_KEY_FIRST_INVOCATION_ONLY = 'specialKey';
 const PERSISTENT_VALUE = `a persistent value that will be put in every log ${uuid}`;
 const REMOVABLE_KEY = 'removableKey';
 const REMOVABLE_VALUE = `a persistent value that will be removed and not displayed in any log ${uuid}`;
@@ -73,6 +74,7 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime}
 
         // Text to be used by Logger in the Lambda function
         PERSISTENT_KEY,
+        PERSISTENT_KEY_FIRST_INVOCATION_ONLY,
         PERSISTENT_VALUE,
         REMOVABLE_KEY,
         REMOVABLE_VALUE,
@@ -127,9 +129,7 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime}
         expect(message).not.toContain(`"cold_start":true`);
       }
     }, TEST_CASE_TIMEOUT);
-  });
 
-  describe('Context data', () => {
     it('should log context information in every log', async () => {
       const logMessages = invocationLogs[0].getFunctionLogs();
 
@@ -143,6 +143,34 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime}
     }, TEST_CASE_TIMEOUT);
   });
 
+  describe('Log event', () => {
+
+    it('should log the event on the first invocation', 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);
+
+  });
+
   describe('Persistent additional log keys and values', () => {
     it('should contain persistent value in every log', async () => {
       const logMessages = invocationLogs[0].getFunctionLogs();
@@ -163,12 +191,12 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime}
     it('with clear state enabled, should not persist keys across invocations', async () => {
       const firstInvocationMessages = invocationLogs[0].getFunctionLogs();
       for (const message of firstInvocationMessages) {
-        expect(message).toContain(`"specialKey":0`);
+        expect(message).toContain(`"${PERSISTENT_KEY_FIRST_INVOCATION_ONLY}":0`);
       }
 
       const secondInvocationMessages = invocationLogs[1].getFunctionLogs();
       for (const message of secondInvocationMessages) {
-        expect(message).not.toContain(`"specialKey":0`);
+        expect(message).not.toContain(`"${PERSISTENT_KEY_FIRST_INVOCATION_ONLY}":0`);
       }
     }, TEST_CASE_TIMEOUT);
   });

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

@@ -572,6 +572,7 @@ describe('Class: Logger', () => {
         coldStart: false, // This is now false because the `coldStart` attribute has been already accessed once by the `addContext` method
         customConfigService: undefined,
         envVarsService: expect.any(EnvironmentVariablesService),
+        logEvent: false,
         logFormatter: expect.any(PowertoolLogFormatter),
         logLevel: 'DEBUG',
         logLevelThresholds: {
@@ -808,6 +809,7 @@ describe('Class: Logger', () => {
     test('when used as decorator, it returns a function with the correct scope of the decorated class', async () => {
 
       // Prepare
+
       const logger = new Logger();
       const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation();
       class LambdaFunction implements LambdaInterface {
@@ -1042,6 +1044,7 @@ describe('Class: Logger', () => {
         coldStart: true,
         customConfigService: undefined,
         envVarsService: expect.any(EnvironmentVariablesService),
+        logEvent: false,
         logFormatter: expect.any(PowertoolLogFormatter),
         logLevel: 'DEBUG',
         logLevelThresholds: {
@@ -1065,6 +1068,7 @@ describe('Class: Logger', () => {
         coldStart: true,
         customConfigService: undefined,
         envVarsService: expect.any(EnvironmentVariablesService),
+        logEvent: false,
         logFormatter: expect.any(PowertoolLogFormatter),
         logLevel: 'DEBUG',
         logLevelThresholds: {
@@ -1090,6 +1094,7 @@ describe('Class: Logger', () => {
         coldStart: true,
         customConfigService: undefined,
         envVarsService: expect.any(EnvironmentVariablesService),
+        logEvent: false,
         logFormatter: expect.any(PowertoolLogFormatter),
         logLevel: 'DEBUG',
         logLevelThresholds: {
@@ -1113,6 +1118,7 @@ describe('Class: Logger', () => {
         coldStart: true,
         customConfigService: undefined,
         envVarsService: expect.any(EnvironmentVariablesService),
+        logEvent: false,
         logFormatter: expect.any(PowertoolLogFormatter),
         logLevel: 'ERROR',
         logLevelThresholds: {
@@ -1135,4 +1141,48 @@ describe('Class: Logger', () => {
 
   });
 
+  describe('Method: logEventIfEnabled', () => {
+
+    test('When the feature is disabled, it DOES NOT log the event', () => {
+
+      // Prepare
+      const logger = new Logger();
+      const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation();
+
+      // Act
+      logger.logEventIfEnabled(dummyEvent);
+
+      // Assess
+
+      expect(consoleSpy).toBeCalledTimes(0);
+    });
+
+    test('When the feature is enabled via overwrite flag, it DOES log the event', () => {
+
+      // Prepare
+      const event = {
+        something: 'happened!'
+      };
+      const logger = new Logger();
+      const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation();
+
+      // Act
+      logger.logEventIfEnabled(event, true);
+
+      // Assess
+      expect(consoleSpy).toBeCalledTimes(1);
+      expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
+        level: 'INFO',
+        message: 'Lambda invocation event',
+        service: 'hello-world',
+        timestamp: '2016-06-20T12:08:10.000Z',
+        xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793',
+        event: {
+          something: 'happened!'
+        }
+      },
+      ));
+    });
+  });
+
 });