fix(logger): enable logging of arbitrary objects (#883)

* fix(logger): enable logging of arbitrary objects

* Update docs

* Add E2E test

* Use nested objects in tests

* Update usage docs

Author: Dmitry Balabanov

docs/core/logger.md

@@ -273,34 +273,37 @@ You can append additional persistent keys and values in the logs generated durin
 
 !!! tip "Logger will automatically ignore any key with an `undefined` value"
 
-### Appending additional log keys and values to a single log item
+### Appending additional data to a single log item
 
-You can append additional keys and values in a single log item passing them as parameters.
-Pass a string for logging it with default key name `extra`. Alternatively, pass one or multiple objects with custom keys.
-If you already have an object containing a `message` key and an additional property, you can pass this object directly.
+You can append additional data to a single log item by passing objects as additional parameters.
+
+* Pass a simple string for logging it with default key name `extra`
+* Pass one or multiple objects containing arbitrary data to be logged. Each data object should be placed in an enclosing object as a single property value, you can name this property as you need: `{ myData: arbitraryObjectToLog }`
+* If you already have an object containing a `message` key and an additional property, you can pass this object directly
 
 === "handler.ts"
 
-    ```typescript hl_lines="14 18-19 23 31"
+    ```typescript hl_lines="14 18-20 24 32"
     import { Logger } from '@aws-lambda-powertools/logger';
 
     const logger = new Logger();
 
-    export const handler = async (_event: any, _context: any): Promise<unknown> => {
+    export const handler = async (event: any, _context: any): Promise<unknown> => {
 
         const myImportantVariable = {
             foo: 'bar'
         };
         
-        // Pass additional keys and values in single log items
+        // Log additional data in single log items
         
         // As second parameter
         logger.info('This is a log with an extra variable', { data: myImportantVariable });
         
-        // You can also pass multiple parameters
-        logger.info('This is a log with 2 extra variables',
+        // You can also pass multiple parameters containing arbitrary objects
+        logger.info('This is a log with 3 extra objects',
             { data: myImportantVariable },
-            { correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } }
+            { correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } },
+            { lambdaEvent: event }
         );
 
         // Simply pass a string for logging additional data
@@ -322,14 +325,14 @@ If you already have an object containing a `message` key and an additional prope
     ```
 === "Example CloudWatch Logs excerpt"
 
-    ```json hl_lines="7 15-16 24 32"
+    ```json hl_lines="7 15-21 28 37"
     {
         "level": "INFO",
         "message": "This is a log with an extra variable",
         "service": "serverlessAirline",
         "timestamp": "2021-12-12T22:06:17.463Z",
         "xray_trace_id": "abcdef123456abcdef123456abcdef123456",
-        "data": { foo: "bar" }
+        "data": { "foo": "bar" }
     }
     {
         "level": "INFO",
@@ -338,7 +341,12 @@ If you already have an object containing a `message` key and an additional prope
         "timestamp": "2021-12-12T22:06:17.466Z",
         "xray_trace_id": "abcdef123456abcdef123456abcdef123456",
         "data": { "foo": "bar" },
-        "correlationIds": { "myCustomCorrelationId": "foo-bar-baz" }
+        "correlationIds": { "myCustomCorrelationId": "foo-bar-baz" },
+        "lambdaEvent": { 
+            "exampleEventData": {
+                "eventValue": 42
+            }
+        }
     }
     {
         "level": "INFO",

packages/logger/examples/additional-keys.ts

@@ -12,7 +12,7 @@ import { Logger } from '../src';
 
 const logger = new Logger();
 
-const lambdaHandler: Handler = async () => {
+const lambdaHandler: Handler = async (event) => {
 
   // Pass a custom correlation ID
   logger.warn('This is a WARN log', { correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } });
@@ -23,6 +23,9 @@ const lambdaHandler: Handler = async () => {
   // Pass a simple string as additional data
   logger.info('This is an INFO log', 'Extra log data');
 
+  // Pass an arbitrary object as additional data
+  logger.debug('This is a DEBUG log', { lambdaEvent: event });
+
   return {
     foo: 'bar'
   };

packages/logger/src/types/Log.ts

@@ -9,7 +9,7 @@ type LogLevelThresholds = {
   [key in LogLevel]: number;
 };
 
-type LogAttributeValue = string | number | boolean | null | undefined | LogAttributeValue[] | { [key: string]: LogAttributeValue } | Error;
+type LogAttributeValue = unknown;
 type LogAttributes = { [key: string]: LogAttributeValue };
 
 type LogAttributesWithMessage = LogAttributes & {

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

@@ -1,12 +1,14 @@
 import { injectLambdaContext, Logger } from '../../src';
-import { APIGatewayProxyEvent, Context } from 'aws-lambda';
+import { APIGatewayProxyEvent, Context, APIGatewayAuthorizerResult } from 'aws-lambda';
 import middy from '@middy/core';
 
 const PERSISTENT_KEY = process.env.PERSISTENT_KEY;
 const PERSISTENT_VALUE = process.env.PERSISTENT_VALUE;
 const ERROR_MSG = process.env.ERROR_MSG || 'error';
 const SINGLE_LOG_ITEM_KEY = process.env.SINGLE_LOG_ITEM_KEY;
 const SINGLE_LOG_ITEM_VALUE = process.env.SINGLE_LOG_ITEM_VALUE;
+const ARBITRARY_OBJECT_KEY = process.env.ARBITRARY_OBJECT_KEY;
+const ARBITRARY_OBJECT_DATA = process.env.ARBITRARY_OBJECT_DATA;
 
 const logger = new Logger({
   persistentLogAttributes: {
@@ -34,6 +36,21 @@ const testFunction = async (event: APIGatewayProxyEvent, context: Context): Prom
     logger.error(ERROR_MSG, e as Error);
   }
 
+  // Test feature 7: Logging an arbitrary object
+  const obj: APIGatewayAuthorizerResult = {
+    principalId: ARBITRARY_OBJECT_DATA,
+    policyDocument: {
+      Version: 'Version' + ARBITRARY_OBJECT_DATA,
+      Statement: [{
+        Effect: 'Effect' + ARBITRARY_OBJECT_DATA,
+        Action: 'Action' + ARBITRARY_OBJECT_DATA,
+        Resource: 'Resource' + ARBITRARY_OBJECT_DATA
+      }]
+    }
+  };
+
+  logger.info('A log entry with an object', { [ARBITRARY_OBJECT_KEY]: obj });
+
   return {
     requestId: context.awsRequestId,
   };

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

@@ -10,6 +10,7 @@
 import path from 'path';
 import { randomUUID } from 'crypto';
 import { App, Stack } from 'aws-cdk-lib';
+import { APIGatewayAuthorizerResult } from 'aws-lambda';
 import {
   createStackWithLambdaFunction,
   generateUniqueName,
@@ -45,6 +46,8 @@ const PERSISTENT_VALUE = `a persistent value that will be put in every log ${uui
 const SINGLE_LOG_ITEM_KEY = `keyForSingleLogItem${uuid}`;
 const SINGLE_LOG_ITEM_VALUE = `a value for a single log item${uuid}`;
 const ERROR_MSG = `error-${uuid}`;
+const ARBITRARY_OBJECT_KEY = `keyForArbitraryObject${uuid}`;
+const ARBITRARY_OBJECT_DATA = `arbitrary object data ${uuid}`;
 
 const integTestApp = new App();
 let logGroupName: string; // We do not know it until deployment
@@ -72,6 +75,8 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime}
         SINGLE_LOG_ITEM_KEY,
         SINGLE_LOG_ITEM_VALUE,
         ERROR_MSG,
+        ARBITRARY_OBJECT_KEY,
+        ARBITRARY_OBJECT_DATA,
       },
       logGroupOutputKey: STACK_OUTPUT_LOG_GROUP,
       runtime: runtime,
@@ -161,10 +166,32 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime}
 
       expect(logMessages).toHaveLength(1);
     }, TEST_CASE_TIMEOUT);
