Customers quite regularly call on me to support them when an application is not behaving as expected. On a development machine there are a lot of ways and utilities to analyse the situation. But troubleshooting the erroneous application behaviour in production environments quite often limits your tool belt to a minimum. The bare minimum that should be available are the application’s log messages, so that’s probably the simplest thing to start with. From what I saw, in most production environments log output is unfortunately reduced to the absolute minimum for the sake of system performance and resource efficiency. In those environments it would be ok to increase the logging for a certain portion of the traffic, e.g. just for one incoming HTTP request, but this seems to be quite complicated. In this post I’d like to show you that it isn’t.
Logging in Java
In the Java ecosystem we are free to choose from a variety of logging frameworks to help us get the job done. There is the time-honoured Apache Log4J, it’s so-called successor Logback and the SLF4J API which became quite popular. But with this post I’d like to direct your attention to Log4J’s new major version release Apache Log4j 2. Apart from greater performance and numerous bugfixes, Log4j 2 also comes with some new and optimised features which we can use to accomplish our task.
The building blocks
The first thing we need is a place to intercept the HTTP request, extract the appropriate HTTP header and add it to Log4j’s
ThreadContext is a “Mapped Diagnostic Context” (MDC) which is also known from other logging frameworks.
Below you will find a naive implementation of a
ServletFilter which does exactly this, assuming that the parameter to enable debugging is a boolean HTTP header like
Of course you can use any other request parameter you like.
Once we got the parameter in our
ThreadContext, we don’t need any further code changes, but can solely focus on the Log4j 2 configuration.
In our Log4j configuration we can now make use of the DynamicThresholdFilter to generally change the log level to TRACE in case the parameter “x-debug-enabled” is set to “true”.
A simple yet complete
log4j2.xml file doing this could look like the following:
With this in hand we might even decide that we want to write those special HTTP requests to a different log file. This can be done by adding the following snippet to our
In this case we are using a
ThreadContextMapFilter to ACCEPT log messages only in case the
x-debug-enabled parameter in the
ThreadContext map is set to
Otherwise the log message is DENIED meaning not written to this RollingFile appender.
We’ve just shown how to enable
TRACE logging with Log4j 2 on a per-request basis, but of course this isn’t limited to HTTP requests.
Any parameter in the
ThreadContext can be used as a trigger. Therefore it is possible to debug batch jobs which have a certain flag, WebSocket connections or any other thread-based processing.
The Log4j 2 manual has a lot more information and also explains use cases for new features. I recommend you read through it if you want to gain a deeper understanding. If you happen to read German, you might also be interested in the introductory article on Log4j 2 “Logging konsolidieren und Performance gewinnen” by my colleagues Stefan and Phillip.
As I always like to get constructive feedback, please feel free to get in contact either via Twitter, mail or the contact form on innoq.com