bug(logger): standardize extra input logging

[dreamorosi]

Bug description

As described in the docs Logger accepts a second parameter that allows to append additional keys and values in a single log item.

This works when passing an object, for example logger.info('my-message', { data: 'my-value' }); results in:

{
  "cold_start": true,
  "function_arn": "arn:aws:lambda:eu-west-1:123456789101:function:myFunction",
  "function_memory_size": 128,
  "function_name": "AwsLambdaPowertoolsDemoSt-HelloWorldFunctionB2AB6E-sYstm6IvDAEB",
  "function_request_id": "b5fe0e01-91f5-43f2-8ef9-d572df88b61c",
  "level": "INFO",
  "message": "my-message",
  "service": "service_undefined",
  "timestamp": "2022-02-21T11:15:18.493Z",
  "data": "my-value"
}

But when passing directly a string, like: logger.info('my-message', 'my-value'); it results in this:

{
  "0": "m",
  "1": "y",
  "2": "-",
  "3": "v",
  "4": "a",
  "5": "l",
  "6": "u",
  "7": "e",
  "cold_start": false,
  "function_arn": "arn:aws:lambda:eu-west-1:123456789101:function:myFunction",
  "function_memory_size": 128,
  "function_name": "AwsLambdaPowertoolsDemoSt-HelloWorldFunctionB2AB6E-sYstm6IvDAEB",
  "function_request_id": "a0c5ab8f-c0f0-40fa-8c75-347020065880",
  "level": "INFO",
  "message": "my-message",
  "service": "service_undefined",
  "timestamp": "2022-02-21T11:08:19.611Z"
}

Likewise, when passing an array, logger.info('my-message', ['my-value', 'my-value2']); it results in:

{
  "0": "my-value",
  "1": "my-value2",
  "cold_start": true,
  "function_arn": "arn:aws:lambda:eu-west-1:123456789101:function:myFunction",
  "function_memory_size": 128,
  "function_name": "AwsLambdaPowertoolsDemoSt-HelloWorldFunctionB2AB6E-sYstm6IvDAEB",
  "function_request_id": "b5fe0e01-91f5-43f2-8ef9-d572df88b61c",
  "level": "INFO",
  "message": "my-message",
  "service": "service_undefined",
  "timestamp": "2022-02-21T11:15:18.493Z",
}

Expected Behavior

Have a consistent behaviour across data types, potentially using a default key when a string or array are passed, i.e. logger.info('my-message', 'my-value');

{
  "extra_data": "my-value",
  "cold_start": false,
  "function_arn": "arn:aws:lambda:eu-west-1:123456789101:function:myFunction",
  "function_memory_size": 128,
  "function_name": "AwsLambdaPowertoolsDemoSt-HelloWorldFunctionB2AB6E-sYstm6IvDAEB",
  "function_request_id": "a0c5ab8f-c0f0-40fa-8c75-347020065880",
  "level": "INFO",
  "message": "my-message",
  "service": "service_undefined",
  "timestamp": "2022-02-21T11:08:19.611Z"
}

Current Behavior

{
  "0": "m",
  "1": "y",
  "2": "-",
  "3": "v",
  "4": "a",
  "5": "l",
  "6": "u",
  "7": "e",
  "cold_start": false,
  "function_arn": "arn:aws:lambda:eu-west-1:123456789101:function:myFunction",
  "function_memory_size": 128,
  "function_name": "AwsLambdaPowertoolsDemoSt-HelloWorldFunctionB2AB6E-sYstm6IvDAEB",
  "function_request_id": "a0c5ab8f-c0f0-40fa-8c75-347020065880",
  "level": "INFO",
  "message": "my-message",
  "service": "service_undefined",
  "timestamp": "2022-02-21T11:08:19.611Z"
}

Expand below to see full CloudWatch log output

```log 2022-02-21T11:08:19.611Z a0c5ab8f-c0f0-40fa-8c75-347020065880 INFO {"0":"m","1":"y","2":"-","3":"v","4":"a","5":"l","6":"u","7":"e","cold_start":false,"function_arn":"arn:aws:lambda:eu-west-1:123456789101:function:AwsLambdaPowertoolsDemoSt-HelloWorldFunctionB2AB6E-sYstm6IvDAEB","function_memory_size":128,"function_name":"AwsLambdaPowertoolsDemoSt-HelloWorldFunctionB2AB6E-sYstm6IvDAEB","function_request_id":"a0c5ab8f-c0f0-40fa-8c75-347020065880","level":"INFO","message":"my-key","service":"service_undefined","timestamp":"2022-02-21T11:08:19.611Z"} ```

Possible Solution

Check data types and treat them accordingly.

Steps to Reproduce

1. Use any version of @aws-lambda-powertools/logger in your Lambda
2. Emit a lot entry and pass a string or array as second parameter
3. Check logs

Environment

• Powertools version used: any
• Packaging format (Layers, npm): N/A
• AWS Lambda function runtime: nodejs14.x
• Debugging logs: (see above)

