Bug: replace system fields value from seconds parameters

[VladimirGorobetsWildix]

Expected Behavior

System fields should not be replaced by values ​​from additional parameters.
If duplicate fields occur, a prefix should be added for fields from additional objects.

For example message -> _message

Current Behavior

import {Logger} from '@aws-lambda-powertools/logger';

const logger = new Logger({
    serviceName: 'production-server',
});

const data = {
    timestamp: 'one year ago',
    name: 'user',
    message: 'message from chat',
    level: 'poweredUser',
    service: 'internal chat',
}

logger.info('test message', {user: 'admin'});

logger.info('very important log key', data);

Received result

{"level":"INFO","message":"test message","sampling_rate":0,"service":"production-server","timestamp":"2024-10-17T14:40:49.209Z","user":"admin"}

{"level":"poweredUser","message":"message from chat","sampling_rate":0,"service":"internal chat","timestamp":"one year ago","name":"user"}

First log is correct, but in the second log all system fields have been based on the fields of the second object.

This is a very non-obvious behavior that results in the loss of important logs and many hours of debugging and understanding the cause.

Code snippet

import {Logger} from '@aws-lambda-powertools/logger';

const logger = new Logger({
    serviceName: 'production-server',
});

const data = {
    timestamp: 'one year ago',
    name: 'user',
    message: 'message from chat',
    level: 'poweredUser',
    service: 'internal chat',
}

logger.info('test message', {user: 'admin'});

logger.info('very important log key', data);

Steps to Reproduce

1. run snippet code
2. find changed system fields (timestamp, message, level.....)

Possible Solution

If duplicate fields occur, a prefix should be added for fields from additional objects.

For example message -> _message

Powertools for AWS Lambda (TypeScript) version

latest

AWS Lambda function runtime

20.x

Packaging format used

npm

Execution logs

{"level":"INFO","message":"test message","sampling_rate":0,"service":"production-server","timestamp":"2024-10-17T14:40:49.209Z","user":"admin"}

{"level":"poweredUser","message":"message from chat","sampling_rate":0,"service":"internal chat","timestamp":"one year ago","name":"user"}

[boring-cyborg]

Thanks for opening your first issue here! We'll come back to you as soon as we can.
In the meantime, check out the #typescript channel on our Powertools for AWS Lambda Discord: Invite link

[dreamorosi]

Hi, thank you for opening this issue.

I believe this is intended, according to our documentation here (emphasis mine):

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 }

To avoid the behavior you're seeing, the data parameter should be within an object:

logger.info('very important log key', { data });

which I confirmed produces:

{
    "level": "INFO",
    "message": "very important log key",
    "sampling_rate": 0,
    "service": "production-server",
    "timestamp": "2024-10-17T15:14:59.825Z",
    "data": {
        "timestamp": "one year ago",
        "name": "user",
        "message": "message from chat",
        "level": "poweredUser",
        "service": "internal chat"
    }
}

This is necessary because by default we merge each parameter with the JSON object of the log, so if your parameters have objects with duplicate keys they'll overwrite existing keys.

I understand how the current wording doesn't explicitly state this, and I am sorry to hear it led to data loss. We'll consider improving the section, perhaps with a more explicit disclaimer.

[VladimirGorobetsWildix]

A warning in the documentation is very good, but trying to fix potential developer errors would be great.

This is very unobvious behavior because it is not limited in any way with the help of TypeScript, and the developer constantly needs to remember this feature of the logger.

Yesterday, one of our developers spent a lot of time because of this feature of the logger.

It is very difficult for a developer who is using your logger for the first time to understand why this can be done

logger.info('very important log key', {info: data});

but that's not possible

logger.info('very important log key', {message: data});

[VladimirGorobetsWildix]

In our case, the developer followed your recommendation completely, but got unexpected behavior.

const message = await getMessageById(id);

logger.info('received message', {message});