Does your Spring Boot app output detailed JSON to its logs yet?

With a few minor configuration changes, and a fresh perspective on your logging practices, your Spring Boot application can easily benefit from the latest logging analysis tools.

Background

For years I’ve touted the benefits of

Each of these explorations has presented minor challenges that we have had to overcome along the way. But over time, we have adapted a wealth of techniques from our everyday development experience.

This blog focuses on refining and documenting some of these techniques for Java developers who are new to Spring Boot, as well as experts who are evaluating the switch to JSON-based logging.

JSON Logging for Java

Whether you will be examining logs from the command line or ingesting them into a search engine, streaming data from Java to JSON is one of the most readable, efficient, and versatile encoding formats available.

We have been successful using the combination of SLF4J logging APIs on top of the widely supported and extendable Logback implementation. Logstash provides us with a wonderfully adaptable JSON encoder for Logback.

The rest of this blog details the process of integrating these resources to produce useful JSON logging output from a Spring Boot application.

Add Maven Dependencies

By default Spring Boot already claims dependencies on Logback and SLF4J.

We only need to add a dependency for the Logstash JSON encoder:

pom.xml

<dependency>
        <groupId>net.logstash.logback</groupId>
        <artifactId>logstash-logback-encoder</artifactId>
        <version>5.2</version>
</dependency>

Add Logback Configuration for JSON Output

Spring Boot already provides a default Logback configuration, but allows us to override it by adding our own Logback configuration to src/main/resources/logback-spring.xml.

Our configuration uses the Logstash Logback JSON encoder which provides the most customizable JSON formatting available.

To enable JSON logging, use this Logback configuration:

src/main/resources/logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
	<property resource="application.properties" />
	<contextName>${spring.application.name}</contextName>
	<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
		<encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
			<providers>
				<contextName>
					<fieldName>app</fieldName>
				</contextName>
				<timestamp>
					<fieldName>ts</fieldName>
					<timeZone>UTC</timeZone>
				</timestamp>
				<loggerName>
					<fieldName>logger</fieldName>
				</loggerName>
				<logLevel>
					<fieldName>level</fieldName>
				</logLevel>
				<callerData>
					<classFieldName>class</classFieldName>
					<methodFieldName>method</methodFieldName>
					<lineFieldName>line</lineFieldName>
					<fileFieldName>file</fileFieldName>
				</callerData>
				<threadName>
					<fieldName>thread</fieldName>
				</threadName>
				<mdc />
				<arguments>
					<includeNonStructuredArguments>false</includeNonStructuredArguments>
				</arguments>
				<stackTrace>
					<fieldName>stack</fieldName>
				</stackTrace>
   				<message>
					<fieldName>msg</fieldName>
				</message>
			</providers>
		</encoder>
	</appender>
	<root level="INFO">
		<appender-ref ref="CONSOLE" />
	</root>
</configuration>

Note: We declare the src/main/resources/application.properties file as a source for Logback property values, and then reference ${spring.application.name} whose value is provided by that file.

Configure Spring Application Properties

Add these property values to src/main/resources/application.properties:

src/main/resources/application.properties

spring.application.name=MySpringApplication
spring.main.banner-mode=OFF
logging.level.=INFO
logging.level.org.springframework=WARN
logging.level.org.hibernate=WARN
logging.level.com.netflix=WARN

Spring Boot automatically configures Logback resources using Spring application properties, making it a simple matter to change the logging levels when specific classes or entire packages require different levels of visibility.

Always Set These Properties

spring.application.name=MySpringApplication

All Spring Applications should have this property available because it is used throughout the Spring Framework for outputting the application’s name in some of the logs. We reference this value in logback-spring.xml for the Logback context, and is automatically rendered with each logged event.

spring.main.banner-mode=OFF

This turns off the generic Spring Banner output which is NOT JSON friendly.

logging.level.=WARN

Spring Boot uses this property to configure the default logging level for all loggers. Set this to WARN or INFO unless you are debugging 3rd party packages.

Use SLF4J for Logging

