fix(logging): Prevent accidental overwriting of reserved keys via structured arguments #1822
Conversation
💾 Artifacts Size Report
|
There was a problem hiding this comment.
Left a couple of comments on the documentation, one of which needs attention.
Regarding the implementation, two comments:
- in TS and I think other runtimes, we are emitting a warning when we ignore a key to let the customer know there's been data loss - see here. Was this omission intentional?
- I don't know the implementation good enough to answer this question without running the Logger, so I'll ask: if I add a reserved key via the
appendKey()method, is it being correctly ignored?
Finally, could you look at the SonarQubeCloud findings and either address them or mark them as false positives?
Yes, it was intentional because I didn't want to spam the user's logs with warning messages on each log emission where this happens. If you have a strong opinion on adding a warning I can do so. I believe in .NET there is a warning in the documentation only – similar to what I propose here.
The You can check the Preview Documentation to see the Logging v2 docs where To answer your question "is it being correctly ignored?": Unfortunately not and this is why I added the warning in the documentation that unlike with StructuredArguments MDC will not be ignored. The reason for this is a bit technical (see this issue message). Within the Logger utility we are using This comes down to the tradeoff between using Java standards vs. custom interfaces / implementations. The value proposition of MDC is that it will automatically work for new users onboarding with Powertools for AWS because there is a high chance they are already using MDC for their logs before adopting Powertools for AWS. |
Correct, we do not log any warning to user. |
|
Thanks for the explanations. As a customer, if I am emitting a log with a key and that key is dropped, I would want to know. Putting myself 8000 in the shoes of an operator, having a warning that tells me this has happened helps me understand. The opposite means: 1/ I see a missing key from my logs when I needed it, 2/ I think there's an issue with my code, 3/ I spend time troubleshooting, 4/ maybe, after a long while, I understand this is because of a Powertools specific behavior, 5/ I'm now frustrated because I wasted time. Since we are saying we're excluding MDC from this logic (more on this in a sec), then we'd not be spamming the customer since the warning would be local to a specific log entry (aka it's emitted once). Besides, warnings are subject to log level, so I could silence them if I really don't want them. Alternatively, we could also have a "warn once" logic that emits a warning at most once whenever a key filtering action happens the first time. This way we still inform the customer, but keep warnings at minimum. This is still a better option than saying nothing in my opinion. Regarding MDC, this is again a limitation of knowledge in the language/ecosystem, but does this code (from the docs) add the keys to that one specific log entry, or does it add to all the subsequent ones? import static software.amazon.lambda.powertools.logging.argument.StructuredArguments.entry;
import static software.amazon.lambda.powertools.logging.argument.StructuredArguments.entries;
public class PaymentFunction implements RequestHandler<APIGatewayProxyRequestEvent, APIGatewayProxyResponseEvent> {
private static final Logger LOGGER = LoggerFactory.getLogger(AppLogResponse.class);
@Logging
public APIGatewayProxyResponseEvent handleRequest(final APIGatewayProxyRequestEvent input, final Context context) {
// ...
LOGGER.info("Collecting payment", entry("orderId", order.getId()));
// ...
Map<String, String> customKeys = new HashMap<>();
customKeys.put("paymentId", payment.getId());
customKeys.put("amount", payment.getAmount);
LOGGER.info("Payment successful", entries(customKeys));
}
} |
This code will add the keys only to those specific log entries (this is what I refer to as StructuredArguments). If you want to add keys to all log entries you can do this – and this is where we can't prevent users from adding reserved keys: public class CreditCardFunction implements RequestHandler<APIGatewayProxyRequestEvent, APIGatewayProxyResponseEvent> {
private static final Logger LOGGER = LoggerFactory.getLogger(CreditCardFunction.class);
@Logging(clearState = true)
public APIGatewayProxyResponseEvent handleRequest(final APIGatewayProxyRequestEvent input, final Context context) {
// This will be attached to each log
MDC.put("cardNumber", card.getId());
LOGGER.info("Updating card information");
// ...
}
}
This is a strong argument, I can send an update emitting a warning log. |
…ependency in LambdaLoggingAspectTest.
…no longer needed now.
|
|
Hey @hjgraca and @dreamorosi, thank you again for your comments. I sent an update addressing your comments. While working on this I also improved the implementation by moving the reserved key logic out of the respective log4j/logback implementation to the I also deployed a preview of the documentation here to avoid any confusion: https://dealn7fl31ram.cloudfront.net/ Let me summarize the current behavior with an example:
|
Issue #, if available: #1759
Description of changes:
This PR fixes two problems for both the logback logging module as well as the log4j logging module:
message,level, Lambda context information, etc.MapArgumentwhere JSON serialization was missing a comma if the map contained multiple root-level keys.Note: In addition to unit tests, I ran E2E tests as well. Until E2E tests are restored in GitHub workflows, here is the output from running in my AWS account.
Checklist