AWS Lambda in Java 8, log4j2 and scattered stack trace in CloudWatch
Edit: works fine with lo4j2 appender, aws-lambda-java-log4j2 1.1.0 and aws-lambda-java-core 1.2.0.
TL;DR; It’s not that obvious how to get Java stack trace to be single CloudWatch entry — using log4j2 with custom Converter may be one way to go. Scroll down to point 4 for details.
Last week, I spent far too much time configuring logging for AWS Lambda functions in Java 8 so I’m writing this to (hopefully) save some time for the next person with similar troubles.
The issue: when logging stack trace to standard output with one of standard loggers, stack trace is nicely formatted with newlines. Unfortunately, CloudWatch treats every line of such formatted stack trace as a separate entry, which is unreadable and may become an issue if you then export your CloudWatch entries to another tool.
AWS in their documentation claims that the solution is using log4j2 — http://docs.aws.amazon.com/lambda/latest/dg/java-logging.html . In their code example (using log4j2), there is a note:
// Use log4j to log the same thing as above and AWS Lambda will log only one event in CloudWatch.logger.debug("log data from log4j debug \n this is continuation of log4j debug");
Unfortunately, I found that this doesn’t work, with only difference between my configuration and exemplary configuration being log4j transformer plugin. I used gradle plugin de.sebastianboegl.gradle.plugins:shadow-log4j-transformer:2.1.1 while AWS documentation uses maven plugin maven-shade-plugin.log4j2-cachefile-transformer. . I don’t think that makes a difference in case of stack trace (if I am wrong, please let me know), so I was left with a task of configuring log4j in a way that would not end up with stack trace split to separate entries.
After some googling I found out that a (bit tricky) way to achieve what we want is to replace ‘\n’ in stack trace with ‘\r’ — such messages are treated as one entry by Cloudwatch and and the same time displayed by Cloudwatch with newlines, and therefore easy to read.
That proved to be more difficult than I thought — here are some options that you may want to consider.
1. Write your custom logging service that will use ‘\r’ as separators
Covering log4j2 api with custom LoggingService implementation that would take care of formatting stack trace with ‘\r’ as a separator. At first, that seems like a great idea, because besides solving the problem with stack trace, you can also enforce conventions and choose which log4j2 api calls will be used (and there are lots of options). However, I stumbled upon a problem with varargs. Log4j logger’s api uses varargs heavily — when you use parametrized message as a first argument, you can then pass any number of objects to be printed in places where you left placeholders:
logger.info("This is {} important {} for all {}", "very", "info", "readers");The same goes for lambda expressions:
logger.info("This would be {} of {}", () -> "result", () -> someExpensiveOp());In my custom logging service, I attempted to pass lambda expressions to underlying log4j implementation:
class CustomLoggingService {
public void error(String msg, Supplier<?>… paramSuppliers) {
logger.error(msg, paramSuppliers);
}
}This ends with a compiler warning that it cannot decide if varargs or non-varargs call is desired. While conversion to Object[] or Object helps to get rid of this warning, supplied lambda expressions are no longer called. Instead, we see the results of calling toString() on passed Suppliers — and not on the results they supply — which is not what we want at all:
2017–10–31 19:47:10 ERROR Library:29 — Testing error logging com.testing.Library$$Lambda$21/1857815974@3cef309d com.testing.Library$$Lambda$22/1852584274@32709393 com.testing.Library$$Lambda$23/1354011814@3d99d22e2. Provide static helper method
Providing static method that should be called by programmers whenever they want to log a stack trace. That’s easy to understand and implement, but programmers need to remember to call it each time they want to log an exception — really not ideal.
3. Change line separator or use replace from log4j2 PatternLayout
For a moment I hoped for an elegant solution. See https://logging.apache.org/log4j/2.x/manual/layouts.html#PatternLayout.
In your log4j configuration, you have an option to disable automatic exception logging. If you do so, you can then include %exception or %throwable in your logging pattern. The default value of either of those is a stack trace log. When you do so, you have two options — you can either set a line separator or you can use a replacement:
The problem is that both those approaches write exactly the literal ‘\r’ to the logs and not CR, which we want. If you are fine with replacing ‘\n’ with space (or any other character that is not special) and you don’t mind losing formatting that’s the quickest (and quite clean) thing you can do.
4. Create custom log4j2 converter.
Log4j allows for creating custom converters by extending LogEventPatternConverter class.
After registering them in log4j configuration, we can use them in place of those provided.
That works, and is transparent for programmers, though I really don’t like the constructor ignoring options parameter — need to figure out how to write this one correctly.
