Description
What were you trying to accomplish?
The current 2.0.0-SNAPSHOT allows logging of reserved keys via structured arguments. This can lead to bugs where users accidentally log a key that is reserved by either the Logging module itself (e.g. message) or Powertools.
Examples below are using:
<dependency>
<groupId>software.amazon.lambda</groupId>
<artifactId>powertools-logging-log4j</artifactId>
<version>2.0.0-SNAPSHOT</version>
</dependency>Expected Behavior
Given the following code, my expected behavior is that the message and service key appended via StructuredArguments are ignored and a user warning is logged stating that the appended keys are reserved keys by Powertools logging.
public class App implements RequestHandler {
Logger log = LogManager.getLogger(App.class);
@Logging
public String handleRequest(final Object input, final Context context) {
log.info(
"My message.",
StructuredArguments.entry("message", "My duplicated message."),
StructuredArguments.entry("service", "My duplicated service."));
return "OK";
}
}Expected output:
{
"level": "INFO",
"message": "My message.",
"cold_start": true,
"function_arn": "arn:aws:lambda:eu-west-1:<account id>:function:<function name>",
"function_memory_size": 512,
"function_name": "<function name>",
"function_request_id": "9b990378-33dc-470a-a4f2-5f69ccfca154",
"function_version": "$LATEST",
"service": "${env:POWERTOOLS_SERVICE_NAME}",
"timestamp": "2025-01-31T10:54:23.730Z",
"xray_trace_id": "1-679cabdd-0676a40a4205208f06b16cbf"
}
{
"level": "WARN",
"message": "Detected logging of reserved keys 'message', 'service' as structured arguments. Structured arguments with reserved keys will be ignored. More information at <link to docs>.",
"cold_start": true,
"function_arn": "arn:aws:lambda:eu-west-1:<account id>:function:<function name>",
"function_memory_size": 512,
"function_name": "<function name>",
"function_request_id": "9b990378-33dc-470a-a4f2-5f69ccfca154",
"function_version": "$LATEST",
"service": "${env:POWERTOOLS_SERVICE_NAME}",
"timestamp": "2025-01-31T10:54:23.730Z",
"xray_trace_id": "1-679cabdd-0676a40a4205208f06b16cbf"
}Current Behavior
The current behavior outputs the key twice to STDOUT. In CloudWatch, it ignores the first key which will lead to logging of the structured argument only.
Output to STDOUT (second message and service key comes from StructuredArguments):
{"level":"INFO","message":"My message.","cold_start":true,"function_arn":"arn:aws:lambda:us-east-1:<account id>:function:<function name>","function_memory_size":512,"function_name":"<function name>","function_request_id":"b8670361-9faf-41a4-8e8c-a8ac98c57d29","function_version":"$LATEST","service":"service_undefined","timestamp":"2025-01-31T11:10:13.316Z","message":"My duplicated message.","service":"My duplicated service."}Output in CloudWatch (initial message and service keys are shadowed by the provided structured arguments without warning):
{
"level": "INFO",
"message": "My duplicated message.", # <-- Structured argument overwrites actual log message
"cold_start": true,
"function_arn": "arn:aws:lambda:eu-west-1:<account id>:function:<function name>",
"function_memory_size": 512,
"function_name": "<function name>",
"function_request_id": "9b990378-33dc-470a-a4f2-5f69ccfca154",
"function_version": "$LATEST",
"service": "My duplicated service.", # <-- Structured arguments overwrites Powertools service key
"timestamp": "2025-01-31T10:54:23.730Z",
"xray_trace_id": "1-679cabdd-0676a40a4205208f06b16cbf"
}Environment
- Powertools for AWS Lambda (Java) version used:
2.0.0-SNAPSHOT/ Java11 - Packaging format (Layers, Maven/Gradle): Maven
- AWS Lambda function runtime: Java11
Same behavior in 1.18.0
Same behavior is observed for the current v1 version 1.18.0.
<dependency>
<groupId>software.amazon.lambda</groupId>
<artifactId>powertools-logging</artifactId>
<version>1.18.0</version>
</dependency>public class App implements RequestHandler {
Logger log = LogManager.getLogger(App.class);
@Logging
public String handleRequest(final Object input, final Context context) {
LoggingUtils.appendKey("message", "My duplicated message.");
LoggingUtils.appendKey("service", "My duplicated service.");
log.info("My message.");
return "OK";
}
}{
"timestamp": "2025-01-31T11:22:22.088+0000UTC",
"instant": {
"epochSecond": 1738322542,
"nanoOfSecond": 88459000
},
"thread": "main",
"level": "INFO",
"loggerName": "helloworld.App",
"message": "My duplicated message.", # <-- appendKey overwrites actual log message
"endOfBatch": false,
"loggerFqcn": "org.apache.logging.log4j.spi.AbstractLogger",
"threadId": 1,
"threadPriority": 5,
"coldStart": "true",
"functionArn": "arn:aws:lambda:eu-west-1:<account id>:function:<function name>",
"functionMemorySize": "512",
"functionName": "<function name>",
"functionVersion": "$LATEST",
"function_request_id": "c4d82e40-f07d-4f40-9fc2-87cb1360fb0d",
"samplingRate": "0.0",
"service": "My duplicated service.", # <-- appendKey overwrites Powertools service name
"xray_trace_id": "1-679cb26b-2a91f0cc29bb36af081bdfba"
}