fix(logger): fix handling of additional log keys (#614)

* fix(logger): fix handling of additional log keys

* fix(logger): add unit tests

* chore(examples): extend logger example

* docs: update docs about logging additional keys

Author: Dmitry Balabanov

Diff for: docs/core/logger.md

@@ -276,10 +276,12 @@ You can append additional persistent keys and values in the logs generated durin
 ### Appending additional log keys and values 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.
 
 === "handler.ts"
 
-    ```typescript hl_lines="14 18-19"
+    ```typescript hl_lines="14 18-19 23 31"
     import { Logger } from '@aws-lambda-powertools/logger';
 
     const logger = new Logger();
@@ -300,6 +302,17 @@ You can append additional keys and values in a single log item passing them as p
             { data: myImportantVariable },
             { correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } }
         );
+
+        // Simply pass a string for logging additional data
+        logger.info('This is a log with additional string value', 'string value');
+
+        // Directly passing an object containing both the message and the additional info
+        const logObject = {
+            message: 'This is a log message',
+            additionalValue: 42
+        };
+
+        logger.info(logObject);
         
         return {
             foo: 'bar'
@@ -309,7 +322,7 @@ You can append additional keys and values in a single log item passing them as p
     ```
 === "Example CloudWatch Logs excerpt"
 
-    ```json hl_lines="7 15-16"
+    ```json hl_lines="7 15-16 24 32"
     {
         "level": "INFO",
         "message": "This is a log with an extra variable",
@@ -327,6 +340,22 @@ You can append additional keys and values in a single log item passing them as p
         "data": { "foo": "bar" },
         "correlationIds": { "myCustomCorrelationId": "foo-bar-baz" }
     }
+    {
+        "level": "INFO",
+        "message": "This is a log with additional string value",
+        "service": "serverlessAirline",
+        "timestamp": "2021-12-12T22:06:17.463Z",
+        "xray_trace_id": "abcdef123456abcdef123456abcdef123456",
+        "extra": "string value"
+    }
+    {
+        "level": "INFO",
+        "message": "This is a log message",
+        "service": "serverlessAirline",
+        "timestamp": "2021-12-12T22:06:17.463Z",
+        "xray_trace_id": "abcdef123456abcdef123456abcdef123456",
+        "additionalValue": 42
+    }
     ```
 
 ### Logging errors
@@ -347,14 +376,14 @@ The error will be logged with default key name `error`, but you can also pass yo
             throw new Error('Unexpected error #1');
         } catch (error) {
             // Log information about the error using the default "error" key
-            logger.error('This is the first error', error);
+            logger.error('This is the first error', error as Error);
         }
 
         try {
             throw new Error('Unexpected error #2');
         } catch (error) {
             // Log information about the error using a custom "myCustomErrorKey" key
-            logger.error('This is the second error', { myCustomErrorKey: error } );
+            logger.error('This is the second error', { myCustomErrorKey: error as Error } );
         }
 
     };
