Bug: v2 StructuredArguments allow logging of reserved keys

[phipag]

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"
}

[phipag]

TypeScript opted for something similar (aws-powertools/powertools-lambda-typescript#3217). They prevent overwriting of reserved keys and log a warning each time a user attempts to do so. I will do something similar here. Related PR in TypeScript: aws-powertools/powertools-lambda-typescript#3553.

[phipag]

For Log4j we need to update the NON_POWERTOOLS_FIELD_RESOLVER to skip resolving reserved keys (https://github.com/aws-powertools/powertools-lambda-java/blob/v2/powertools-logging/powertools-logging-log4j/src/main/java/org/apache/logging/log4j/layout/template/json/resolver/PowertoolsResolver.java#L173-L203).

There is already a safeguard in place for MDC context keys, however it does not work as intended:

powertools-lambda-java/powertools-logging/powertools-logging-log4j/src/main/java/org/apache/logging/log4j/layout/template/json/resolver/PowertoolsResolver.java

Lines 183 to 188 in 7b18029

	contextData.forEach((key, value) -> {
	if (!PowertoolsLoggedFields.stringValues().contains(key)) {
	serializer.writeSeparator();
	serializer.writeObjectField(key, value);
	}
	});

While this will avoid appending the reserved key a second time, the regular field resolver will still run and set the overwritten value.

Idea 1: We cannot intercept the MDC.put calls since the come from the standard slf4j interface. But we can block resolving the event if the source of the logevent comes from outside of the Powertools package.

• This doesn't work because the context will be passed with each log event. We would block resolving of the field for all customer log events if we did this.

Idea 2: We could track MDC context changes on reserved keys only and block changes coming from customer source code. However, this seems overengineered for the problem at hand and might impact logging performance and memory usage to do such a complicated change.

Idea 3: Whenever we call MDC.put from within the library we actually put a different name like "_PT_function_name" and map this modified name to the resolver that will add the field to the structured log. Just before adding the field, the resolver will remove the "_PT_" from the name again. This might solve the problem for the structured logs but it will leave the MDC in a confusing state for users who use the MDC in any other way.

As the title of the issue says, I will focus on blocking reserved key usage on StructuredArguments only for now.

[phipag]

I created a PR to prevent overwriting of reserved keys via structured arguments. I also added a warning in the documentation for this. This PR also fixes a bug in the serialization of MapArguments.

PR: #1822

The output is as expected now:

    @Logging(clearState = true)
    public String handleRequest(final Object input, final Context context) {
        LOGGER.info("My message.", StructuredArguments.entry("message", "My duplicated message."),
                StructuredArguments.entry("message2", "My second message."),
                StructuredArguments.entry("service", "My duplicated service."),
                StructuredArguments.entry("function_name", "My duplicated function_name"));
        return "OK";
    }

yields

{
  "level": "INFO",
  "message": "My message.",
  "cold_start": true,
  "function_arn": "arn:aws:lambda:us-east-1:012345678912:function:HelloWorldFunction",
  "function_memory_size": 512,
  "function_name": "HelloWorldFunction",
  "function_request_id": "0fbef3a7-6b9a-4203-af44-e4e35ff6ca99",
  "function_version": "$LATEST",
  "service": "service_undefined",
  "timestamp": "2025-04-23T14:19:16.552Z",
  "message2": "My second message."
}

I decided to not log a warning for each log emitted because it felt like too much spam and might drive up CloudWatch costs for users who do not notice the warning.

[phipag]

Resolved by PR #1822. Please see this PR message for details about the final implementation: #1822 (comment).

We opted for adding warning messages if users attempt to log a reserved key via StructuredArguments.