Simple Logging Facade for Java (SLF4J) is an easy to use framework included with your Spring Boot application that provides a “Simple” API layer between available logging APIs and your code. This provides a consistent and powerful API for generating the logging message. Additional information such as a timestamp, originating classname, and line number are automatically output with each log entry for traceability.

It’s worth reading the two-page user manual at http://slf4j.org/manual.html

Code Example

To use SLF4J in your Spring Boot application, add these imports:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

Then simply create a Logger instance by calling the static LoggerFactory.getLogger() method. Logger methods info(), debug(), trace(), warn(), and error() are used to generate log entries from your application code.

// MySpringApplication.java

package com.myapp.MySpringApplication.myspringapplication;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import javax.annotation.PostConstruct;


@SpringBootApplication
public class MySpringApplication
{
        public static void main(String[] args)
        {
                SpringApplication.run(MySpringApplication.class, args);
        }

        @PostConstruct
        public void init()
        {
                Logger log = LoggerFactory.getLogger(MySpringApplication.class);

                try
                {
                        log.info("Hello, World!");

                        throw new NullPointerException("Oh no!");
                }
                catch (Exception e)
                {
                        log.error("Could not continue.", e);
                }
        }
}

These JSON Fields Are Output for Each Event

JSON Output Example

The code example from the previous section produced the following JSON output.

Scroll right to view each line in its entirety:

