Logback know how-to

What is logback?

Logback is intended as a successor to the popular log4j project. It was designed by Ceki Gülcü, log4j's founder. 

package chapters.introduction;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class HelloWorld1 {

  public static void main(String[] args) {

    Logger logger = LoggerFactory.getLogger("chapters.introduction.HelloWorld1");
    logger.debug("Hello world.");

  }
}

Logger, Appenders and Layouts

Logback is built upon three main classes: Logger, Appender and Layout. These three types of components work together to enable developers to log messages according to message type and level, and to control at runtime how these messages are formatted and where they are reported.

The Logger class is part of the logback-classic module. On the other hand, the Appender and Layout interfaces are part of logback-core. As a general-purpose module, logback-core has no notion of loggers.

Logger context

The first and foremost advantage of any logging API over plain System.out.println resides in its ability to disable certain log statements while allowing others to print unhindered. This capability assumes that the logging space, that is, the space of all possible logging statements, is categorized according to some developer-chosen criteria. In logback-classic, this categorization is an inherent part of loggers. Every single logger is attached to aLoggerContext which is responsible for manufacturing loggers as well as arranging them in a tree like hierarchy.

Loggers are named entities. Their names are case-sensitive and they follow the hierarchical naming rule:

Named Hierarchy

A logger is said to be an ancestor of another logger if its name followed by a dot is a prefix of the descendant logger name. A logger is said to be a parent of a child logger if there are no ancestors between itself and the descendant logger.

For example, the logger named "com.foo" is a parent of the logger named "com.foo.Bar". Similarly, "java" is a parent of "java.util" and an ancestor of "java.util.Vector". This naming scheme should be familiar to most developers.

The root logger resides at the top of the logger hierarchy. It is exceptional in that it is part of every hierarchy at its inception. Like every logger, it can be retrieved by its name, as follows:

Logger rootLogger = LoggerFactory.getLogger(org.slf4j.Logger.ROOT_LOGGER_NAME);

If a given logger is not assigned a level, then it inherits one from its closest ancestor with an assigned level. More formally:

The effective level for a given logger L, is equal to the first non-null level in its hierarchy, starting at L itself and proceeding upwards in the hierarchy towards the root logger.

To ensure that all loggers can eventually inherit a level, the root logger always has an assigned level. By default, this level is DEBUG.

Below are four examples with various assigned level values and the resulting effective (inherited) levels according to the level inheritance rule.

Example 1

Logger name	Assigned level	Effective level
root	DEBUG	DEBUG
X	none	DEBUG
X.Y	none	DEBUG
X.Y.Z	none	DEBUG

In example 1 above, only the root logger is assigned a level. This level value, DEBUG, is inherited by the other loggers X, X.Y and X.Y.Z

Example 2

Logger name	Assigned level	Effective level
root	ERROR	ERROR
X	INFO	INFO
X.Y	DEBUG	DEBUG
X.Y.Z	WARN	WARN

Parameterized logging

Given that loggers in logback-classic implement the SLF4J's Logger interface, certain printing methods admit more than one parameter. These printing method variants are mainly intended to improve performance while minimizing the impact on the readability of the code.

For some Logger logger, writing,

logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));

incurs the cost of constructing the message parameter, that is converting both integer i and entry[i] to a String, and concatenating intermediate strings. This is regardless of whether the message will be logged or not.

One possible way to avoid the cost of parameter construction is by surrounding the log statement with a test. Here is an example.

if(logger.isDebugEnabled()) { 
  logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));
}

This way you will not incur the cost of parameter construction if debugging is disabled for logger. On the other hand, if the logger is enabled for the DEBUG level, you will incur the cost of evaluating whether the logger is enabled or not, twice: once in debugEnabled and once in debug. In practice, this overhead is insignificant because evaluating a logger takes less than 1% of the time it takes to actually log a request.

Better alternative

There exists a convenient alternative based on message formats. Assuming entry is an object, you can write:

