fix(logging): Prevent accidental overwriting of reserved keys via structured arguments

docs/core/logging.md

@@ -354,6 +354,9 @@ Your logs will always include the following keys in your structured logging:
 | **xray_trace_id** | String | "1-5759e988-bd862e3fe1be46a994272793"                                                               | X-Ray Trace ID when [Tracing is enabled](https://docs.aws.amazon.com/lambda/latest/dg/services-xray.html){target="_blank"} |
 | **error**         | Map    | `{ "name": "InvalidAmountException", "message": "Amount must be superior to 0", "stack": "at..." }` | Eventual exception (e.g. when doing `logger.error("Error", new InvalidAmountException("Amount must be superior to 0"));`)  |
 
+???+ note
+    If you emit a log message with a key that matches one of the [standard structured keys](#standard-structured-keys) or one of the [additional structured keys](#additional-structured-keys), the Logger will log a warning message and ignore the key.
+
 ## Additional structured keys
 
 ### Logging Lambda context information
@@ -640,6 +643,9 @@ To append additional keys in your logs, you can use the `StructuredArguments` cl
             }
         ```
 
+???+ warning "Do not use reserved keys in `StructuredArguments`"
+    If the key name of your structured argument matches any of the [standard structured keys](#standard-structured-keys) or any of the [additional structured keys](#additional-structured-keys), the Logger will log a warning message and ignore the key. This is to protect you from accidentally overwriting reserved keys such as the log level or Lambda context information.
+
 **Using MDC**
 
 Mapped Diagnostic Context (MDC) is essentially a Key-Value store. It is supported by the [SLF4J API](https://www.slf4j.org/manual.html#mdc){target="_blank"},
@@ -650,6 +656,9 @@ Mapped Diagnostic Context (MDC) is essentially a Key-Value store. It is supporte
 ???+ warning "Custom keys stored in the MDC are persisted across warm invocations"
     Always set additional keys as part of your handler method to ensure they have the latest value, or explicitly clear them with [`clearState=true`](#clearing-state).
 
+???+ warning "Do not add reserved keys to MDC"
+    Avoid adding any of the keys listed in [standard structured keys](#standard-structured-keys) and [additional structured keys](#additional-structured-keys) to your MDC. This may cause unindented behavior and will overwrite the context set by the Logger. Unlike with `StructuredArguments`, the Logger will **not** ignore reserved keys set via MDC.
+
 
 ### Removing additional keys
 

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

@@ -191,8 +191,8 @@ public void resolve(LogEvent logEvent, JsonWriter jsonWriter) {
                     Object[] arguments = logEvent.getMessage().getParameters();
                     if (arguments != null) {
                         stream(arguments).filter(StructuredArgument.class::isInstance).forEach(argument -> {
-                            serializer.writeRaw(',');
                             try {
+                                serializer.writeRaw(',');
                                 ((StructuredArgument) argument).writeTo(serializer);
                             } catch (IOException e) {
                                 System.err.printf("Failed to encode log event, error: %s.%n", e.getMessage());
@@ -204,19 +204,20 @@ public void resolve(LogEvent logEvent, JsonWriter jsonWriter) {
 
     private final EventResolver internalResolver;
 
-    private static final Map<String, EventResolver> eventResolverMap = Collections.unmodifiableMap(Stream.of(new Object[][] {
-            { SERVICE.getName(), SERVICE_RESOLVER },
-            { FUNCTION_NAME.getName(), FUNCTION_NAME_RESOLVER },
-            { FUNCTION_VERSION.getName(), FUNCTION_VERSION_RESOLVER },
-            { FUNCTION_ARN.getName(), FUNCTION_ARN_RESOLVER },
-            { FUNCTION_MEMORY_SIZE.getName(), FUNCTION_MEMORY_RESOLVER },
-            { FUNCTION_REQUEST_ID.getName(), FUNCTION_REQ_RESOLVER },
-            { FUNCTION_COLD_START.getName(), COLD_START_RESOLVER },
-            { FUNCTION_TRACE_ID.getName(), XRAY_TRACE_RESOLVER },
-            { SAMPLING_RATE.getName(), SAMPLING_RATE_RESOLVER },
-            { "region", REGION_RESOLVER },
-            { "account_id", ACCOUNT_ID_RESOLVER }
-    }).collect(Collectors.toMap(data -> (String) data[0], data -> (EventResolver) data[1])));
+    private static final Map<String, EventResolver> eventResolverMap = Collections
+            .unmodifiableMap(Stream.of(new Object[][] {
+                    { SERVICE.getName(), SERVICE_RESOLVER },
+                    { FUNCTION_NAME.getName(), FUNCTION_NAME_RESOLVER },
+                    { FUNCTION_VERSION.getName(), FUNCTION_VERSION_RESOLVER },
+                    { FUNCTION_ARN.getName(), FUNCTION_ARN_RESOLVER },
+                    { FUNCTION_MEMORY_SIZE.getName(), FUNCTION_MEMORY_RESOLVER },
+                    { FUNCTION_REQUEST_ID.getName(), FUNCTION_REQ_RESOLVER },
+                    { FUNCTION_COLD_START.getName(), COLD_START_RESOLVER },
+                    { FUNCTION_TRACE_ID.getName(), XRAY_TRACE_RESOLVER },
+                    { SAMPLING_RATE.getName(), SAMPLING_RATE_RESOLVER },
+                    { "region", REGION_RESOLVER },
+                    { "account_id", ACCOUNT_ID_RESOLVER }
+            }).collect(Collectors.toMap(data -> (String) data[0], data -> (EventResolver) data[1])));
 
 
     PowertoolsResolver(final TemplateResolverConfig config) {

powertools-logging/powertools-logging-log4j/src/test/java/org/apache/logging/log4j/layout/template/json/resolver/PowertoolsResolverArgumentsTest.java

@@ -35,6 +35,8 @@
 import org.junit.jupiter.api.Test;
 import org.mockito.Mock;
 import org.slf4j.MDC;
+
+import software.amazon.lambda.powertools.logging.internal.PowertoolsLoggedFields;
 import software.amazon.lambda.powertools.logging.internal.handler.PowertoolsArguments;
 
 @Order(2)
@@ -83,9 +85,17 @@ void shouldLogArgumentsAsJsonWhenUsingRawJson() {
         // THEN
         File logFile = new File("target/logfile.json");
         assertThat(contentOf(logFile))
-                .contains("\"input\":{\"awsRegion\":\"eu-west-1\",\"body\":\"plop\",\"eventSource\":\"eb\",\"messageAttributes\":{\"keyAttribute\":{\"stringListValues\":[\"val1\",\"val2\",\"val3\"]}},\"messageId\":\"1212abcd\"}")
+                .contains(
+                        "\"input\":{\"awsRegion\":\"eu-west-1\",\"body\":\"plop\",\"eventSource\":\"eb\",\"messageAttributes\":{\"keyAttribute\":{\"stringListValues\":[\"val1\",\"val2\",\"val3\"]}},\"messageId\":\"1212abcd\"}")
                 .contains("\"message\":\"1212abcd\"")
                 .contains("\"message\":\"Message body = plop and id = \\\"1212abcd\\\"\"");
+        // Reserved keys should be ignored
+        PowertoolsLoggedFields.stringValues().stream().forEach(reservedKey -> {
+            assertThat(contentOf(logFile)).doesNotContain("\"" + reservedKey + "\":\"shouldBeIgnored\"");
+            assertThat(contentOf(logFile)).contains(
+                    "\"message\":\"Attempted to use reserved key '" + reservedKey
+                            + "' in structured argument. This key will be ignored.\"");
+        });
     }
 
     @Test
@@ -107,9 +117,18 @@ void shouldLogArgumentsAsJsonWhenUsingKeyValue() {
         // THEN
         File logFile = new File("target/logfile.json");
         assertThat(contentOf(logFile))
-                .contains("\"input\":{\"awsRegion\":\"eu-west-1\",\"body\":\"plop\",\"eventSource\":\"eb\",\"messageAttributes\":{\"keyAttribute\":{\"stringListValues\":[\"val1\",\"val2\",\"val3\"]}},\"messageId\":\"1212abcd\"}")
+                .contains(
+                        "\"input\":{\"awsRegion\":\"eu-west-1\",\"body\":\"plop\",\"eventSource\":\"eb\",\"messageAttributes\":{\"keyAttribute\":{\"stringListValues\":[\"val1\",\"val2\",\"val3\"]}},\"messageId\":\"1212abcd\"}")
                 .contains("\"message\":\"1212abcd\"")
                 .contains("\"message\":\"Message body = plop and id = \\\"1212abcd\\\"\"");
+
+        // Reserved keys should be ignored
+        PowertoolsLoggedFields.stringValues().stream().forEach(reservedKey -> {
+            assertThat(contentOf(logFile)).doesNotContain("\"" + reservedKey + "\":\"shouldBeIgnored\"");
+            assertThat(contentOf(logFile)).contains(
+                    "\"message\":\"Attempted to use reserved key '" + reservedKey
+                            + "' in structured argument. This key will be ignored.\"");
+        });
     }
 
     private void setupContext() {
@@ -119,4 +138,4 @@ private void setupContext() {
         when(context.getMemoryLimitInMB()).thenReturn(10);
         when(context.getAwsRequestId()).thenReturn("RequestId");
     }
-}
+}

powertools-logging/powertools-logging-log4j/src/test/java/software/amazon/lambda/powertools/logging/internal/handler/PowertoolsArguments.java

@@ -16,15 +16,21 @@
 
 import static software.amazon.lambda.powertools.logging.internal.PowertoolsLoggedFields.CORRELATION_ID;
 
+import java.util.HashMap;
+import java.util.Map;
+
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.slf4j.MDC;
+
 import com.amazonaws.services.lambda.runtime.Context;
 import com.amazonaws.services.lambda.runtime.RequestHandler;
 import com.amazonaws.services.lambda.runtime.events.SQSEvent;
 import com.fasterxml.jackson.core.JsonProcessingException;
-import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
-import org.slf4j.MDC;
+
 import software.amazon.lambda.powertools.logging.Logging;
 import software.amazon.lambda.powertools.logging.argument.StructuredArguments;
+import software.amazon.lambda.powertools.logging.internal.PowertoolsLoggedFields;
 import software.amazon.lambda.powertools.utilities.JsonConfig;
 
 public class PowertoolsArguments implements RequestHandler<SQSEvent.SQSMessage, String> {
@@ -41,11 +47,27 @@ public String handleRequest(SQSEvent.SQSMessage input, Context context) {
         try {
             MDC.put(CORRELATION_ID.getName(), input.getMessageId());
             if (argumentFormat == ArgumentFormat.JSON) {
-                LOG.debug("SQS Event", StructuredArguments.json("input",
-                        JsonConfig.get().getObjectMapper().writeValueAsString(input)));
+                LOG.debug("SQS Event",
+                        StructuredArguments.json("input",
+                                JsonConfig.get().getObjectMapper().writeValueAsString(input)),
+                        // function_name is a reserved key by PowertoolsLoggedFields and should be omitted
+                        StructuredArguments.entry("function_name", "shouldBeIgnored"));
             } else {
-                LOG.debug("SQS Event", StructuredArguments.entry("input", input));
+                LOG.debug("SQS Event",
+                        StructuredArguments.entry("input", input),
+                        // function_name is a reserved key by PowertoolsLoggedFields and should be omitted
+                        StructuredArguments.entry("function_name", "shouldBeIgnored"));
+            }
+
+            // Attempt logging all reserved keys, the values should not be overwritten by "shouldBeIgnored"
+            final Map<String, String> reservedKeysMap = new HashMap<>();
+            for (String field : PowertoolsLoggedFields.stringValues()) {
+                reservedKeysMap.put(field, "shouldBeIgnored");
             }
+            reservedKeysMap.put("message", "shouldBeIgnored");
+            reservedKeysMap.put("level", "shouldBeIgnored");
+            reservedKeysMap.put("timestamp", "shouldBeIgnored");
+            LOG.debug("Reserved keys", StructuredArguments.entries(reservedKeysMap));
             LOG.debug("{}", input.getMessageId());
             LOG.warn("Message body = {} and id = \"{}\"", input.getBody(), input.getMessageId());
         } catch (JsonProcessingException e) {

powertools-logging/powertools-logging-logback/src/main/java/software/amazon/lambda/powertools/logging/logback/JsonUtils.java

@@ -22,6 +22,7 @@
 import java.util.Map;
 import java.util.TimeZone;
 import java.util.TreeMap;
+
 import software.amazon.lambda.powertools.logging.argument.StructuredArgument;
 import software.amazon.lambda.powertools.logging.internal.JsonSerializer;
 import software.amazon.lambda.powertools.logging.internal.PowertoolsLoggedFields;
@@ -36,7 +37,7 @@ private JsonUtils() {
     }
 
     static void serializeTimestamp(JsonSerializer generator, long timestamp, String timestampFormat,
-                                          String timestampFormatTimezoneId, String timestampAttributeName) {
+            String timestampFormatTimezoneId, String timestampAttributeName) {
         String formattedTimestamp;
         if (timestampFormat == null || timestamp < 0) {
             formattedTimestamp = String.valueOf(timestamp);

powertools-logging/powertools-logging-logback/src/test/java/software/amazon/lambda/powertools/logging/internal/LambdaJsonEncoderTest.java

@@ -29,6 +29,8 @@
 import com.amazonaws.services.lambda.runtime.Context;
 import com.amazonaws.services.lambda.runtime.events.SQSEvent;
 import com.fasterxml.jackson.databind.ObjectMapper;
+import com.fasterxml.jackson.databind.util.JSONPObject;
+
 import java.io.ByteArrayInputStream;
 import java.io.ByteArrayOutputStream;
 import java.io.File;
@@ -126,6 +128,13 @@ void shouldLogArgumentsAsJsonWhenUsingRawJson() {
                 .contains("\"input\":{\"awsRegion\":\"eu-west-1\",\"body\":\"plop\",\"eventSource\":\"eb\",\"messageAttributes\":{\"keyAttribute\":{\"stringListValues\":[\"val1\",\"val2\",\"val3\"]}},\"messageId\":\"1212abcd\"}")
                 .contains("\"message\":\"1212abcd\"")
                 .contains("\"message\":\"Message body = plop and id = \"1212abcd\"\"");
+        // Reserved keys should be ignored
+        PowertoolsLoggedFields.stringValues().stream().forEach(reservedKey -> {
+            assertThat(contentOf(logFile)).doesNotContain("\"" + reservedKey + "\":\"shouldBeIgnored\"");
+            assertThat(contentOf(logFile)).contains(
+                    "\"message\":\"Attempted to use reserved key '" + reservedKey
+                            + "' in structured argument. This key will be ignored.\"");
+        });
     }
 
     @Test
@@ -150,6 +159,13 @@ void shouldLogArgumentsAsJsonWhenUsingKeyValue() {
                 .contains("\"input\":{\"awsRegion\":\"eu-west-1\",\"body\":\"plop\",\"eventSource\":\"eb\",\"messageAttributes\":{\"keyAttribute\":{\"stringListValues\":[\"val1\",\"val2\",\"val3\"]}},\"messageId\":\"1212abcd\"}")
                 .contains("\"message\":\"1212abcd\"")
                 .contains("\"message\":\"Message body = plop and id = \"1212abcd\"\"");
+        // Reserved keys should be ignored
+        PowertoolsLoggedFields.stringValues().stream().forEach(reservedKey -> {
+            assertThat(contentOf(logFile)).doesNotContain("\"" + reservedKey + "\":\"shouldBeIgnored\"");
+            assertThat(contentOf(logFile)).contains(
+                    "\"message\":\"Attempted to use reserved key '" + reservedKey
+                            + "' in structured argument. This key will be ignored.\"");
+        });
     }
 
     private final LoggingEvent loggingEvent = new LoggingEvent("fqcn", logger, Level.INFO, "message", null, null);

powertools-logging/powertools-logging-logback/src/test/java/software/amazon/lambda/powertools/logging/internal/handler/PowertoolsArguments.java

@@ -16,15 +16,21 @@
 
 import static software.amazon.lambda.powertools.logging.internal.PowertoolsLoggedFields.CORRELATION_ID;
 
+import java.util.HashMap;
+import java.util.Map;
+
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.slf4j.MDC;
+
 import com.amazonaws.services.lambda.runtime.Context;
 import com.amazonaws.services.lambda.runtime.RequestHandler;
 import com.amazonaws.services.lambda.runtime.events.SQSEvent;
 import com.fasterxml.jackson.core.JsonProcessingException;
-import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
-import org.slf4j.MDC;
+
 import software.amazon.lambda.powertools.logging.Logging;
 import software.amazon.lambda.powertools.logging.argument.StructuredArguments;
+import software.amazon.lambda.powertools.logging.internal.PowertoolsLoggedFields;
 import software.amazon.lambda.powertools.utilities.JsonConfig;
 
 public class PowertoolsArguments implements RequestHandler<SQSEvent.SQSMessage, String> {
@@ -41,11 +47,27 @@ public String handleRequest(SQSEvent.SQSMessage input, Context context) {
         try {
             MDC.put(CORRELATION_ID.getName(), input.getMessageId());
             if (argumentFormat == ArgumentFormat.JSON) {
-                LOG.debug("SQS Event", StructuredArguments.json("input",
-                        JsonConfig.get().getObjectMapper().writeValueAsString(input)));
+                LOG.debug("SQS Event",
+                        StructuredArguments.json("input",
+                                JsonConfig.get().getObjectMapper().writeValueAsString(input)),
+                        // function_name is a reserved key by PowertoolsLoggedFields and should be omitted
+                        StructuredArguments.entry("function_name", "shouldBeIgnored"));
             } else {
-                LOG.debug("SQS Event", StructuredArguments.entry("input", input));
+                LOG.debug("SQS Event",
+                        StructuredArguments.entry("input", input),
+                        // function_name is a reserved key by PowertoolsLoggedFields and should be omitted
+                        StructuredArguments.entry("function_name", "shouldBeIgnored"));
+            }
+
+            // Attempt logging all reserved keys, the values should not be overwritten by "shouldBeIgnored"
+            final Map<String, String> reservedKeysMap = new HashMap<>();
+            for (String field : PowertoolsLoggedFields.stringValues()) {
+                reservedKeysMap.put(field, "shouldBeIgnored");
             }
+            reservedKeysMap.put("message", "shouldBeIgnored");
+            reservedKeysMap.put("level", "shouldBeIgnored");
+            reservedKeysMap.put("timestamp", "shouldBeIgnored");
+            LOG.debug("Reserved keys", StructuredArguments.entries(reservedKeysMap));
             LOG.debug("{}", input.getMessageId());
             LOG.warn("Message body = {} and id = \"{}\"", input.getBody(), input.getMessageId());
         } catch (JsonProcessingException e) {

powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/argument/ArrayArgument.java

@@ -15,12 +15,13 @@
 package software.amazon.lambda.powertools.logging.argument;
 
 import java.util.Objects;
+
 import software.amazon.lambda.powertools.logging.internal.JsonSerializer;
 
 /**
  * See {@link StructuredArguments#array(String, Object...)}
  */
-public class ArrayArgument implements StructuredArgument {
+class ArrayArgument implements StructuredArgument {
     private final String key;
     private final Object[] values;
 
@@ -40,4 +41,5 @@ public void writeTo(JsonSerializer serializer) {
     public String toString() {
         return key + "=" + StructuredArguments.toString(values);
     }
+
 }

powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/argument/JsonArgument.java

@@ -15,12 +15,13 @@
 package software.amazon.lambda.powertools.logging.argument;
 
 import java.util.Objects;
+
 import software.amazon.lambda.powertools.logging.internal.JsonSerializer;
 
 /**
  * See {@link StructuredArguments#json(String, String)}
  */
-public class JsonArgument implements StructuredArgument {
+class JsonArgument implements StructuredArgument {
     private final String key;
     private final String rawJson;
 
@@ -39,4 +40,5 @@ public void writeTo(JsonSerializer serializer) {
     public String toString() {
         return key + "=" + rawJson;
     }
+
 }

powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/argument/KeyValueArgument.java

@@ -15,12 +15,13 @@
 package software.amazon.lambda.powertools.logging.argument;
 
 import java.util.Objects;
+
 import software.amazon.lambda.powertools.logging.internal.JsonSerializer;
 
 /**
  * See {@link StructuredArguments#entry(String, Object)}
  */
-public class KeyValueArgument implements StructuredArgument {
+class KeyValueArgument implements StructuredArgument {
     private final String key;
     private final Object value;