{"app":"MySpringApplication","ts":"2018-12-17T17:51:10.701+00:00","logger":"com.myapp.MySpringApplication.myspringapplication.MySpringApplication","level":"INFO","class":"org.springframework.boot.StartupInfoLogger","method":"logStarting","file":"StartupInfoLogger.java","line":50,"thread":"main","msg":"Starting MySpringApplication v0.0.1-SNAPSHOT on C02R16SXG8WN.corp.proofpoint.com with PID 16838 (/Users/pcunningham/sandbox/my-spring-application/target/my-spring-application-0.0.1-SNAPSHOT.jar started by pcunningham in /Users/pcunningham/sandbox/my-spring-application)"}
{"app":"MySpringApplication","ts":"2018-12-17T17:51:10.712+00:00","logger":"com.myapp.MySpringApplication.myspringapplication.MySpringApplication","level":"INFO","class":"org.springframework.boot.SpringApplication","method":"logStartupProfileInfo","file":"SpringApplication.java","line":675,"thread":"main","msg":"No active profile set, falling back to default profiles: default"}
{"app":"MySpringApplication","ts":"2018-12-17T17:51:11.133+00:00","logger":"com.myapp.MySpringApplication.myspringapplication.MySpringApplication","level":"INFO","class":"com.myapp.MySpringApplication.myspringapplication.MySpringApplication","method":"init","file":"MySpringApplication.java","line":25,"thread":"main","msg":"Hello, World!"}
{"app":"MySpringApplication","ts":"2018-12-17T17:51:11.136+00:00","logger":"com.myapp.MySpringApplication.myspringapplication.MySpringApplication","level":"ERROR","class":"com.myapp.MySpringApplication.myspringapplication.MySpringApplication","method":"init","file":"MySpringApplication.java","line":31,"thread":"main","stack":"java.lang.NullPointerException: Oh no!\n\tat com.myapp.MySpringApplication.myspringapplication.MySpringApplication.init(MySpringApplication.java:27)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat java.lang.reflect.Method.invoke(Method.java:498)\n\tat org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleElement.invoke(InitDestroyAnnotationBeanPostProcessor.java:363)\n\tat org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleMetadata.invokeInitMethods(InitDestroyAnnotationBeanPostProcessor.java:307)\n\tat org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor.postProcessBeforeInitialization(InitDestroyAnnotationBeanPostProcessor.java:136)\n\tat org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsBeforeInitialization(AbstractAutowireCapableBeanFactory.java:419)\n\tat org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1737)\n\tat org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:576)\n\tat org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:498)\n\tat org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:320)\n\tat org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)\n\tat org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:318)\n\tat org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:199)\n\tat org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:846)\n\tat org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:863)\n\tat org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:546)\n\tat org.springframework.boot.SpringApplication.refresh(SpringApplication.java:775)\n\tat org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:397)\n\tat org.springframework.boot.SpringApplication.run(SpringApplication.java:316)\n\tat org.springframework.boot.SpringApplication.run(SpringApplication.java:1260)\n\tat org.springframework.boot.SpringApplication.run(SpringApplication.java:1248)\n\tat com.myapp.MySpringApplication.myspringapplication.MySpringApplication.main(MySpringApplication.java:15)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat java.lang.reflect.Method.invoke(Method.java:498)\n\tat org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48)\n\tat org.springframework.boot.loader.Launcher.launch(Launcher.java:87)\n\tat org.springframework.boot.loader.Launcher.launch(Launcher.java:50)\n\tat org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:51)\n","msg":"Could not continue."}
{"app":"MySpringApplication","ts":"2018-12-17T17:51:11.335+00:00","logger":"com.myapp.MySpringApplication.myspringapplication.MySpringApplication","level":"INFO","class":"org.springframework.boot.StartupInfoLogger","method":"logStarted","file":"StartupInfoLogger.java","line":59,"thread":"main","msg":"Started MySpringApplication in 1.264 seconds (JVM running for 1.795)"

JSON Field Descriptions

The following list of fields represents the Java-specific context of a logging event. Most of this information pin-points a specific location in the codebase, with some execution context on the side:

  • app - The spring.application.name of the application that created the event as set in your application.properties resource file.
  • ts - The ISO8601 timestamp assigned to the logging entry when it was written.
  • logger - The name assigned to the logger in code. This is usually set to this.getClass() but could be something else.
  • level - The log level assigned to the log entry. This is usually set to TRACE, DEBUG, INFO, WARN, or ERROR.
  • class - The java classname from where the log entry originated in code.
  • method - The java class method from where the log entry originated in code.
  • file - The java filename from where the log entry originated in code.
  • line - The line of code in the java file where the log entry originated in code.
  • thread - The name of the thread that was executing when the log entry was written. These have unique names within a thread pool.
  • msg - The human-readable message associated with this log entry. This can sometimes contain non-JSON data.
  • stack - The Java stack trace associated with this log entry. This field does not appear unless a Throwable was logged with the event. The first line of this field will often display additional information about the event, the rest of it is a length-limited stack trace.

For the casual JSON reader, the level and msg are the most important fields for consideration.

Use Logger Levels Appropriately

SLF4J provides discrete Logger methods which require at minimum the msg field value. These methods also support passing a Throwable instance for the stack field, as well as other arguments for parameter substitution.

Note: In general, try to avoid the use of substitution parameters as part of the msg. Additional context can be provided as separate JSON fields using StructuredArguments (see below). Providing a static msg makes it easier to identify and group repeated operations as their code location may vary as the codebase is altered.

log.error()

Use for fatal errors, caught exceptions, and other conditions where the code cannot complete its function. Errors should never be filtered.

Examples:

log.error("Missing companyId");
log.error("Could not continue.", nullPtrException);

log.warn()

Use for non-critical errors, including notable/unexpected outcomes in code. This may be the first indication something is not working correctly. Don’t ignore.

Examples:

log.warn("Missing filter parameter; using defaults.");
log.warn("Could not establish connection.", ioException);

log.info()

Use for output that indicates normal operation. This includes significant points of success, and other output that is helpful in verifying “normal” operation.

Examples:

log.info("Uploading users to server...");
log.info("Connection established.");
log.info("Upload process completed.");
log.info("Saved company information.");

log.debug()

Use for active debugging. This will help output for debugging sessions stand out. Remove or change these to log.trace() before release.

Examples:

log.debug("For developers eyes only.");
log.debug("Entering loop...");
log.debug("Processing item " + itemIndex);
log.debug("Created {} items", itemCount);

log.trace()

Use for low-level debugging code that you normally would not want to see in production, but is useful for tracing low-level operations at runtime.

Examples:

log.trace("Entering...");
log.trace("Parsed token: " + token);
log.trace("Sending email {} of {}", emailIndex, emailCount);
log.trace("Exiting...");

Using these conventions across a larger code base makes the Logback filtering process more flexible and predictable at runtime. Production code can be run at the INFO or WARN level and be very efficient at reporting the overall progress of your application. For development and testing, these levels can be lowered to DEBUG and TRACE to provide more insight into the classes and packages that are being monitored. Prolific output from a single package, class, or method can be targeted and disabled completely using configuration properties.

Choose a Human-Readable Message

SLF4J and Logback offer advanced formatting features which makes it very easy to parameterize the msg with additional parameters, ultimately generating output that is unique, and ultimately more difficult to read in context. While this can occasionally be useful while debugging, avoid formatting the msg with additional parameters:

  • Use a short static sentence or phrase for the msg parameter value.
  • Use StructuredArguments to pass additional parameters values by key.

DON’T USE MESSAGE FORMATTING

log.info("Processing company {} of {}", companyIndex, companyCount);

This combines the parameters with the message:

{ ... "msg":"Processing company 128 of 250" }

USE STRUCTURED ARGUMENTS INSTEAD

import static net.logstash.logback.argument.StructuredArguments.v;

...

log.info("Processing company",
		v("companyIndex", companyIndex), v("companyCount", companyCount));

This logs the parameters as separate searchable fields:

{ ... "msg":"Processing company","companyIndex":128,"companyCount":250 }

Why Static msg with Structured Arguments?

When your msg is output separately from your arguments:

  • You can search for the msg in Splunk without a wildcard on the search string. This returns search results much faster.
  • You can search for the msg in Java code without needing to wildcard the search string. This makes it easier to find the line in code where a specific msg value was generated.
  • You can search for the argument values as separate fields.
  • You can perform dynamic calculations and formatting on the fields themselves without needing to invoke a regular expression to parse them out of the msg.

Although an expert with regular expressions can locate data embedded in the msg, there’s no reason to put it upon yourself, or your favorite search engine, to do this. Just pass them separately as StructuredArguments and they will appear distinctly as their own human-readable JSON fields.

But I need to put more context to the msg itself…

Fine. Go ahead. Use msg formatting. If you are using debug() and trace() during development, you may find it more convenient to do this during testing and debugging. Just TRY HARD to avoid them for output that will be logged in production.

Use StructuredArguments for Additional Context

Included with the dependency on logstash-logback-encoder are Structured Arguments. Although SLF4J already has log message formatting which incorporates values from an argument list, this subtle extension provides some important benefits:

  • Logger arguments are associated with a named key and output as separate JSON fields.
  • Logstash provides the static method StructuredArguments.v() which converts key/value pairs into an Object that is passed as a parameter to SLF4J and logged as an extra field in the JSON.
  • You don’t need to manage the MDC to temporarily insert key/value pairs into the logging output.

Here’s an example of how it’s done:

import static net.logstash.logback.argument.StructuredArguments.v;

public class StructuredArgumentsTest
{
	public void testArguments()
	{
		Logger log = LoggerFactory.getLogger(this.getClass());
	
		String foo = "FOO";
		String bar = "BAR";
		String bang = "BANG";
	
		log.info("Stuff happened.",
			v("foo", foo), v("bar", bar), v("bang", bang));
	}
}

Because Logstash now sees each argument as a StructuredArgument, it knows to add them as key/values in the JSON. The output looks similar to this:

{"ts":"2017-06-13T20:35:45.881+00:00",
	"class":"StructuredArgumentsTest","method":"testArguments",
	"file":"StructuredArgumentsTest.java","line":13,
	"thread":"main","logger":"TestArguments",
	"level":"INFO","msg":"Stuff happened.",
	"foo":"FOO","bar":"BAR","bang":"BANG"}

You can see that all three StructuredArgument parameter values are represented as separate key/value pairs for foo, bar, and bang in the JSON output after the msg field.

Appendix

The sections that follow provide additional information and tips regarding JSON logging in no particular order.

Appendix A: Configure Levels for Specific Loggers

Adding a logging.level property for specific Loggers is as easy as adding its package or class name to your src/main/resources/application.properties file:

Example configuration:

logging.level.org.springframework=WARN
logging.level.org.hibernate=ERROR
logging.level.com.netflix=OFF
logging.level.com.myapp=DEBUG
logging.level.com.myapp.MySpringApplication=TRACE
  • Using the WARN, ERROR, and OFF logging levels limits output from 3rd party packages until a problem occurs. This significantly reduces overall output from frameworks like Spring and Hibernate. Add logging.level properties for any 3rd party packages you need to restrict.

  • Using logging.level.com.myapp=DEBUG enables DEBUG level logging for all Loggers that are named starting with com.myapp. This property should be set to INFO for production to disable debugging output.

  • Using logging.level.com.myapp.MySpringApplication=TRACE enables TRACE level logging for ONLY the Loggers that are named com.myapp.MySpringApplication. Sometimes it’s necessary to enable TRACE level logging on classes during debugging and development. This property should be set to INFO for production to disbale superfluous trace output.

Appendix B: Customize the JSON Output

The src/main/resources/logback-spring.xml file contains the configuration for net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder supporting the use of customizable Providers for controlling how Logback’s context is output as JSON.

Here are the providers we used:

<contextName>
	<fieldName>app</fieldName>
</contextName>

This creates a JSON field app which contains the value of spring.application.name.

<timestamp>
	<fieldName>ts</fieldName>
	<timeZone>UTC</timeZone>
</timestamp>

This creates a JSON field ts containing a UTC formatted timestamp. We shortened the default fieldName from @timestamp to ts to reduce the amount of output per log event.

<loggerName>
	<fieldName>logger</fieldName>
</loggerName>

This creates a JSON field logger containing the name of the logger. The default fieldName is logger_name which we simply shortened.

<logLevel>
	<fieldName>level</fieldName>
</logLevel>

This creates a JSON field level containing the logging level (ERROR, WARN, INFO, DEBUG, or TRACE).

<callerData>
	<classFieldName>class</classFieldName>
	<methodFieldName>method</methodFieldName>
	<lineFieldName>line</lineFieldName>
	<fileFieldName>file</fileFieldName>
</callerData>

This creates JSON fields for class, method, line, and file which have all been shortened from their respective default values of caller_class_name, caller_method_name, caller_line_number, and caller_file_name.

This change is for the sanity of developers who will be reading this the JSON output directly, significantly reducing the amount of bloat.

<threadName>
	<fieldName>thread</fieldName>
</threadName>

This creates a JSON field thread containing the name of the executing Thread.

<mdc />

This automatically creates JSON fields for all entries stored in the Mapped Domain Context or MDC. This is useful adding correlation data which identify logging events from the same session or authority.

<arguments />

This creates a JSON field for each StructuredArgument passed as an argument to any of the SLF4J logging methods. This is most commonly used with the net.logstash.logback.argument.StructuredArgments.v() static method.

<stackTrace>
    <fieldName>stack</fieldName>
</stackTrace>

This creates a JSON field stack containing the stack trace logging events accompanied by a Throwable.

<message>
	<fieldName>msg</fieldName>
</message>

This creates a JSON field msg containing the text of the logging message. The fieldName was changed from the default message for brevity.

Appendix C: The Naming of Loggers

Logger instances can have any name, but common convention is to put a Java classname in there making it possible to filter output of specific classes through simple Logback configuration.

  • Static methods use the static classname (ie: MyClass.class).
  • Instance methods use the instance classname (ie: this.getClass()).

Naming Loggers for Static Methods

For static methods, Logger is likely to be retrieved “on the fly”:

// MyApp.java
	
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
	
public class MyApp
{
    public static void main(String args[])
    {
        Logger log = LoggerFactory.getLogger(MyApp.class);
        
        log.info("Hello, World!");
    }
}

Here we are using the static classname of its container class MyApp.class. In this situation, the logger and the class fields would both be MyApp, which is just fine.

Naming Loggers for Instance Methods

Store the Logger reference as a member variable and it will be accessible from any instance method:

// MyApp.java
	
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
	
public class MyApp
{
	private Logger log = LoggerFactory.getLogger(this.getClass());
	
    public void meetTheWorld()
    {
        log.info("I am the world.");
    }
	
    public void greetTheWorld()
    {
        log.info("Hello, World!");
    }
}

When a Logger is named with this.getClass(), the logger name will always reflect the class instance as opposed to the class in code from where the Logger is actually used. This is useful for filtering all of the output for entire classes, since it would include output from their inherited methods. Remember that the field class will still be reported correctly to pinpoint its origin in code.

Add org.slf4j.Logger To Your Base Classes

You can quickly incorporate SLF4J into your project by adding org.slf4j.Logger as a protected member to a base classes that are inherited by other classes your application uses:

// MyAppBase.java

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
  
public class MyAppBase
{
    @Transient // Prevents this field from being Serialized
    protected transient Logger log = LoggerFactory.getLogger(this.getClass());
}

Subclasses of MyAppBase can now use this Logger instance freely:

public class MyApp extends MyAppBase
{
    public void foo()
    {
        log.info("Hello, MyApp!");
    }
}

Use this convention in all of your base classes that use SFL4J and it will always be available when you need it. The main advantage to this is not having to remember the imports for org.slf4j.Logger and org.slf4j.LoggerFactory each time you create a new class.

Naming Conventions Used By Third Party Loggers

You will find that some 3rd party libraries don’t use Java classnames for their Logger instances, and follow alternate naming conventions. For this reason the fields for class, method, and line are available to pinpoint the origin of the log entry code.

Appendix D: Reduce Logging Overhead

Although SLF4J and Logback are very efficient when it comes to avoiding any unnecessary processing, here is one way to deal with sections of code which could be resource intensive:

Branch around calls to debug() and trace()

While it is a best practice to remove DEBUG and disabled TRACE output for production, there is sometimes too much supporting code to merit its removal, but executing it could be drain on available resources. No problem, you can use Logger.isDebugEnabled() and Logger.isTraceEnabled() to create a branch around your logging instead.

public class ItemHandler
{
	Logger log = LoggerFactory.getLogger(this.getClass());
	
	public void handleItem(Object item, int itemIndex, int itemCount)
	{
		if (log.isTraceEnabled()) log.trace("Handling item {}", itemIndex);

		if (log.isDebugEnabled())
		{
			StringBuilder b = new StringBuilder();
			b.append("Processing item ");
			b.append(itemIndex);
			b.append(": ");
			b.append(item.toString());
			log.debug(b.toString());

			double completed = (itemIndex / itemCount) * 100.0;
			log.debug("Processing is {}% completed.", completed);
		}

		if (log.isTraceEnabled()) log.trace("Handled {} items", itemCount);
	}
}

Appendix E: Useful MDC Cleanup Trick

You might not trust that your MDC-introduced key/value pairs will be cleaned up in a timely manner after you are through with them. Starting with JDK 1.7, we can use a try-with-resources block to declare the values we are adding to MDC and that they be auto-released when the block exits.

Here’s a quick example:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

public class MDCTesting
{
	public void testTryWithResources()
	{
		Logger log = LoggerFactory.getLogger(this.getClass());
		
		try (
			MDC.MDCCloseable alpha = MDC.putCloseable("alpha", "AAA");
			MDC.MDCCloseable beta = MDC.putCloseable("beta", "BBB");
		) {
			// Logs of called methods will output the additional MDC values to JSON.
			testLoggingWithMDC();
		}

		// Logs from outside the try block will NOT output the MDC values to JSON.
		log.info("Test completed.");
	}

	public void testLoggingWithMDC()
	{
		log.info("Info 1, 2, 3");
		log.debug("Debugging 1, 2, 3");
		log.trace("Tracing 1, 2, 3");
		log.warn("Warning 1, 2, 3");
		log.error("Error 1, 2, 3");
	}
}

In this example, the try-with-resources Statement allows us to both declare and add key/value pairs to the MDC in one easy step. Then we execute code within the block which automatically logs the values we added. When the block is exited, the added MDC values are removed for us.

References