+
+    it('should log additional arbitrary object only once', async () => {
+      const logMessages = invocationLogs[0].getFunctionLogs()
+        .filter(message => message.includes(ARBITRARY_OBJECT_DATA));
+
+      expect(logMessages).toHaveLength(1);
+
+      const logObject = InvocationLogs.parseFunctionLog(logMessages[0]);
+      expect(logObject).toHaveProperty(ARBITRARY_OBJECT_KEY);
+      const arbitrary = logObject[ARBITRARY_OBJECT_KEY] as APIGatewayAuthorizerResult;
+      expect(arbitrary.principalId).toBe(ARBITRARY_OBJECT_DATA);
+      expect(arbitrary.policyDocument).toEqual(expect.objectContaining(
+        {
+          Version: 'Version' + ARBITRARY_OBJECT_DATA,
+          Statement: [{
+            Effect: 'Effect' + ARBITRARY_OBJECT_DATA,
+            Action: 'Action' + ARBITRARY_OBJECT_DATA,
+            Resource: 'Resource' + ARBITRARY_OBJECT_DATA
+          }]
+        }
+      ));
+    }, TEST_CASE_TIMEOUT);
   });
 
   describe('Logging an error object', () => {
-    it('should log additional keys and value only once', async () => {
+    it('should log error only once', async () => {
       const logMessages = invocationLogs[0].getFunctionLogs(LEVEL.ERROR)
         .filter(message => message.includes(ERROR_MSG));
 

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

@@ -280,6 +280,14 @@ describe('Class: Logger', () => {
           });
           const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation();
 
+          interface NestedObject { bool: boolean; str: string; num: number; err: Error }
+          interface ArbitraryObject<TNested> { value: 'CUSTOM' | 'USER_DEFINED'; nested: TNested }
+
+          const arbitraryObject: ArbitraryObject<NestedObject> = {
+            value: 'CUSTOM',
+            nested: { bool: true, str: 'string value', num: 42, err: new Error('Arbitrary object error') }
+          };
+
           // Act
           if (logger[methodOfLogger]) {
             logger[methodOfLogger]('A log item without extra parameters');
@@ -289,6 +297,8 @@ describe('Class: Logger', () => {
             logger[methodOfLogger]('A log item with a string as first parameter, and an error as second parameter', new Error('Something happened!'));
             logger[methodOfLogger]('A log item with a string as first parameter, and an error with custom key as second parameter', { myCustomErrorKey: new Error('Something happened!') });
             logger[methodOfLogger]('A log item with a string as first parameter, and a string as second parameter', 'parameter');
+            logger[methodOfLogger]('A log item with a string as first parameter, and an inline object as second parameter', { extra: { custom: mockDate } });
+            logger[methodOfLogger]('A log item with a string as first parameter, and an arbitrary object as second parameter', { extra: arbitraryObject });
           }
 
           // Assess
@@ -360,6 +370,36 @@ describe('Class: Logger', () => {
             xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793',
             extra: 'parameter',
           }));
+          expect(consoleSpy).toHaveBeenNthCalledWith(8, JSON.stringify({
+            level: method.toUpperCase(),
+            message: 'A log item with a string as first parameter, and an inline object as second parameter',
+            service: 'hello-world',
+            timestamp: '2016-06-20T12:08:10.000Z',
+            xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793',
+            extra: { custom: '2016-06-20T12:08:10.000Z' }
+          }));
+          const parameterCallNumber9 = JSON.parse(consoleSpy.mock.calls[8][0]);
+          expect(parameterCallNumber9).toEqual(expect.objectContaining({
+            level: method.toUpperCase(),
+            message: 'A log item with a string as first parameter, and an arbitrary object as second parameter',
+            service: 'hello-world',
+            timestamp: '2016-06-20T12:08:10.000Z',
+            xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793',
+            extra: {
+              value: 'CUSTOM',
+              nested: {
+                bool: true,
+                str: 'string value',
+                num: 42,
+                err: {
+                  location: expect.stringMatching(/Logger.test.ts:[0-9]+$/),
+                  message: 'Arbitrary object error',
+                  name: 'Error',
+                  stack: expect.stringMatching(/Logger.test.ts:[0-9]+:[0-9]+/),
+                }
+              }
+            }
+          }));
         });
       });