Skip to content

Commit 374b38d

Browse files
phipagphipag
authored
fix(logging): Prevent accidental overwriting of reserved keys via structured arguments
* Ignore logging of reserved keys when passed as StructuredArgument. * Add error to reserved log keys. * Update docs with a warning about logging of reserved keys when using structured arguments. * Update docs with warning in MDC section as well. * Update product name in documentation. * Make StructuredArgument implementations package private. They should only be instantiated by factory StructuredArguments. * Make StructuredArgument interface public and remove package private dependency in LambdaLoggingAspectTest. * Move reserved key logic from logging implementation to StructuredArguments. * Remove .keys() method again from StructuredArgument interface. It is no longer needed now. * Update documentation warnings regarding logging of reserved keys.
1 parent 7b18029 commit 374b38d

File tree

15 files changed

+286
-69
lines changed

15 files changed

+286
-69
lines changed

‎docs/core/logging.md

+9
Original file line numberDiff line numberDiff line change
@@ -354,6 +354,9 @@ Your logs will always include the following keys in your structured logging:
354354
| **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"} |
355355
| **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"));`) |
356356

357+
???+ note
358+
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.
359+
357360
## Additional structured keys
358361

359362
### Logging Lambda context information
@@ -640,6 +643,9 @@ To append additional keys in your logs, you can use the `StructuredArguments` cl
640643
}
641644
```
642645

646+
???+ warning "Do not use reserved keys in `StructuredArguments`"
647+
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.
648+
643649
**Using MDC**
644650

645651
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
650656
???+ warning "Custom keys stored in the MDC are persisted across warm invocations"
651657
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).
652658

659+
???+ warning "Do not add reserved keys to MDC"
660+
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.
661+
653662

654663
### Removing additional keys
655664

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

+15-14
Original file line numberDiff line numberDiff line change
@@ -191,8 +191,8 @@ public void resolve(LogEvent logEvent, JsonWriter jsonWriter) {
191191
Object[] arguments = logEvent.getMessage().getParameters();
192192
if (arguments != null) {
193193
stream(arguments).filter(StructuredArgument.class::isInstance).forEach(argument -> {
194-
serializer.writeRaw(',');
195194
try {
195+
serializer.writeRaw(',');
196196
((StructuredArgument) argument).writeTo(serializer);
197197
} catch (IOException e) {
198198
System.err.printf("Failed to encode log event, error: %s.%n", e.getMessage());
@@ -204,19 +204,20 @@ public void resolve(LogEvent logEvent, JsonWriter jsonWriter) {
204204

205205
private final EventResolver internalResolver;
206206

207-
private static final Map<String, EventResolver> eventResolverMap = Collections.unmodifiableMap(Stream.of(new Object[][] {
208-
{ SERVICE.getName(), SERVICE_RESOLVER },
209-
{ FUNCTION_NAME.getName(), FUNCTION_NAME_RESOLVER },
210-
{ FUNCTION_VERSION.getName(), FUNCTION_VERSION_RESOLVER },
211-
{ FUNCTION_ARN.getName(), FUNCTION_ARN_RESOLVER },
212-
{ FUNCTION_MEMORY_SIZE.getName(), FUNCTION_MEMORY_RESOLVER },
213-
{ FUNCTION_REQUEST_ID.getName(), FUNCTION_REQ_RESOLVER },
214-
{ FUNCTION_COLD_START.getName(), COLD_START_RESOLVER },
215-
{ FUNCTION_TRACE_ID.getName(), XRAY_TRACE_RESOLVER },
216-
{ SAMPLING_RATE.getName(), SAMPLING_RATE_RESOLVER },
217-
{ "region", REGION_RESOLVER },
218-
{ "account_id", ACCOUNT_ID_RESOLVER }
219-
}).collect(Collectors.toMap(data -> (String) data[0], data -> (EventResolver) data[1])));
207+
private static final Map<String, EventResolver> eventResolverMap = Collections
208+
.unmodifiableMap(Stream.of(new Object[][] {
209+
{ SERVICE.getName(), SERVICE_RESOLVER },
210+
{ FUNCTION_NAME.getName(), FUNCTION_NAME_RESOLVER },
211+
{ FUNCTION_VERSION.getName(), FUNCTION_VERSION_RESOLVER },
212+
{ FUNCTION_ARN.getName(), FUNCTION_ARN_RESOLVER },
213+
{ FUNCTION_MEMORY_SIZE.getName(), FUNCTION_MEMORY_RESOLVER },
214+
{ FUNCTION_REQUEST_ID.getName(), FUNCTION_REQ_RESOLVER },
215+
{ FUNCTION_COLD_START.getName(), COLD_START_RESOLVER },
216+
{ FUNCTION_TRACE_ID.getName(), XRAY_TRACE_RESOLVER },
217+
{ SAMPLING_RATE.getName(), SAMPLING_RATE_RESOLVER },
218+
{ "region", REGION_RESOLVER },
219+
{ "account_id", ACCOUNT_ID_RESOLVER }
220+
}).collect(Collectors.toMap(data -> (String) data[0], data -> (EventResolver) data[1])));
220221

221222

222223
PowertoolsResolver(final TemplateResolverConfig config) {

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

+22-3
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,8 @@
3535
import org.junit.jupiter.api.Test;
3636
import org.mockito.Mock;
3737
import org.slf4j.MDC;
38+
39+
import software.amazon.lambda.powertools.logging.internal.PowertoolsLoggedFields;
3840
import software.amazon.lambda.powertools.logging.internal.handler.PowertoolsArguments;
3941

4042
@Order(2)
@@ -83,9 +85,17 @@ void shouldLogArgumentsAsJsonWhenUsingRawJson() {
8385
// THEN
8486
File logFile = new File("target/logfile.json");
8587
assertThat(contentOf(logFile))
86-
.contains("\"input\":{\"awsRegion\":\"eu-west-1\",\"body\":\"plop\",\"eventSource\":\"eb\",\"messageAttributes\":{\"keyAttribute\":{\"stringListValues\":[\"val1\",\"val2\",\"val3\"]}},\"messageId\":\"1212abcd\"}")
88+
.contains(
89+
"\"input\":{\"awsRegion\":\"eu-west-1\",\"body\":\"plop\",\"eventSource\":\"eb\",\"messageAttributes\":{\"keyAttribute\":{\"stringListValues\":[\"val1\",\"val2\",\"val3\"]}},\"messageId\":\"1212abcd\"}")
8790
.contains("\"message\":\"1212abcd\"")
8891
.contains("\"message\":\"Message body = plop and id = \\\"1212abcd\\\"\"");
92+
// Reserved keys should be ignored
93+
PowertoolsLoggedFields.stringValues().stream().forEach(reservedKey -> {
94+
assertThat(contentOf(logFile)).doesNotContain("\"" + reservedKey + "\":\"shouldBeIgnored\"");
95+
assertThat(contentOf(logFile)).contains(
96+
"\"message\":\"Attempted to use reserved key '" + reservedKey
97+
+ "' in structured argument. This key will be ignored.\"");
98+
});
8999
}
90100

91101
@Test
@@ -107,9 +117,18 @@ void shouldLogArgumentsAsJsonWhenUsingKeyValue() {
107117
// THEN
108118
File logFile = new File("target/logfile.json");
109119
assertThat(contentOf(logFile))
110-
.contains("\"input\":{\"awsRegion\":\"eu-west-1\",\"body\":\"plop\",\"eventSource\":\"eb\",\"messageAttributes\":{\"keyAttribute\":{\"stringListValues\":[\"val1\",\"val2\",\"val3\"]}},\"messageId\":\"1212abcd\"}")
120+
.contains(
121+
"\"input\":{\"awsRegion\":\"eu-west-1\",\"body\":\"plop\",\"eventSource\":\"eb\",\"messageAttributes\":{\"keyAttribute\":{\"stringListValues\":[\"val1\",\"val2\",\"val3\"]}},\"messageId\":\"1212abcd\"}")
111122
.contains("\"message\":\"1212abcd\"")
112123
.contains("\"message\":\"Message body = plop and id = \\\"1212abcd\\\"\"");
124+
125+
// Reserved keys should be ignored
126+
PowertoolsLoggedFields.stringValues().stream().forEach(reservedKey -> {
127+
assertThat(contentOf(logFile)).doesNotContain("\"" + reservedKey + "\":\"shouldBeIgnored\"");
128+
assertThat(contentOf(logFile)).contains(
129+
"\"message\":\"Attempted to use reserved key '" + reservedKey
130+
+ "' in structured argument. This key will be ignored.\"");
131+
});
113132
}
114133

115134
private void setupContext() {
@@ -119,4 +138,4 @@ private void setupContext() {
119138
when(context.getMemoryLimitInMB()).thenReturn(10);
120139
when(context.getAwsRequestId()).thenReturn("RequestId");
121140
}
122-
}
141+
}

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

+28-6
Original file line numberDiff line numberDiff line change
@@ -16,15 +16,21 @@
1616

1717
import static software.amazon.lambda.powertools.logging.internal.PowertoolsLoggedFields.CORRELATION_ID;
1818

19+
import java.util.HashMap;
20+
import java.util.Map;
21+
22+
import org.slf4j.Logger;
23+
import org.slf4j.LoggerFactory;
24+
import org.slf4j.MDC;
25+
1926
import com.amazonaws.services.lambda.runtime.Context;
2027
import com.amazonaws.services.lambda.runtime.RequestHandler;
2128
import com.amazonaws.services.lambda.runtime.events.SQSEvent;
2229
import com.fasterxml.jackson.core.JsonProcessingException;
23-
import org.slf4j.Logger;
24-
import org.slf4j.LoggerFactory;
25-
import org.slf4j.MDC;
30+
2631
import software.amazon.lambda.powertools.logging.Logging;
2732
import software.amazon.lambda.powertools.logging.argument.StructuredArguments;
33+
import software.amazon.lambda.powertools.logging.internal.PowertoolsLoggedFields;
2834
import software.amazon.lambda.powertools.utilities.JsonConfig;
2935

3036
public class PowertoolsArguments implements RequestHandler<SQSEvent.SQSMessage, String> {
@@ -41,11 +47,27 @@ public String handleRequest(SQSEvent.SQSMessage input, Context context) {
4147
try {
4248
MDC.put(CORRELATION_ID.getName(), input.getMessageId());
4349
if (argumentFormat == ArgumentFormat.JSON) {
44-
LOG.debug("SQS Event", StructuredArguments.json("input",
45-
JsonConfig.get().getObjectMapper().writeValueAsString(input)));
50+
LOG.debug("SQS Event",
51+
StructuredArguments.json("input",
52+
JsonConfig.get().getObjectMapper().writeValueAsString(input)),
53+
// function_name is a reserved key by PowertoolsLoggedFields and should be omitted
54+
StructuredArguments.entry("function_name", "shouldBeIgnored"));
4655
} else {
47-
LOG.debug("SQS Event", StructuredArguments.entry("input", input));
56+
LOG.debug("SQS Event",
57+
StructuredArguments.entry("input", input),
58+
// function_name is a reserved key by PowertoolsLoggedFields and should be omitted
59+
StructuredArguments.entry("function_name", "shouldBeIgnored"));
60+
}
61+
62+
// Attempt logging all reserved keys, the values should not be overwritten by "shouldBeIgnored"
63+
final Map<String, String> reservedKeysMap = new HashMap<>();
64+
for (String field : PowertoolsLoggedFields.stringValues()) {
65+
reservedKeysMap.put(field, "shouldBeIgnored");
4866
}
67+
reservedKeysMap.put("message", "shouldBeIgnored");
68+
reservedKeysMap.put("level", "shouldBeIgnored");
69+
reservedKeysMap.put("timestamp", "shouldBeIgnored");
70+
LOG.debug("Reserved keys", StructuredArguments.entries(reservedKeysMap));
4971
LOG.debug("{}", input.getMessageId());
5072
LOG.warn("Message body = {} and id = \"{}\"", input.getBody(), input.getMessageId());
5173
} catch (JsonProcessingException e) {

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

+2-1
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@
2222
import java.util.Map;
2323
import java.util.TimeZone;
2424
import java.util.TreeMap;
25+
2526
import software.amazon.lambda.powertools.logging.argument.StructuredArgument;
2627
import software.amazon.lambda.powertools.logging.internal.JsonSerializer;
2728
import software.amazon.lambda.powertools.logging.internal.PowertoolsLoggedFields;
@@ -36,7 +37,7 @@ private JsonUtils() {
3637
}
3738

3839
static void serializeTimestamp(JsonSerializer generator, long timestamp, String timestampFormat,
39-
String timestampFormatTimezoneId, String timestampAttributeName) {
40+
String timestampFormatTimezoneId, String timestampAttributeName) {
4041
String formattedTimestamp;
4142
if (timestampFormat == null || timestamp < 0) {
4243
formattedTimestamp = String.valueOf(timestamp);

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

+16
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,8 @@
2929
import com.amazonaws.services.lambda.runtime.Context;
3030
import com.amazonaws.services.lambda.runtime.events.SQSEvent;
3131
import com.fasterxml.jackson.databind.ObjectMapper;
32+
import com.fasterxml.jackson.databind.util.JSONPObject;
33+
3234
import java.io.ByteArrayInputStream;
3335
import java.io.ByteArrayOutputStream;
3436
import java.io.File;
@@ -126,6 +128,13 @@ void shouldLogArgumentsAsJsonWhenUsingRawJson() {
126128
.contains("\"input\":{\"awsRegion\":\"eu-west-1\",\"body\":\"plop\",\"eventSource\":\"eb\",\"messageAttributes\":{\"keyAttribute\":{\"stringListValues\":[\"val1\",\"val2\",\"val3\"]}},\"messageId\":\"1212abcd\"}")
127129
.contains("\"message\":\"1212abcd\"")
128130
.contains("\"message\":\"Message body = plop and id = \"1212abcd\"\"");
131+
// Reserved keys should be ignored
132+
PowertoolsLoggedFields.stringValues().stream().forEach(reservedKey -> {
133+
assertThat(contentOf(logFile)).doesNotContain("\"" + reservedKey + "\":\"shouldBeIgnored\"");
134+
assertThat(contentOf(logFile)).contains(
135+
"\"message\":\"Attempted to use reserved key '" + reservedKey
136+
+ "' in structured argument. This key will be ignored.\"");
137+
});
129138
}
130139

131140
@Test
@@ -150,6 +159,13 @@ void shouldLogArgumentsAsJsonWhenUsingKeyValue() {
150159
.contains("\"input\":{\"awsRegion\":\"eu-west-1\",\"body\":\"plop\",\"eventSource\":\"eb\",\"messageAttributes\":{\"keyAttribute\":{\"stringListValues\":[\"val1\",\"val2\",\"val3\"]}},\"messageId\":\"1212abcd\"}")
151160
.contains("\"message\":\"1212abcd\"")
152161
.contains("\"message\":\"Message body = plop and id = \"1212abcd\"\"");
162+
// Reserved keys should be ignored
163+
PowertoolsLoggedFields.stringValues().stream().forEach(reservedKey -> {
164+
assertThat(contentOf(logFile)).doesNotContain("\"" + reservedKey + "\":\"shouldBeIgnored\"");
165+
assertThat(contentOf(logFile)).contains(
166+
"\"message\":\"Attempted to use reserved key '" + reservedKey
167+
+ "' in structured argument. This key will be ignored.\"");
168+
});
153169
}
154170

155171
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

+28-6
Original file line numberDiff line numberDiff line change
@@ -16,15 +16,21 @@
1616

1717
import static software.amazon.lambda.powertools.logging.internal.PowertoolsLoggedFields.CORRELATION_ID;
1818

19+
import java.util.HashMap;
20+
import java.util.Map;
21+
22+
import org.slf4j.Logger;
23+
import org.slf4j.LoggerFactory;
24+
import org.slf4j.MDC;
25+
1926
import com.amazonaws.services.lambda.runtime.Context;
2027
import com.amazonaws.services.lambda.runtime.RequestHandler;
2128
import com.amazonaws.services.lambda.runtime.events.SQSEvent;
2229
import com.fasterxml.jackson.core.JsonProcessingException;
23-
import org.slf4j.Logger;
24-
import org.slf4j.LoggerFactory;
25-
import org.slf4j.MDC;
30+
2631
import software.amazon.lambda.powertools.logging.Logging;
2732
import software.amazon.lambda.powertools.logging.argument.StructuredArguments;
33+
import software.amazon.lambda.powertools.logging.internal.PowertoolsLoggedFields;
2834
import software.amazon.lambda.powertools.utilities.JsonConfig;
2935

3036
public class PowertoolsArguments implements RequestHandler<SQSEvent.SQSMessage, String> {
@@ -41,11 +47,27 @@ public String handleRequest(SQSEvent.SQSMessage input, Context context) {
4147
try {
4248
MDC.put(CORRELATION_ID.getName(), input.getMessageId());
4349
if (argumentFormat == ArgumentFormat.JSON) {
44-
LOG.debug("SQS Event", StructuredArguments.json("input",
45-
JsonConfig.get().getObjectMapper().writeValueAsString(input)));
50+
LOG.debug("SQS Event",
51+
StructuredArguments.json("input",
52+
JsonConfig.get().getObjectMapper().writeValueAsString(input)),
53+
// function_name is a reserved key by PowertoolsLoggedFields and should be omitted
54+
StructuredArguments.entry("function_name", "shouldBeIgnored"));
4655
} else {
47-
LOG.debug("SQS Event", StructuredArguments.entry("input", input));
56+
LOG.debug("SQS Event",
57+
StructuredArguments.entry("input", input),
58+
// function_name is a reserved key by PowertoolsLoggedFields and should be omitted
59+
StructuredArguments.entry("function_name", "shouldBeIgnored"));
60+
}
61+
62+
// Attempt logging all reserved keys, the values should not be overwritten by "shouldBeIgnored"
63+
final Map<String, String> reservedKeysMap = new HashMap<>();
64+
for (String field : PowertoolsLoggedFields.stringValues()) {
65+
reservedKeysMap.put(field, "shouldBeIgnored");
4866
}
67+
reservedKeysMap.put("message", "shouldBeIgnored");
68+
reservedKeysMap.put("level", "shouldBeIgnored");
69+
reservedKeysMap.put("timestamp", "shouldBeIgnored");
70+
LOG.debug("Reserved keys", StructuredArguments.entries(reservedKeysMap));
4971
LOG.debug("{}", input.getMessageId());
5072
LOG.warn("Message body = {} and id = \"{}\"", input.getBody(), input.getMessageId());
5173
} catch (JsonProcessingException e) {

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

+3-1
Original file line numberDiff line numberDiff line change
@@ -15,12 +15,13 @@
1515
package software.amazon.lambda.powertools.logging.argument;
1616

1717
import java.util.Objects;
18+
1819
import software.amazon.lambda.powertools.logging.internal.JsonSerializer;
1920

2021
/**
2122
* See {@link StructuredArguments#array(String, Object...)}
2223
*/
23-
public class ArrayArgument implements StructuredArgument {
24+
class ArrayArgument implements StructuredArgument {
2425
private final String key;
2526
private final Object[] values;
2627

@@ -40,4 +41,5 @@ public void writeTo(JsonSerializer serializer) {
4041
public String toString() {
4142
return key + "=" + StructuredArguments.toString(values);
4243
}
44+
4345
}

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

+3-1
Original file line numberDiff line numberDiff line change
@@ -15,12 +15,13 @@
1515
package software.amazon.lambda.powertools.logging.argument;
1616

1717
import java.util.Objects;
18+
1819
import software.amazon.lambda.powertools.logging.internal.JsonSerializer;
1920

2021
/**
2122
* See {@link StructuredArguments#json(String, String)}
2223
*/
23-
public class JsonArgument implements StructuredArgument {
24+
class JsonArgument implements StructuredArgument {
2425
private final String key;
2526
private final String rawJson;
2627

@@ -39,4 +40,5 @@ public void writeTo(JsonSerializer serializer) {
3940
public String toString() {
4041
return key + "=" + rawJson;
4142
}
43+
4244
}

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

+2-1
Original file line numberDiff line numberDiff line change
@@ -15,12 +15,13 @@
1515
package software.amazon.lambda.powertools.logging.argument;
1616

1717
import java.util.Objects;
18+
1819
import software.amazon.lambda.powertools.logging.internal.JsonSerializer;
1920

2021
/**
2122
* See {@link StructuredArguments#entry(String, Object)}
2223
*/
23-
public class KeyValueArgument implements StructuredArgument {
24+
class KeyValueArgument implements StructuredArgument {
2425
private final String key;
2526
private final Object value;
2627

0 commit comments

Comments
 (0)