@@ -391,6 +420,9 @@ The error will be logged with default key name `error`, but you can also pass yo
     }
     ```
 
+!!! tip "Logging errors and log level"
+    You can also log errors using the `warn`, `info`, and `debug` methods. Be aware of the log level though, you might miss those  errors when analyzing the log later depending on the log level configuration.
+
 ## Advanced
 
 ### Using multiple Logger instances across your code

Diff for: packages/logger/examples/additional-keys.ts

@@ -20,6 +20,9 @@ const lambdaHandler: Handler = async () => {
   // Pass an error that occurred
   logger.error('This is an ERROR log', new Error('Something bad happened!'));
 
+  // Pass a simple string as additional data
+  logger.info('This is an INFO log', 'Extra log data');
+
   return {
     foo: 'bar'
   };

Diff for: packages/logger/examples/errors.ts

@@ -17,13 +17,13 @@ const lambdaHandler: Handler = async () => {
   try {
     throw new Error('Unexpected error #1');
   } catch (error) {
-    logger.error('This is an ERROR log #1', error);
+    logger.error('This is an ERROR log #1', error as Error);
   }
 
   try {
     throw new Error('Unexpected error #2');
   } catch (error) {
-    logger.error('This is an ERROR log #2', { myCustomErrorKey: error } );
+    logger.error('This is an ERROR log #2', { myCustomErrorKey: error as Error } );
   }
 
   return {

Diff for: packages/logger/src/Logger.ts

@@ -200,7 +200,7 @@ class Logger extends Utility implements ClassThatLogs {
    * It prints a log item with level DEBUG.
    *
    * @param {LogItemMessage} input
-   * @param {Error | LogAttributes | unknown} extraInput
+   * @param {Error | LogAttributes | string} extraInput
    * @returns {void}
    */
   public debug(input: LogItemMessage, ...extraInput: LogItemExtraInput): void {
@@ -211,7 +211,7 @@ class Logger extends Utility implements ClassThatLogs {
    * It prints a log item with level ERROR.
    *
    * @param {LogItemMessage} input
-   * @param {Error | LogAttributes | unknown} extraInput
+   * @param {Error | LogAttributes | string} extraInput
    * @returns {void}
    */
   public error(input: LogItemMessage, ...extraInput: LogItemExtraInput): void {
@@ -231,7 +231,7 @@ class Logger extends Utility implements ClassThatLogs {
    * It prints a log item with level INFO.
    *
    * @param {LogItemMessage} input
-   * @param {Error | LogAttributes | unknown} extraInput
+   * @param {Error | LogAttributes | string} extraInput
    * @returns {void}
    */
   public info(input: LogItemMessage, ...extraInput: LogItemExtraInput): void {
@@ -288,7 +288,7 @@ class Logger extends Utility implements ClassThatLogs {
    * It prints a log item with level WARN.
    *
    * @param {LogItemMessage} input
-   * @param {Error | LogAttributes | unknown} extraInput
+   * @param {Error | LogAttributes | string} extraInput
    * @returns {void}
    */
   public warn(input: LogItemMessage, ...extraInput: LogItemExtraInput): void {
@@ -336,9 +336,13 @@ class Logger extends Utility implements ClassThatLogs {
     if (typeof input !== 'string') {
       logItem.addAttributes(input);
     }
-    extraInput.forEach((item: Error | LogAttributes | unknown) => {
-      const attributes = item instanceof Error ? { error: item } : item;
-      logItem.addAttributes(<LogAttributes>attributes);
+    extraInput.forEach((item: Error | LogAttributes | string) => {
+      const attributes: LogAttributes =
+        item instanceof Error ? { error: item } :
+          typeof item === 'string' ? { extra: item } :
+            item;
+
+      logItem.addAttributes(attributes);
     });
 
     return logItem;

Diff for: packages/logger/src/types/Logger.ts

@@ -50,7 +50,7 @@ type UnformattedAttributes = {
 };
 
 type LogItemMessage = string | LogAttributesWithMessage;
-type LogItemExtraInput = Array<Error | LogAttributes | unknown>;
+type LogItemExtraInput = [Error | string] | LogAttributes[];
 
 type HandlerMethodDecorator = (
   target: LambdaInterface,

Diff for: packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts

@@ -30,7 +30,7 @@ const testFunction = async (event: APIGatewayProxyEvent, context: Context): Prom
   try {
     throw new Error(ERROR_MSG);
   } catch (e) {
-    logger.error(ERROR_MSG, e);
+    logger.error(ERROR_MSG, e as Error);
   }
 
   return {

Diff for: packages/logger/tests/unit/Logger.test.ts

@@ -288,6 +288,7 @@ describe('Class: Logger', () => {
             logger[methodOfLogger]( { message: 'A log item with an object as first parameters', extra: 'parameter' });
             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');
           }
 
           // Assess
@@ -351,6 +352,14 @@ describe('Class: Logger', () => {
               stack: expect.stringMatching(/Logger.test.ts:[0-9]+:[0-9]+/),
             },
           }));
+          expect(console[methodOfConsole]).toHaveBeenNthCalledWith(7, JSON.stringify({
+            level: method.toUpperCase(),
+            message: 'A log item with a string as first parameter, and a string as second parameter',
+            service: 'hello-world',
+            timestamp: '2016-06-20T12:08:10.000Z',
+            xray_trace_id: 'abcdef123456abcdef123456abcdef123456',
+            extra: 'parameter',
+          }));
         });
       });