Object entry = new SomeObject(); 
logger.debug("The entry is {}.", entry);

1. Logback tries to find a file called logback.groovy in the classpath.
2. If no such file is found, logback tries to find a file called logback-test.xml in the classpath.
3. If no such file is found, it checks for the file logback.xml in the classpath..
4. If neither file is found, logback configures itself automatically using the BasicConfigurator which will cause logging output to be directed to the console.

The fourth and last step is meant to provide a default (but very basic) logging functionality in the absence of a configuration file.

Specifying the location of the default configuration file as a system property

You may specify the location of the default configuration file with a system property named"logback.configurationFile". The value of this property can be a URL, a resource on the class path or a path to a file external to the application.

java -Dlogback.configurationFile=/path/to/config.xml chapters.configuration.MyApp1

Note that the file extension must be ".xml" or ".groovy". Other extensions are ignored. Explicitly registering a status listener may help debugging issues locating the configuration file.

Automatically reloading configuration file upon modification

Logback-classic can scan for changes in its configuration file and automatically reconfigure itself when the configuration file changes.

If instructed to do so, logback-classic will scan for changes in its configuration file and automatically reconfigure itself when the configuration file changes. In order to instruct logback-classic to scan for changes in its configuration file and to automatically re-configure itself set the scan attribute of the element to true, as shown next.

Example: Scanning for changes in configuration file and automatic re-configuration (logback-examples/src/main/java/chapters/configuration/scan1.xml)

View as .groovy

 scan="true"> 
  ...  

By default, the configuration file will be scanned for changes once every minute. You can specify a different scanning period by setting the scanPeriod attribute of the  element. Values can be specified in units of milliseconds, seconds, minutes or hours. Here is an example:

Example: Specifying a different scanning period (logback-examples/src/main/java/chapters/configuration/scan2.xml)

View as .groovy

 scan="true" scanPeriod="30 seconds" > 
  ... 

NOTE If no unit of time is specified, then the unit of time is assumed to be milliseconds, which is usually inappropriate. If you change the default scanning period, do not forget to specify a time unit.

Invoking JoranConfigurator directly

Logback relies on a configuration library called Joran, part of logback-core. Logback's default configuration mechanism invokes JoranConfigurator on the default configuration file it finds on the class path. If you wish to override logback's default configuration mechanism for whatever reason, you can do so by invokingJoranConfigurator directly. The next application, MyApp3, invokes JoranConfigurator on a configuration file passed as a parameter.

Example: Invoking JoranConfigurator directly (logback-examples/src/main/java/chapters/configuration/MyApp3.java)

package chapters.configuration;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.joran.JoranConfigurator;
import ch.qos.logback.core.joran.spi.JoranException;
import ch.qos.logback.core.util.StatusPrinter;
public class MyApp3 {
  final static Logger logger = LoggerFactory.getLogger(MyApp3.class);

  public static void main(String[] args) {
    // assume SLF4J is bound to logback in the current environment
    LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory();
    
    try {
      JoranConfigurator configurator = new JoranConfigurator();
      configurator.setContext(context);
      // Call context.reset() to clear any previous configuration, e.g. default 
      // configuration. For multi-step configuration, omit calling context.reset().
      context.reset(); 
      configurator.doConfigure(args[0]);
    } catch (JoranException je) {
      // StatusPrinter will handle this
    }
    StatusPrinter.printInCaseOfErrorsOrWarnings(context);

    logger.info("Entering application.");

    Foo foo = new Foo();
    foo.doIt();
    logger.info("Exiting application.");
  }
}

This application fetches the LoggerContext currently in effect, creates a new JoranConfigurator, sets the context on which it will operate, resets the logger context, and then finally asks the configurator to configure the context using the configuration file passed as a parameter to the application. Internal status data is printed in case of warnings or errors. Note that for multi-step configuration, context.reset() invocation should be omitted.