Related issues, RFCs

N/A

[dreamorosi]

The proposal in the "expected behaviour" section is not final and can be discussed. Ideally would appreciate whoever picks up the issue to engage with the maintainers to discuss options and implementation before going for a PR.

[ijemmy]

@dreamorosi In the expected behavior, this example:

logger.info('my-key', 'my-value');

Do you actually mean this?

logger.info('my-message', 'my-value');

[dreamorosi]

@ijemmy indeed and good catch. Copy/paste errors, I've corrected the OP.

[ghost]

@ijemmy I'd like to take this one. Let me describe my proposal for the log format for extra strings and arrays. I'll get back to you for a review before implementing it.

[ghost]

@ijemmy @dreamorosi Here's my proposed log format for these use cases. In a nutshell: every additional input without a key gets an auto-generated key extra_data with a zero-based index as suffix. Please let me know if you agree or want to change something.

Examples:

• One additional string: logger.info('my-message', 'my-value')

  "extra_data0" : "my-value"

• Multiple strings: logger.info('my-message', 'my-first-value', 'my-second-value')

  "extra_data0" : "my-first-value",
  "extra_data1" : "my-second-value",

• One array: logger.info('my-message', ['my-value1', 'my-value2'])

  "extra_data0" : ["my-value1", "my-value2"]

• Multiple arrays: logger.info('my-message', ['my-value1', 'my-value2'], ['my-value3'])

  "extra_data0" : ["my-value1", "my-value2"],
  "extra_data1" : ["my-value3"]

Note: Lambda PowerTools for Python and Java only accept additional input with explicitly specified keys (aka dict). I we'd align to them, that would be a breaking change in our API. Should we consider this?

[saragerion]

Thanks for detailing your proposal @AWSDB.
To give more context, currently the logger parameters support these formats:
https://github.com/awslabs/aws-lambda-powertools-typescript/blob/main/packages/logger/tests/unit/Logger.test.ts#L287

// 1) Message as string
logger.info('This is the message value');

// 2) Message as string, object
logger.info('This is the message value', { extra: 'parameter' });

// 3) Message as string, object, object, ...
logger.info('This is the message value', { parameterOne: 'foo' }, { parameterTwo: 'bar' });

// 4) Object (that contains the message key)
logger.info( { message: 'This is the message value', extra: 'parameter' });

// 5) Message as string, error
logger.info('This is the message value', new Error('Something happened!') );

// 6) Message as string, error with custom key
logger.info('This is the message value', { myCustomErrorKey: new Error('Something happened!') });

The current logic of the logger assumes that if you pass a string as first parameter, that string represents the value of the message key in the structured logs. You can achieve the same by passing an object with a message key.
Everything else should be passed as object with key-value pairs because the logger relies on structured logging and developers should give their logs clear and easy to understand keys to troubleshoot.
As action point, this can be an opportunity to make our documentation clearer about the parameters and how they are supposed to be used.

[ghost]

Thanks for the explanation @saragerion.
As stated by @dreamorosi, this issue addresses the logger behavior when callers provide a plain string or an array as additional input (instead of an Error object or a dict).
This is possible because the type is not really restricted:

type LogItemExtraInput = Array<Error | LogAttributes | unknown>;

As I mentioned above, we could restrict the extra objects to the cases you describe (Error and key-value pairs). But then, this would be a breaking change. @dreamorosi proposed a non-breaking fix so that the unknown objects (strings...) will be logged with auto-generated keys, I just elaborated on that a bit.

Please let me know which way you'd prefer: a breaking API change (+updating the docs) or a non-breaking change proposed by @dreamorosi.

[dreamorosi]

Thanks @saragerion for clarifying, I was not aware that examples 3 & 4 in your code snippet were possible. From my side I just wanted to highlight again that I don't have any strong preference towards my proposal.

What I would expect as user would be to either the types telling me I cannot pass a string or else if it's accepted to not break it down into characters in the JSON.

Also definitely consistency with other runtimes is something we should keep in mind.

[ijemmy]

@AWSDB

I've discussed with maintainers. We have to make a trade-off here. And we prefer consistency with other PowerTool even it means a breaking change (as we're still in Beta).

Here's the scope of this issue:

1. Use "extra" field if the customers passes two string (one for message, one for extra)
2. Let's refrain from having multiple extras (e.g. extra0, extra1, etc.) This is not common in other run time. Let's stop user from pass multiple strings or array in type check if possible.
3. Restrict extra objects besides Error and key-value pair). It's better to have a breaking change now than later.
4. Update the official documentation to include the example 1-6 from Sara's comment and the changes above.

[ghost]

I believe we can resolve this one, because the corresponding PR is already merged.

[github-actions]

⚠️ COMMENT VISIBILITY WARNING ⚠️

Comments on closed issues are hard for our team to see.
If you need more assistance, please either tag a team member or open a new issue that references this one.
If you wish to keep having a conversation with other community members under this issue feel free to do so.