Java: Collapsing multiline stack traces into a single log event using Spring backed by Logback or Log4j2

The two most common logging implementations used in conjunction with Spring/Spring Boot are Logback and Log4j2.

In the recent past, a developer had a great deal of discretion on the format and files used for logging. But in the modern world of container deployment and scale, these logs typically feed enterprise logging solutions which requires some level of standardization.

And one of the biggest problems is that Java exceptions typically lead to a large multi-line stack trace in the logs. And now instead of a single log event indicating an exception, you have 100+ distinct log events (one for every line of the stack trace) interleaved among all the other log events coming in from other services and service instances.

In this article, I will show you how to configure a Spring Boot application to collapse exceptions into a single line for both Logback and Log4j2. This allows your logging solution to treat an exception and its stack trace as a single log event.

Spring Music application

In this article, I’ll use a customized version of the spring-music application to demonstrate the logging customizations required for Logback and Log4j2.

We need to ensure we can build it from source. The project requires Java8, so the first step is to install Java8 on our Ubuntu host.

$ sudo add-apt-repository ppa:openjdk-r/ppa -y
$ sudo apt-get update
$ sudo apt-cache policy openjdk-8-jdk
$ sudo apt-get install openjdk-8-jdk -y
$ sudo update-alternatives --config java
$ sudo update-alternatives --config javac

$ /usr/bin/java -version
openjdk version "1.8.0_141"
OpenJDK Runtime Environment (build 1.8.0_141-8u141-b15-3~14.04-b15)
OpenJDK 64-Bit Server VM (build 25.141-b15, mixed mode)

Then we grab the source code of the project from github and assemble it using the included gradle scripts:

$ sudo apt-get install git -y
$ git clone https://github.com/fabianlee/spring-music.git
$ cd spring-music
$ ./gradlew clean assemble

...
BUILD SUCCESSFUL

Folding multiline exceptions using Logback

Go ahead and build the project jar with a Logback logging implementation with the standard gradle command:

$ ./gradlew clean assemble
...
BUILD SUCCESSFUL

The “build/libs/spring-music.jar” is self executing and has an embedded Tomcat that binds to localhost:8080. Invoke the jar using:

$ java -jar build/libs/spring-music.jar

Calling up http://localhost:8080 with a browser will then show you the Albums listing page, and you will see a log line output to the console that looks similar to below:

2018-03-09T23:08:54.871+0000 DEBUG http-nio-8080-exec-10 o.c.s.m.w.AlbumController:26 [log_framework=logback;app_name=spring-music;app_version=1.0;instance_id=0] Getting all albums at DEBUG level MULTIEXCEPTION

This log line syntax is defined in “src/main/resources/logback-spring.xml” using the custom pattern:

%date{"yyyy-MM-dd'T'HH:mm:ss.SSSZ", UTC} %5p %t %c{5}:%L [log_framework=logback;app_name=${APP_NAME};app_version=${APP_VERSION};instance_id=${CF_INSTANCE_INDEX}] %m MULTIEXCEPTION %replace(%xException){'\n','\u2028'}%nopex%n

