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

docs/core/logging.md

@@ -640,6 +640,9 @@ To append additional keys in your logs, you can use the `StructuredArguments` cl
             }
         ```
 
+???+ warning "Do not use arguments with reserved keys"
+    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 whole argument will be ignored. 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 +653,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 Powertools. Unlike with StructuredArguments, Powertools 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

@@ -27,7 +27,9 @@
 
 import java.io.IOException;
 import java.util.Collections;
+import java.util.List;
 import java.util.Map;
+import java.util.Set;
 import java.util.stream.Collectors;
 import java.util.stream.Stream;
 import org.apache.logging.log4j.core.LogEvent;
@@ -45,6 +47,10 @@
  * to be able to recognize powertools fields in the LambdaJsonLayout.json file.
  */
 final class PowertoolsResolver implements EventResolver {
+    private static final Set<String> RESERVED_LOG_KEYS = Stream
+            .concat(PowertoolsLoggedFields.stringValues().stream(),
+                    List.of("message", "level", "timestamp", "error").stream())
+            .collect(Collectors.toSet());
 
     private static final EventResolver COLD_START_RESOLVER = new EventResolver() {
         @Override
@@ -191,9 +197,17 @@ 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 {
-                                ((StructuredArgument) argument).writeTo(serializer);
+                                final StructuredArgument structArg = (StructuredArgument) argument;
+                                final Iterable<String> logKeys = structArg.keys();
+                                // If any of the logKeys are a reserved key we are going to ignore the argument
+                                for (final String logKey : logKeys) {
+                                    if (RESERVED_LOG_KEYS.contains(logKey)) {
+                                        return;
+                                    }
+                                }
+                                serializer.writeRaw(',');
+                                structArg.writeTo(serializer);
                             } catch (IOException e) {
                                 System.err.printf("Failed to encode log event, error: %s.%n", e.getMessage());
                             }

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,14 @@ 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\"");
+        });
     }
 
     @Test
@@ -107,9 +114,15 @@ 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\"");
+        });
     }
 
     private void setupContext() {
@@ -119,4 +132,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

@@ -19,9 +19,14 @@
 import java.text.DateFormat;
 import java.text.SimpleDateFormat;
 import java.util.Date;
+import java.util.List;
 import java.util.Map;
+import java.util.Set;
 import java.util.TimeZone;
 import java.util.TreeMap;
+import java.util.stream.Collectors;
+import java.util.stream.Stream;
+
 import software.amazon.lambda.powertools.logging.argument.StructuredArgument;
 import software.amazon.lambda.powertools.logging.internal.JsonSerializer;
 import software.amazon.lambda.powertools.logging.internal.PowertoolsLoggedFields;
@@ -30,13 +35,17 @@
  * Json tools to serialize common fields
  */
 final class JsonUtils {
+    private static final Set<String> RESERVED_LOG_KEYS = Stream
+            .concat(PowertoolsLoggedFields.stringValues().stream(),
+                    List.of("message", "level", "timestamp", "error").stream())
+            .collect(Collectors.toSet());
 
     private JsonUtils() {
         // static utils
     }
 
     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);
@@ -77,8 +86,16 @@ static void serializeArguments(ILoggingEvent event, JsonSerializer serializer) t
         if (arguments != null) {
             for (Object argument : arguments) {
                 if (argument instanceof StructuredArgument) {
+                    final StructuredArgument structArg = (StructuredArgument) argument;
+                    final Iterable<String> logKeys = structArg.keys();
+                    // If any of the logKeys are a reserved key we are going to ignore the argument
+                    for (final String logKey : logKeys) {
+                        if (RESERVED_LOG_KEYS.contains(logKey)) {
+                            return;
+                        }
+                    }
                     serializer.writeRaw(',');
-                    ((StructuredArgument) argument).writeTo(serializer);
+                    structArg.writeTo(serializer);
                 }
             }
         }

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,10 @@ 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\"");
+        });
     }
 
     @Test
@@ -150,6 +156,10 @@ 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\"");
+        });
     }
 
     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,6 +15,8 @@
 package software.amazon.lambda.powertools.logging.argument;
 
 import java.util.Objects;
+import java.util.Set;
+
 import software.amazon.lambda.powertools.logging.internal.JsonSerializer;
 
 /**
@@ -40,4 +42,9 @@ public void writeTo(JsonSerializer serializer) {
     public String toString() {
         return key + "=" + StructuredArguments.toString(values);
     }
+
+    @Override
+    public Iterable<String> keys() {
+        return Set.of(key);
+    }
 }

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

@@ -15,6 +15,8 @@
 package software.amazon.lambda.powertools.logging.argument;
 
 import java.util.Objects;
+import java.util.Set;
+
 import software.amazon.lambda.powertools.logging.internal.JsonSerializer;
 
 /**
@@ -39,4 +41,9 @@ public void writeTo(JsonSerializer serializer) {
     public String toString() {
         return key + "=" + rawJson;
     }
+
+    @Override
+    public Iterable<String> keys() {
+        return Set.of(key);
+    }
 }

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

@@ -15,6 +15,8 @@
 package software.amazon.lambda.powertools.logging.argument;
 
 import java.util.Objects;
+import java.util.Set;
+
 import software.amazon.lambda.powertools.logging.internal.JsonSerializer;
 
 /**
@@ -39,6 +41,11 @@ public String toString() {
         return key + "=" + StructuredArguments.toString(value);
     }
 
+    @Override
+    public Iterable<String> keys() {
+        return Set.of(getKey());
+    }
+
     public String getKey() {
         return key;
     }