feat(logger): pretty printing logs in local and non-prod environment (#1141)

* test(logger): add tests for POWERTOOLS_DEV env var and for pretty printing logs when var is set to truthy value

* feat(logger): add POWERTOOLS_DEV env var and method to get its value

* test(logger): fix tests adding method that gets value of POWERTOOLS_DEV env var

* feat(logger): add pretty printing to logs if POWERTOOLS_DEV env var set to truthy value

* refactor(review): add private class property for indent size, move evaluation of this property to setOptions()

* test(logger): fix tests according to the changes in default logger config

* docs(logger): update sections for pretty printing logs using POWERTOOLS_DEV env var

* Update docs/core/logger.md

* Update docs/core/logger.md

Co-authored-by: ijemmy <[email protected]>

* fix(docs): update default value for POWERTOOLS_DEV env var

* feat(logger): add isValueTrue method that checks the string value for truthiness

* test(logger): adjust tests for config interface

* test(logger): add tests for isValueTrue method, remove redundunt tests

Co-authored-by: Andrea Amorosi <[email protected]>
Co-authored-by: ijemmy <[email protected]>

Author: 3 people

docs/core/logger.md

@@ -104,6 +104,9 @@ Your Logger will include the following keys to your structured logging (default
 | **xray_trace_id**: `string` | `1-5759e988-bd862e3fe1be46a994272793`                                                                            | X-Ray Trace ID. This value is always presented in Lambda environment, whether [tracing is enabled](https://docs.aws.amazon.com/lambda/latest/dg/services-xray.html){target="_blank"} or not. Logger will always log this value. |
 | **error**: `Object`         | `{ name: "Error", location: "/my-project/handler.ts:18", message: "Unexpected error #1", stack: "[stacktrace]"}` | Optional - An object containing information about the Error passed to the logger                                                                                                                                                |
 
+???+ info
+    When `POWERTOOLS_DEV` environment variable is present and set to `"true"` or `"1"`, Logger will pretty-print log messages for easier readability. We recommend to use this setting only when debugging on local environments.
+
 ### Capturing Lambda context info
 
 You can enrich your structured logs with key Lambda context information in multiple ways.

docs/index.md

@@ -293,6 +293,7 @@ Core utilities such as Tracing, Logging, and Metrics will be available across al
 | **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_DEV**            | Increase JSON indentation to ease debugging when running functions locally or in a non-production environment                                                                     | [Logger](./core/logger)   | `false`                   |
 | **LOG_LEVEL**                                | Sets logging level                                                                     | [Logger](./core/logger)   | `INFO`                |
 
 ## Tenets

packages/logger/src/Logger.ts

@@ -6,6 +6,7 @@ import { LogItem } from './log';
 import cloneDeep from 'lodash.clonedeep';
 import merge from 'lodash.merge';
 import { ConfigServiceInterface, EnvironmentVariablesService } from './config';
+import { LogJsonIndent } from './types';
 import type {
   ClassThatLogs,
   Environment,
@@ -127,6 +128,8 @@ class Logger extends Utility implements ClassThatLogs {
 
   private logFormatter?: LogFormatterInterface;
 
+  private logIndentation: number = LogJsonIndent.COMPACT;
+
   private logLevel?: LogLevel;
 
   private readonly logLevelThresholds: LogLevelThresholds = {
@@ -595,7 +598,7 @@ class Logger extends Utility implements ClassThatLogs {
 
     const consoleMethod = logLevel.toLowerCase() as keyof ClassThatLogs;
 
-    this.console[consoleMethod](JSON.stringify(log.getAttributes(), this.removeCircularDependencies()));
+    this.console[consoleMethod](JSON.stringify(log.getAttributes(), this.removeCircularDependencies(), this.logIndentation));
   }
 
   /**
@@ -688,6 +691,19 @@ class Logger extends Utility implements ClassThatLogs {
     this.logFormatter = logFormatter || new PowertoolLogFormatter();
   }
 
+  /**
+   * If the `POWERTOOLS_DEV' env variable is set,
+   * it adds JSON indentation for pretty printing logs.
+   *
+   * @private
+   * @returns {void}
+   */
+  private setLogIndentation(): void {
+    if (this.getEnvVarsService().getDevMode()) {
+      this.logIndentation = LogJsonIndent.PRETTY;
+    }
+  }
+
   /**
    * It sets the Logger's instance log level.
    *
@@ -757,6 +773,7 @@ class Logger extends Utility implements ClassThatLogs {
     this.setLogFormatter(logFormatter);
     this.setPowertoolLogData(serviceName, environment);
     this.setLogEvent();
+    this.setLogIndentation();
 
     this.addPersistentLogAttributes(persistentLogAttributes);
 

packages/logger/src/config/ConfigServiceInterface.ts

@@ -22,6 +22,13 @@ interface ConfigServiceInterface {
    */
   getCurrentEnvironment(): string
 
+  /**
+   * It returns the value of the POWERTOOLS_DEV environment variable.
+   *
+   * @returns {boolean}
+   */
+  getDevMode(): boolean
+
   /**
    * It returns the value of the POWERTOOLS_LOGGER_LOG_EVENT environment variable.
    *
@@ -50,6 +57,14 @@ interface ConfigServiceInterface {
    */
   getServiceName(): string
 
+  /**
+   * It returns true if the string value represents a boolean true value.
+   *
+   * @param {string} value
+   * @returns boolean
+   */
+  isValueTrue(value: string): boolean
+
 }
 
 export {

packages/logger/src/config/EnvironmentVariablesService.ts

@@ -20,6 +20,7 @@ class EnvironmentVariablesService extends CommonEnvironmentVariablesService impl
   // Reserved environment variables
   private awsRegionVariable = 'AWS_REGION';
   private currentEnvironmentVariable = 'ENVIRONMENT';
+  private devModeVariable = 'POWERTOOLS_DEV';
   private functionNameVariable = 'AWS_LAMBDA_FUNCTION_NAME';
   private functionVersionVariable = 'AWS_LAMBDA_FUNCTION_VERSION';
   private logEventVariable = 'POWERTOOLS_LOGGER_LOG_EVENT';
@@ -45,6 +46,17 @@ class EnvironmentVariablesService extends CommonEnvironmentVariablesService impl
     return this.get(this.currentEnvironmentVariable);
   }
 
+  /**
+   * It returns the value of the POWERTOOLS_DEV environment variable.
+   *
+   * @returns {boolean}
+   */
+  public getDevMode(): boolean {
+    const value = this.get(this.devModeVariable);
+
+    return this.isValueTrue(value);
+  }
+
   /**
    * It returns the value of the AWS_LAMBDA_FUNCTION_MEMORY_SIZE environment variable.
    *
@@ -81,8 +93,8 @@ class EnvironmentVariablesService extends CommonEnvironmentVariablesService impl
    */
   public getLogEvent(): boolean {
     const value = this.get(this.logEventVariable);
-
-    return value.toLowerCase() === 'true' || value === '1';
+    
+    return this.isValueTrue(value);
   }
 
   /**
@@ -105,6 +117,18 @@ class EnvironmentVariablesService extends CommonEnvironmentVariablesService impl
     return (value && value.length > 0) ? Number(value) : undefined;
   }
 
+  /**
+   * It returns true if the string value represents a boolean true value.
+   *
+   * @param {string} value
+   * @returns boolean
+   */
+  public isValueTrue(value: string): boolean {
+    const truthyValues: string[] = [ '1', 'y', 'yes', 't', 'true', 'on' ];
+
+    return truthyValues.includes(value.toLowerCase());
+  }
+
 }
 
 export {

packages/logger/src/types/Logger.ts

@@ -74,3 +74,8 @@ export {
   ConstructorOptions,
   HandlerOptions
 };
+
+export const enum LogJsonIndent {
+  PRETTY = 4,
+  COMPACT = 0,
+}

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

@@ -11,7 +11,7 @@ import * as dummyEvent from '../../../../tests/resources/events/custom/hello-wor
 import { createLogger, Logger } from '../../src';
 import { EnvironmentVariablesService } from '../../src/config';
 import { PowertoolLogFormatter } from '../../src/formatter';
-import { ClassThatLogs } from '../../src/types';
+import { ClassThatLogs, LogJsonIndent } from '../../src/types';
 import { Context, Handler } from 'aws-lambda';
 import { Console } from 'console';
 
@@ -573,6 +573,7 @@ describe('Class: Logger', () => {
         customConfigService: undefined,
         envVarsService: expect.any(EnvironmentVariablesService),
         logEvent: false,
+        logIndentation: 0,
         logFormatter: expect.any(PowertoolLogFormatter),
         logLevel: 'DEBUG',
         logLevelThresholds: {
@@ -1271,6 +1272,7 @@ describe('Class: Logger', () => {
         customConfigService: undefined,
         envVarsService: expect.any(EnvironmentVariablesService),
         logEvent: false,
+        logIndentation: 0,
         logFormatter: expect.any(PowertoolLogFormatter),
         logLevel: 'DEBUG',
         logLevelThresholds: {
@@ -1295,6 +1297,7 @@ describe('Class: Logger', () => {
         customConfigService: undefined,
         envVarsService: expect.any(EnvironmentVariablesService),
         logEvent: false,
+        logIndentation: 0,
         logFormatter: expect.any(PowertoolLogFormatter),
         logLevel: 'DEBUG',
         logLevelThresholds: {
@@ -1321,6 +1324,7 @@ describe('Class: Logger', () => {
         customConfigService: undefined,
         envVarsService: expect.any(EnvironmentVariablesService),
         logEvent: false,
+        logIndentation: 0,
         logFormatter: expect.any(PowertoolLogFormatter),
         logLevel: 'DEBUG',
         logLevelThresholds: {
@@ -1345,6 +1349,7 @@ describe('Class: Logger', () => {
         customConfigService: undefined,
         envVarsService: expect.any(EnvironmentVariablesService),
         logEvent: false,
+        logIndentation: 0,
         logFormatter: expect.any(PowertoolLogFormatter),
         logLevel: 'ERROR',
         logLevelThresholds: {
@@ -1411,4 +1416,49 @@ describe('Class: Logger', () => {
     });
   });
 
+  describe('Feature: Pretty indentation for a local or non-production environment', () => {
+    
+    test('when the `POWERTOOLS_DEV` env var is SET it makes log output has multiple lines', () => {
+      
+      // Prepare
+      process.env.POWERTOOLS_DEV = 'true';
+      const INDENTATION = LogJsonIndent.PRETTY;
+      const logger = new Logger();
+      const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation();
+
+      // Act
+      logger.info('Message with pretty identation');
+      
+      // Assess
+      expect(consoleSpy).toBeCalledTimes(1);
+      expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
+        level: 'INFO',
+        message: 'Message with pretty identation',
+        service: 'hello-world',
+        timestamp: '2016-06-20T12:08:10.000Z',
+        xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793',
+      }, null, INDENTATION));
+    });
+
+    test('when the `POWERTOOLS_DEV` env var is NOT SET it makes log output as one-liner', () => {
+        
+      // Prepare
+      const logger = new Logger();
+      const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation();
+
+      // Act
+      logger.info('Message without pretty identation');
+      
+      // Assess
+      expect(consoleSpy).toBeCalledTimes(1);
+      expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
+        level: 'INFO',
+        message: 'Message without pretty identation',
+        service: 'hello-world',
+        timestamp: '2016-06-20T12:08:10.000Z',
+        xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793',
+      }));
+    });
+  });
+
 });