I need to print something to the console, fast!

Java developers have many options when it comes to quickly logging some text to the console.

The canonical Java example:

public class Wombat
{
	public void main(String args[])
	{
		System.out.println(“Hello, World!”);
	}
}

Because of this well-known and supported convention, many Java programmers will unceremoniously add a System.out.println() to their code at the first sign of trouble. Unexpected runtime exceptions, such as this faked NullPointerException, are trapped and printed to the error console using Throwable.printStackTrace(). It works. And it’s only temporary, right?

public class Wombat
{
	public void main(String args[])
	{
		try
		{
			throw new NullPointerException("Oh no!");
		}
		catch (Exception e)
		{
			System.err.println(e.getMessage());
			e.printStackTrace();
		}
	}
}

This approach can become a liability for maintaining production quality code:

  • There’s no way to disable this output in production.
  • There’s not enough information about from where the output originated in code.
  • All output goes directly to the console.

1: Use SLF4J and Logback for Logging

Simple Logging Facade for Java (SLF4J) is an easy to use framework that provides a “Simple” API layer between available logging APIs and your code. This provides a consistent way for your code to focus on providing the logging message, and not the details of how it is actually logged. Common information such as a timestamp, originating classname, and line number are output with each log entry for traceability.

Everything you need to know is in the two-page user manual at http://slf4j.org/manual.html

Once we’ve added SLF4J to our project we can write our code more like this:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
 
public class Wombat
{
	public void main(String args[])
	{
		Logger log = LoggerFactory.getLogger(Wombat.class);

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

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

2: 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:

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

Subclasses of WombatBase can now use this Log instance freely:

public class Wombat extends BaseObject
{
	public void main(String args[])
	{
		Wombat wombat = new Wombat();
		wombat.foo();
	}
	
	public void foo()
	{
		try
		{
			log.info(“Hello, World!”);

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

Use this convention in all of your base classes and SFL4J will be ready anytime you need it.

3. Actively Use logback.xml To Control Logging

All this effort is of limited use without a way to control which log statements are output and how.

By default, SLF4J uses Logback http://logback.qos.ch/manual/index.html

As it’s primarily logging implementation, Logback offers many features including:

  • The logback.xml configuration file that is automatically loaded from the classpath at startup.
  • Filtering based on the specified name of the logger and specified logging level (loggers).
  • Log file output and management options (appenders).
  • Prolific support from 3rd-partys and other popular Java-based APIs.

A simple logback.xml configuration file looks like this:

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
  </appender>

  <logger name=“Wombat” level="TRACE"/>
  <logger name=“com.foo” level=“INFO”/>

  <root level=“WARN”>
    <appender-ref ref="STDOUT"/>
  </root>
</configuration>

This logback.xml configuration tells Logback that we are expecting output to be appended to the console. Any Logger with the name Wombat will be output at the TRACE logging level, any Logger containing the com.wombat package name will be output at the INFO logging level, while all other output (including output from 3rd-part APIs) will be limited to the WARN level.

This is tremendously useful! By changing this one file, we can quickly enable or disable output to only the classes we are interested in monitoring.

Don’t be afraid to change this file to hide logging that you don’t want to see, and highlight the logging that you do want to see.

In production, you’ll probably want to use the INFO or WARN levels for everything.

4. Use the Logger Methods Appropriately

There are five levels of logging supported by SLF4J which should not be used interchangeably:

  • log.info() for all operations that you want to see during normal operation. This includes significant points of success and output that is helpful in verifying “normal” operation. Avoid outputting PII to prevent it from being sent to log files in production.
  • log.debug() ONLY for active debugging. This will make output from your active debugging sessions stand out. Remove or change these to log.trace() before deploying to production servers.
  • log.trace() for low-level debugging code that you normally would not want to see in production, but is useful for debugging low-level operations at runtime.
  • log.warn() to report on non-critical errors and other notable and unexpected outcomes in code. This may be your first indication that something is not exactly right at runtime. Don’t ignore these.
  • log.error() to report fatal errors, exceptions, and other conditions where the code cannot complete its function. Errors should never be filtered.

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 disabled completely without changing any code.

5. Change logback.xml at Runtime

One of the biggest advantages of Logback is that you can configure the logback.xml to be monitored for changes while your application is running. This means that, although your application might be configured to only output WARN level messages at startup, the logback.xml can be changed in realtime to allow more verbose logging output without having to restart. You can use this option in the configuration tag:

<configuration scan="true">
...
</configuration>

This tells Logback to start up a thread to monitor the contents of the logback.xml file periodically for changes. When a change is detected to the file, any supported configuration change is immediately effected and available to the application. This is great for temporarily turning on TRACE level output, or disabling prolific ERROR or WARN level output. Very specific output can be targeted using the logger filters making run-time debugging easier to monitor for specific output.

Notes on Avoiding Unnecessary Overhead

You might be concerned about all the extra “overhead” an API like SLF4J might be adding to your production-level code.

Here are a few things to know about this:

  • In most cases the amount of CPU used for logging is worth the additional runtime visibility provided by your application. Unless you are trying to shave microseconds off a tight loop, leave all your logging code intact during production and selectively disable it using the logback.xml in production.
  • Replace log.debug() with log.trace() to make it easier to separate production-quality trace output from development-related debugging output. If the only debugs are from code that you’re actively debugging, you can use the DEBUG logging level to see this output, while continuing to hide TRACE level output from other code.
  • Don’t worry about passing a null Object value parameter to SLF4J logging methods. It will be displayed as null automatically and won’t throw a NullPointerException.
  • If your debugging code is costly to set up and execute, you can branch around it using log.isTraceEnabled() and log.isDebugEnabled() to prevent it from running unless debugging is explicitly enabled. Use the logback.xml file to enable TRACE or DEBUG to temporarily re-enable it in production.