The ${…} variables are pulled in from application.properties and system properties (which can be viewed at http://localhost:8080/env). But the part we really want to call out is the part right after the message (%m).

MULTIEXCEPTION %replace(%xException){'\n','\u2028'}%nopex%n

The word ‘MULTIEXCEPTION’ has no special meaning, it is just a unique string marker of our choosing that allows us to know where the message (%m) ends and the exception begins. You could leave this marker out if you want.

But after that, instead of simply inserting the %xException placeholder (which would output a large stack trace with newline characters), we surround it with the %replace function, and have it replace all the newline characters with “\u2028” which is the Unicode representation of a line separator.

With the “\n” characters removed from the stack trace, the stack trace will now all be sent as a single line. To prove this, go to http://localhost:8080/errors/throw which has the ErrorController intentionally throw a NullPointerException using the following code:

Exception npe = new NullPointerException("Forcing an exception to be thrown");
logger.error("Forcing an exception to be thrown and sent to logging framework",npe);

This generates the log line below to the console.

2018-03-09T23:09:06.483+0000 ERROR http-nio-8080-exec-9 o.c.s.m.w.ErrorController:23 [app_name=spring-music;app_version=1.0;instance_id=0] Forcing an exception to be thrown and sent to logging framework MULTIEXCEPTION java.lang.NullPointerException: Forcing an exception to be thrownu2028 at org.cloudfoundry.samples.music.web.ErrorController.throwException(ErrorController.java:22)u2028...

Where you can see that ‘u2028’ is separating what used to be line feeds in the stack trace. Now the exception message and stack trace will be sent as a single unit.

Folding multiline exceptions using Log4j2

In order to override the default build script and use Log4j2 as the backing implementation for this project, have gradle use the “build-log4j2.gradle” file.

$ ./gradlew clean assemble -b build-log4j2.gradle
...
BUILD SUCCESSFUL

The “build/libs/spring-music.jar” is self executing and has an embedded Tomcat that binds to localhost:8080. Invoke the jar using:

$ java -jar build/libs/spring-music.jar

Calling up http://localhost:8080 with a browser will then show you the Albums listing page, and you will see a log line output to the console that looks similar to below:

2018-03-09T23:24:54.338+0000 DEBUG http-nio-8080-exec-1 org.cloud.sampl.music.web.AlbumController:26 [log_framework=log4j2;app_name=spring-music;app_version=1.0;instance_id=${env:INSTANCE_INDEX}] Getting all albums at DEBUG level MULTIEXCEPTION

This log line syntax is defined in “src/main/resources/log4j2.xml” using the custom pattern:

%date{yyyy-MM-dd'T'HH:mm:ss.SSSZ}{UTC} %5p %t %c{5.}:%L [log_framework=log4j2;app_name=${APP_NAME};app_version=${APP_VERSION};instance_id=${CF_INSTANCE_INDEX}] %m MULTIEXCEPTION %replace{%rException}{\n}{\u2028}%n

MULTIEXCEPTION %replace{%rException}{\n}{\u2028}

But after that, instead of simply inserting the %rException placeholder (which would output a large stack trace with newline characters), we send the value through the %replace function, and have it replace all the newline characters with “\u2028” which is the Unicode representation of a line separator.

Exception npe = new NullPointerException("Forcing an exception to be thrown");
logger.error("Forcing an exception to be thrown and sent to logging framework",npe);

This generates the log line below to the console.

2018-03-09T23:29:04.857+0000 ERROR http-nio-8080-exec-10 org.cloud.sampl.music.web.ErrorController:23 [log_framework=log4j2;app_name=spring-music;app_version=1.0;instance_id=${env:INSTANCE_INDEX}] Forcing an exception to be thrown and sent to logging framework MULTIEXCEPTION java.lang.NullPointerException: Forcing an exception to be thrownu2028 at org.cloudfoundry.samples.music.web.ErrorController.throwException(ErrorController.java:22) [classes!/:?]u2028

Where you can see that ‘u2028’ is separating what used to be line feeds in the stack trace. Now the exception message and stack trace will be sent as a single unit.

Summary

Folding a multi-line Java stack trace into a single line means that it can be treated as a single unit by a centralized logging solution.

There is no reason to expend computing and human resources reconstructing a stack trace on the destination side with correlation ids, large stack sizes, heavy cpu utilization, and clever parsing when it is much more efficient to do this folding on the source side.

The Unicode character can always be replaced on the log collection side (e.g. Logstash) to format the message as originally formatted.

REFERENCES

https://docs.cloudfoundry.org/loggregator/architecture.html#metron (CF logging arch)

http://docs.pivotal.io/pivotalcf/2-0/devguide/deploy-apps/streaming-logs.html#format (streaming log types)

https://docs.pivotal.io/tiledev/2-0/nozzle.html#examples (log format for CF components =<${PRI}>${VERSION} ${TIMESTAMP} ${HOST_IP} ${APP_NAME} ${PROD_ID} ${MSG_ID} ${SD-ELEMENT-instance} ${MESSAGE})

http://grokconstructor.appspot.com/do/construction (online grok)

https://github.com/cloudfoundry/dropsonde-protocol (dropsonde protocol buffers)

https://logback.qos.ch/manual/layouts.html (logback layout formats)

https://www.elastic.co/guide/en/logstash/current/plugins-codecs-protobuf.html (logstash protobuf input)

https://github.com/cloudfoundry-community/firehose-to-syslog (nozzle that resolves app name, space UUID/name, org UUID/name)

http://schd.ws/hosted_files/cfsummit2016/f7/MonitoringCloudFoundry-LearningAboutTheFirehose.pdf (shows UDP and TCP portions of CF logging system)

https://github.com/cloudfoundry-community/logsearch-for-cloudfoundry (ELK stack for CF)

https://discuss.pivotal.io/hc/en-us/articles/223207207-Why-Loggregator-may-lose-logs (predicted loss for msgs/sec)

http://scottfrederick.cfapps.io/blog/2014/02/20/cloud-foundry-and-logstash (how to break apart syslog 5424 event)

https://logz.io/blog/cloud-foundry-elk-stack/ (breaking apart 5424 syslog, binding service, types of kibana graphs)

https://docs.cloudfoundry.org/loggregator/cli-plugin.html (CF CLI plugin for viewing firehost)

https://github.com/cloudfoundry/loggregator-release/blob/develop/docs/java-multi-line-work-around.md (logback workaround for multi-line exception)