Java: collapse multi-line logs into a single-line log using Spirng and Logback or Log4j2 logger
Spring Music is an application for using the Cloud Foundry environment database service in conjunction with the Spring Framework and Spring Boot. It was created to store the same domain objects in one of many different repositories – object-relational, document-oriented or distributed (key-value store).
The two most common loggers that are used with Spring / Spring Boot are Logback and Log4j2. Until recently, the developer had more freedom of action regarding the format of the logs and the files themselves used for logging. However, in the modern world of container implementation and scaling, logging usually offers corporate solutions that require a certain level of standardization.
One of the biggest problems is that Java exceptions usually result in a large multi-line stack trace in the logs. Because of this, instead of a single log event indicating an exception, or an error message, you get more than 100 different logs, one for each line of the stack trace, interspersed with other log events from other services or service instances.
This article describes how to configure the Spring Boot application to collapse exceptions on a single line for both the Logback logger and Log4j2. This allows us to consider exception logging and stack tracing as one event log.
Error and Exception classes in JAVA
JAVA Checked and Unchecked Unchecked Exception Exceptions
Spring Music App
In this article, for specialized logging, a custom version of the spring-music application is used, which is necessary for the operation of the Logback and Log4j2 loggers. First you need to make sure that we can recreate it from the source. The project requires Java8, so the first step is to install Java8 on your Ubuntu host.
Then we take the source code of the project with github and create the assembly using the built-in scripts of the Gradle build system:
Collapse multiline exceptions using Logback
Let's move on and create a jar archive of the jar project with the implementation of the Logback logger using the standard Gradle command:
The file “build / libs / spring-music.jar” is self-executing and contains a built-in Tomcat that is bound to localhost: 8080. The jar file is called using the command:
Calling http: // localhost: 8080 in the browser will show you a page with a list of Albums, and the log line that looks like this will be displayed in the console:
This log line syntax is defined in “src / main / resources / logback-spring.xml” using a custom template:
The variables $ {…} are extracted from application.properties and system properties, which can be viewed on the page at http: // localhost: 8080 / env. However, the part of the code we need is located immediately after the message (% m).
The word ‘MULTIEXCEPTION’ doesn't really matter, it's just a unique string marker that lets us know where the message ends (% m) and the exception starts. If you want, you can leave this marker.
Further, instead of just inserting a% xException placeholder that would throw a large stack trace with newline characters, we convert the value using the% replace function and replace all newline characters with the expression “ u2028”, which is a Unicode string delimiter view .
Removing the characters " n" from the stack trace means that now the stack trace will now be sent in single-line form. To prove this, go to http: // localhost: 8080 / errors / throw, where there is an Error Controller that intentionally throws a NullPointerException using the following code:
This creates a log line in the console, shown below:
Here you can see that the expression “u2028” separates what used to be a newline in the stack trace. Now the exception message and the stack trace will be sent as a unit.
Collapse multi-line exceptions using Log4j2
To override the default build script and use Log4j2 as the backup implementation of this project, you need to use the “build-log4j2.gradle” file.
The file “build / libs / spring-music.jar” is self-executing and uses the built-in Tomcat, which is bound to localhost: 8080. As in the previous example, the jar file is called using the command:
Calling http: // localhost: 8080 using a browser will display a page with a list of Albums with the output of the log line to the console, which looks like this:
This log line syntax is defined in “src / main / resources / log4j2.xml” using a custom template:
The variables $ {…} are extracted from application.properties and system properties, which can be viewed on the page at http: // localhost: 8080 / env. However, the part of the code we need is located immediately after the message (% m).
The word ‘MULTIEXCEPTION’ has no special meaning, it’s just a unique line marker of our choice, which allows you to find out where the message ends (% m) and the exception begins. If you want, you can leave it.
But after that, instead of just inserting a% xException placeholder that would throw a large stack trace with newline characters, we convert the value with the% replace function, which replaces all newline characters with the expression “ u2028”, which is a string delimiter view Unicode
Removing the characters " n" from the stack trace means that now the stack trace will now be sent as a single line. To prove this, go to http: // localhost: 8080 / errors / throw, where there is an Error Controller that intentionally throws a NullPointerException using the following code:
This creates a log line in the console, shown below:
As you can see, here the expression “u2028” separates what used to be a line feed in the stack trace. Now the exception message and the stack trace will be sent as a unit.
conclusions
The ability to collapse the multi-line trace of the Java stack into one line means that this technique can be considered as a single centralized logging solution.
There is no reason to waste computational and human resources on restoring the stack trace on the destination side using correlation identifiers, large stack sizes, high processor utilization, and smart parsing if it is much more efficient to perform this folding on the source side.
In this case, the Unicode character can always be replaced on the side of collecting logs (for example, on the side of the pipeline for collecting, filtering and normalizing Logstash logs) to restore the message in its original format.
Reference material
- https://docs.cloudfoundry.org/loggregator/architecture.html#metron (CF logging architecture)
docs.pivotal.io/pivotalcf/2-0/devguide/deploy-apps/streaming-logs.html#format (types of stream logs) - 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 version of Grok templates)
- https://github.com/cloudfoundry/dropsonde-protocol (Cloud Foundry Dropsonde Protocol for Structured Data Serialization)
- https://logback.qos.ch/manual/layouts.html (formats of components for converting an incoming message to a string)
- https://www.elastic.co/guide/en/logstash/current/plugins-codecs-protobuf.html (logstash protobuf input)
- https://github.com/cloudfoundry-community/firehose-to-syslog (sending firehose events from Cloud Foundry to the syslog)
- http://schd.ws/hosted_files/cfsummit2016/f7/MonitoringCloudFoundry-LearningAboutTheFirehose.pdf (display of parts of UDP and TCP CF logging systems)
- 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 (loss forecasting for msgs / sec)
- http://scottfrederick.cfapps.io/blog/2014/02/20/cloud-foundry-and-logstash (how to split the syslog 5424 event into parts)
- https://logz.io/blog/cloud-foundry-elk-stack/ (separation into 5424 syslog, a built-in service such as a platform for visualizing and analyzing Kibana data)
- https://docs.cloudfoundry.org/loggregator/cli-plugin.html (CF CLI plug-in for viewing firehost)
- https://github.com/cloudfoundry/loggregator-release/blob/develop/docs/java-multi-line-work-around.md (logback bypass for multi-line exception)
- https://stackoverflow.com/questions/23096129/make-logback-include-the-t-between-date-and-time-in-its-date-format-for-str (logback date and time format)
- http://cloud.rohitkelapure.com/2016/06/multi-line-java-stack-traces-out-of.html (logback string format for exception folding)
- https://discuss.elastic.co/t/match-and-replace-unicode-characters/56656 (the idea of using Ruby to replace Unicode in cases when Mutate does not work)
- https://www.diycode.cc/projects/cloudfoundry/loggregator (logging and BOSH manifest)
- https://www.elastic.co/guide/en/logstash/5.0/breaking-changes.html (critical change event.get () for Ruby)
- https://medium.com/@martatatiana/aws-lambda-in-java-8-log4j2-and-scattered-stacktrace-in-cloudwatch-a4aea2e7bf2a (LogEventPatternConverter – custom log4j2 logger converter)
- https://springframework.guru/using-log4j-2-spring-boot/ (using log4j2 in Spring Boot)
- https://www.quickprogrammingtips.com/spring-boot/using-log4j2-with-spring-boot.html (sharing log4j2 and Spring Boot)
- https://logging.apache.org/log4j/2.x/manual/layouts.html (log4j2 templates)
- http://www.codepreference.com/2016/04/configurable-thread-context-tags-log4j2.html (stream logging context variable)
- https://docs.spring.io/spring-boot/docs/current/reference/html/boot-features-external-config.html (external Spring Boot configuration settings)
- http://logging.apache.org/log4j/2.x/manual/configuration.html#PropertySubstitution (replacing log4j2 properties)
A bit of advertising 🙂
Thank you for staying with us. Do you like our articles? Want to see more interesting materials? Support us by placing an order or recommending to your friends, cloud-based VPS for developers from $ 4.99, A unique analogue of entry-level servers that was invented by us for you: The whole truth about VPS (KVM) E5-2697 v3 (6 Cores) 10GB DDR4 480GB SSD 1Gbps from $ 19 or how to divide the server? (options are available with RAID1 and RAID10, up to 24 cores and up to 40GB DDR4).
Dell R730xd 2 times cheaper at the Equinix Tier IV data center in Amsterdam? Only here 2 x Intel TetraDeca-Core Xeon 2x E5-2697v3 2.6GHz 14C 64GB DDR4 4x960GB SSD 1Gbps 100 TV from $ 199 in the Netherlands! Dell R420 – 2x E5-2430 2.2Ghz 6C 128GB DDR3 2x960GB SSD 1Gbps 100TB – from $ 99! Read about How to Build Infrastructure Bldg. class c using Dell R730xd E5-2650 v4 servers costing 9,000 euros for a penny?
