Feat(logger): log event functionality (#1004)

* feat(logger): log event, add business logic and unit tests

* test(logger): add log event support

* feat(logger): add env variable for log event

* test(logger): middy

* chore(logger): middy polish for log event

* test(logger): fix log event unit tests

* test(logger): unit + e2e tests for log event functionality

* docs(logger): add log event

* docs: add single line command for docs generation

* docs: fix typo in env vars section

Author: saragerion

CONTRIBUTING.md

@@ -238,7 +238,11 @@ You can build and start the API reference website by running these two commands
 
 #### Docs website
 
-You can build and start a local docs website by running these two commands:
+You can build and start a local docs website by running:  
+
+`npm run docs-website-build-run`
+
+Alternatively you can run these two commands:
 
 * `npm run docs-buildDockerImage` OR `docker build -t squidfunk/mkdocs-material ./docs/`
 * `npm run docs-runLocalDocker` OR `docker run --rm -it -p 8000:8000 -v ${PWD}:/docs squidfunk/mkdocs-material`

docs/core/logger.md

@@ -14,9 +14,9 @@ Logger provides an opinionated logger with output structured as JSON.
 
 ## Key features
 
-* Capture key fields from Lambda context, cold start and structures logging output as JSON
-* Log Lambda context when instructed (disabled by default)
-* Log sampling prints all logs for a percentage of invocations (disabled by default)
+* Capture key fields from Lambda context, cold start and structure logging output as JSON
+* Log Lambda event when instructed (disabled by default)
+* Log sampling prints all the logs for a percentage of invocations (disabled by default)
 * Append additional keys to structured log at any point in time
 
 ## Getting started
@@ -193,6 +193,50 @@ In each case, the printed log will look like this:
     }
     ```
 
+#### Log incoming event
+
+When debugging in non-production environments, you can instruct Logger to log the incoming event with the middleware/decorator parameter `logEvent` or via POWERTOOLS_LOGGER_LOG_EVENT env var set to `true`.
+
+???+ warning
+This is disabled by default to prevent sensitive info being logged
+
+=== "Middy Middleware"
+
+    ```typescript hl_lines="11"
+    import { Logger, injectLambdaContext } from '@aws-lambda-powertools/logger';
+    import middy from '@middy/core';
+
+    const logger = new Logger();
+
+    const lambdaHandler = async (_event: any, _context: any): Promise<void> => {
+        logger.info('This is an INFO log with some context');
+    };
+
+    export const handler = middy(lambdaHandler)
+        .use(injectLambdaContext(logger, { logEvent: true }));
+    ```
+
+=== "Decorator"
+
+    ```typescript hl_lines="8"
+    import { Logger } from '@aws-lambda-powertools/logger';
+    import { LambdaInterface } from '@aws-lambda-powertools/commons';
+
+    const logger = new Logger();
+    
+    class Lambda implements LambdaInterface {
+        // Set the log event flag to true
+        @logger.injectLambdaContext({ logEvent: true })
+        public async handler(_event: any, _context: any): Promise<void> {
+            logger.info('This is an INFO log with some context');
+        }
+
+    }
+
+    export const myFunction = new Lambda();
+    export const handler = myFunction.handler;
+    ```
+
 ### Appending persistent additional log keys and values
 
 You can append additional persistent keys and values in the logs generated during a Lambda invocation using either mechanism:

docs/index.md

@@ -45,20 +45,20 @@ Each TypeScript utility is installed as standalone NPM package.
 ## Environment variables
 
 !!! info
-    **Explicit parameters take precedence over environment variables.**
-
-| Environment variable                      | Description | Utility                   | Default               |
-|-------------------------------------------| --------------------------------------------------------------------------------- |---------------------------|-----------------------|
-| **POWERTOOLS_SERVICE_NAME**               | Sets service name used for tracing namespace, metrics dimension and structured logging | All                       | `"service_undefined"` |
-| **POWERTOOLS_METRICS_NAMESPACE**          | Sets namespace used for metrics | [Metrics](./core/metrics) | `None`                |
-| **POWERTOOLS_TRACE_ENABLED**              | Explicitly disables tracing | [Tracer](./core/tracer)   | `true`                |
-| **POWERTOOLS_TRACER_CAPTURE_RESPONSE**    | Captures Lambda or method return as metadata. | [Tracer](./core/tracer)   | `true`                |
-| **POWERTOOLS_TRACER_CAPTURE_ERROR**       | Captures Lambda or method exception as metadata. | [Tracer](./core/tracer)   | `true`                |
-| **POWERTOOLS_TRACER_CAPTURE_HTTPS_REQUESTS** | Captures HTTP(s) requests as segments. | [Tracer](./core/tracer)   | `true`                |
-| **POWERTOOLS_LOGGER_LOG_EVENT**           | Logs incoming event | [Logger](./core/logger)   | `false`               |
-| **POWERTOOLS_LOGGER_SAMPLE_RATE**         | Debug log sampling | [Logger](./core/logger)  | `0`                   |
-| **POWERTOOLS_LOG_DEDUPLICATION_DISABLED** | Disables log deduplication filter protection to use Pytest Live Log feature | [Logger](./core/logger)  | `false`               |
-| **LOG_LEVEL**                             | Sets logging level | [Logger](./core/logger)  | `INFO`                |
+    **Explicit parameters passed in constructors or in middleware/decorators take precedence over environment variables.**
+
+| Environment variable                         | Description                                                                            | Utility                   | Default               |
+|----------------------------------------------|----------------------------------------------------------------------------------------|---------------------------|-----------------------|
+| **POWERTOOLS_SERVICE_NAME**                  | Sets service name used for tracing namespace, metrics dimension and structured logging | All                       | `"service_undefined"` |
+| **POWERTOOLS_METRICS_NAMESPACE**             | Sets namespace used for metrics                                                        | [Metrics](./core/metrics) | `None`                |
+| **POWERTOOLS_TRACE_ENABLED**                 | Explicitly disables tracing                                                            | [Tracer](./core/tracer)   | `true`                |
+| **POWERTOOLS_TRACER_CAPTURE_RESPONSE**       | Captures Lambda or method return as metadata.                                          | [Tracer](./core/tracer)   | `true`                |
+| **POWERTOOLS_TRACER_CAPTURE_ERROR**          | Captures Lambda or method exception as metadata.                                       | [Tracer](./core/tracer)   | `true`                |
+| **POWERTOOLS_TRACER_CAPTURE_HTTPS_REQUESTS** | Captures HTTP(s) requests as segments.                                                 | [Tracer](./core/tracer)   | `true`                |
+| **POWERTOOLS_LOGGER_LOG_EVENT**              | Logs incoming event                                                                    | [Logger](./core/logger)   | `false`               |
+| **POWERTOOLS_LOGGER_SAMPLE_RATE**            | Debug log sampling                                                                     | [Logger](./core/logger)   | `0`                   |
+| **POWERTOOLS_LOGGER_LOG_EVENT**              | Logs incoming events                                                                   | [Logger](./core/logger)   | `false`               |
+| **LOG_LEVEL**                                | Sets logging level                                                                     | [Logger](./core/logger)   | `INFO`                |
 
 ## Examples
 

package.json

@@ -30,8 +30,10 @@
     "lerna-preversion": "lerna exec -- npm run lint",
     "lerna-version": "lerna exec -- npm run format && git add -A src",
     "postversion": "git push && git push --tags",
+    "docs-website-build-run": "npm run docs-buildDockerImage && npm run docs-runLocalDocker",
     "docs-buildDockerImage": "docker build -t powertool-typescript/docs ./docs/",
     "docs-runLocalDocker": "docker run --rm -it -p 8000:8000 -v ${PWD}:/docs powertool-typescript/docs",
+    "docs-api-build-run": "npm run docs-generateApiDoc && npx live-server api",
     "docs-generateApiDoc": "typedoc .",
     "docs-runLocalApiDoc": "npx live-server api"
   },

packages/commons/tests/utils/InvocationLogs.ts

@@ -56,6 +56,14 @@ export class InvocationLogs {
     return filteredLogs.length > 0;
   }
 
+  /**
+   * Return all the log of the function
+   * @returns Array of function logs
+   */
+  public getAllFunctionLogs(): string[] {
+    return this.logs;
+  }
+
   /**
    * Return only logs from function, exclude START, END, and REPORT generated by Lambda service
    * @param levelToFilter level to filter

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