Logging

Goal

Concepts

Library

Dependencies

Lesson

The purpose of a computer program is to process some input data and provide some resulting output data. But the result output data may not be the only useful data a program produces. It's common to want to have a persistent record of what actions a program performed. A log of actions is useful for everything from auditing (e.g. finding out who deleted the secret recipe from the database), to debugging (e.g. investigating why a list of animals leaves out all the birds), to simply helping a new developer understand the flow of the program logic.

You've been adding logging capability to some extent in your programs already. Likely you have by started adding a multitude of lines all over your program that look like the following:

Rudimentary logging using System.out.println(…).
System.out.println("variable x currently has the value: " + x);

Using System.out.println(…) for debugging has quite a few drawbacks:

These are the reasons why logging frameworks were invented. These are libraries that allow you to use a consistent interface throughout your program to indicate logging information. These frameworks are flexible and allow configurations that address the needs listed above.

Evolution of Logging in Java

Logging frameworks in Java have had an interesting history. Because various libraries have to interact, it would be best if they all used the same framework. In recent years this is becoming possible, but it wasn't always so easy. There moreover remain several gotchas.

System.out.println(…)

Writing to the console used to be the only way to easily log information. There are now many true logging options, but unfortunately many developers still use this approach for quick-and-dirty logging even though they know better.

Log4j

The first real logging framework for Java was Log4j, an open-source project written by Ceki Gülcü and which is now part of the Apache Software Foundation. The first version, log4j 1, introduced ideas such as loggers and log levels, which you'll learn about later in the lesson. The latest upgrade to the series is currently Log4j 2.

JUL

Sun, the company that invented and was controlling Java at the time, recognized the need for a logging framework and decided to add an official one as part of the the JDK in the java.util.logging package. Referred to simply as java.util.logging (JUL), the JDK's logging infrastructure was similar to Log4j but incompatible with it.

SLF4J

By this point some projects were using Log4j and others were using JUL. So the original author of Log4j decided to create another framework, the Simple Logging Facade for Java (SLF4J). Instead of another logging implementation, this library instead set forth a set of interfaces to simplify and standardize access to any logging implementation.

Using SLF4J a developer could program an application to the SLF4J interfaces and the application could work with either Log4j or JUL, depending on how the developer decided to configuration the application. To make this work, SLFJ provided an adapter library for Log4j and another for JUL, so that the one SLF4J interface could work with either.

Many developers have seen the benefit of working with a single logging interface, so many projects have recently switched from other logging frameworks to SLF4J.

Logback

The creator of Log4j decided to create one more logging framework: Logback. Ceki intended Logback to be the successor to Log4j, although the Apache Software Foundation would probably prefer that log4j 1.x users upgrade to Log4j 2. One benefit of Logback is that it is a direct implementation of the SLF4J interfaces; no adapter libraries are needed.

Apache Commons Logging

The Apache Software Foundation also released its own logging library named Apache Commons Logging. Because this library was once named Jakarta Commons Logging, it is often abbreviated JCL.

SLF4J

Log Level

All the logging frameworks have the idea of a log level. This is the importance or severity of the log messages. You can think of them simply as categories of messages that can be logged, but they do have a set order or priority. Here are the log levels recognized by SLF4J, in order from highest priority to the lowest:

SLF4J log levels.
ERROR
General errors or unexpected conditions.
WARN
An unexpected condition that should be logged but should not interrupt the program.
INFO
General interesting information of events.
DEBUG
Detailed information that may help track down bugs in the logic.
TRACE
Extremely detailed information, including program flow.

Besides indicating the purpose of the message, the use of log levels allows the logging of different log levels to be turned on or off across the entire application by updating the application configuration.

Loggers

A org.slf4j.Logger is the main logger interface through which you will write log messages. It provides equivalent logging methods corresponding to each of the log levels above. For example, all messages sent through one the Logger.info(String msg) method will be logged with the INFO log level.

The simplest way to log a message is just to pass a string to the log method you are using:

Logging a simple message.
logger.info("Starting program.");

Many times you will want to format your string. SLF4J accepts a very simple message template format in which each occurrence of {} is replaced with a following argument.

Logging a formatted message.
logger.warn("Found animal with {} eyes; may not be an error, but more than two eyes is unexpected.", animal.getEyeCount());

If you provide a Throwable as an extra argument to the logging method,SLF4J will log a stack trace of the object—the complete contents of the stack (i.e. the identity of every method recursively calling another method) at the time the exception or error was thrown.

Logging an error message and generating a stack trace of an exception.
logger.error("Error saving vehicle settings.", ioException);

Logger Factories

Before you can use a logger, you have to get one from the org.slf4j.LoggerFactory. At the fundamental level, loggers are given names, and groups of related loggers share the same name. This allows loggers to be turned on or off as a group. It also allows loggers to be arranged in a tree hierarchy, changing settings for entire branches of loggers. It is common practice to name the logger based upon the class doing the logging. Therefore SLF4J has provided a logger factory method that takes a Class as a parameter; a logger name will be determined automatically.

Getting a logger for a particular class.
final Logger logger = LoggerFactory.getLogger(getClass());

Once you get the logger, you can use it within the acquired scope or store it in an instance variable of your class.

Logging Configuration

Dependencies

You'll notice that the Maven artifact ID for the main SLF4J library is slf4j-api. This is because SLF4J is primarily a set of facade interfaces. To get them to work, you'll also need to include an actual logging implementation as a dependency.

Adapters

If you use Logback as your SLF4J implementation, then you have nothing further to do. But if you use another logging framework such as Log4J, you'll need to include a single SLF4J binding as a dependency as well. An SLF4J binding is no other than the adapter design pattern, converting an existing logging framework to work with the SLF4J API. For additional details, see SLF4J user manual.

Binding the SLF4J API to other logging frameworks.
Binding the SLF4J API to other logging frameworks (from SLF4J user manual).

Here are some of the most common SLF4J bindings:

log4j 1
org.slf4j:slf4j-log4j12
JUL
org.slf4j:slf4j-jdk14
JCL
org.slf4j:slf4j-jcl
Bridges

If one of the libraries you are using has not been upgraded to use SLF4J, it may be written directly to the API of some other framework. You'll need to exclude the actual implementation in Maven, and then include one of SLF4J's logging bridges that route calls to the other framework back to SLF4J (and in turn on to the other underlying framework). The following diagram shows various bridges SLF4J provides designed for converting legacy APIs. For more in depth coverage, see Bridging legacy APIs.

Bridging legacy APIs with SLF4J.
Bridging legacy APIs with SLF4J (from Bridging legacy APIs).

Here are some of the most common SLF4J bridges:

log4j 1
org.slf4j:log4j-over-slf4j
JUL
org.slf4j:jul-to-slf4j
JCL
org.slf4j:jcl-over-slf4j

For example suppose that one of your project's dependencies uses JUL, while another uses JCL. You prefer to use SLF4J as your logging API, coupled with Logback as the implementation, as recommended in this lesson. To prevent the libraries you use from logging information to a separate location, you essentially reroute their output to SLF4J by including the appropriate SLF4J bridge libraries in your POM, as shown in the figure.

Configuring pom.xml to use SLF4J with Logback, bridging JUL and JCL to SLF4J.
<!-- use SLF4J API in application -->
<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>slf4j-api</artifactId>
  <version>1.7.21</version>
</dependency>

<!-- ultimately use Logback as logging implementation in application -->
<dependency>
  <groupId>ch.qos.logback</groupId>
  <artifactId>logback-classic</artifactId>
  <version>1.1.7</version>
</dependency>

<!-- bridge java.util.logging to SLF4J -->
<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>jul-to-slf4j</artifactId>
  <version>1.7.21</version>
</dependency>

<!-- bridge Apache commons-logging to SLF4J -->
<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>jcl-over-slf4j</artifactId>
  <version>1.7.21</version>
</dependency>

Configuration Files

Many logging frameworks allow configuration through use of a configuration file apart from the main program code. Logback for example allows many configuration options typically placed inside a logback.xml file, placed in the classpath. In a typical maven configuration, an appropriate location for the static configuration file would be src/main/resources/logback.xml. If no configuration file is provided, Logback provides a default configuration equivalent to that in the following figure. See The logback manual, Chapter 3: Logback configuration for full details.

Equivalent default logback.xml configuration if none is provided.
<configuration>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="DEBUG">
    <appender-ref ref="STDOUT" />
  </root>

</configuration>

Setting Log Level

Most logging implementation default to a reasonable log level. As you saw from the configuration above, default simple logger in Logback defaults to DEBUG, which means that DEBUG information, general INFO messages, and anything more severe will be logged; while TRACE messages will be discarded.

Explicitly setting a log level depends on which logging implementation you are using. In Logback, you can set the log level as part of the configuration file (as shown in Configuration Files, above). You can exclude both DEBUG and TRACE messages, for example, by setting <root level="INFO"> in the configuration.

You may also set Logback's debug level programmatically, using the ch.qos.logback.classic.Level class to indicate the log level. The following example shows how you would set Logback's log level to WARN. It involves setting the log level of the top-level ch.qos.logback.classic.Logger—the root logger in the tree of named loggers.

Programmatically setting the Logback log level.
final Logger rootLogger = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
((ch.qos.logback.classic.Logger)rootLogger).setLevel(ch.qos.logback.classic.Level.WARN);

Layouts

The format of the resulting log output in Logback is governed by a layout. By default Logback uses a ch.qos.logback.classic.encoder.PatternLayoutEncoder layout, which specifies the format of each line using a specified pattern. Most of the time you can simply provide a logback.xml file containing your custom pattern, as shown below. See The logback manual, Chapter 6: Layouts for documentation on the different pattern options.

Custom logback.xml to show the log level at the start, the full date, and actual line numbers.
<configuration>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
      <pattern>%-5level \(%logger{0}\) [%date] - %class.%method\(%file:%line\): %m%n</pattern>
    </encoder>
  </appender>

  <root level="DEBUG">
    <appender-ref ref="STDOUT" />
  </root>

</configuration>

Appenders

Logback uses an appender to specify a destination of the logging output. The examples above use a ch.qos.logback.core.ConsoleAppender to log information to the console using stdout. It is common for an application to also log information to a file, and this can be done using a ch.qos.logback.core.FileAppender. The following example installs a file appender in addition to the appender to stdout.

Additionally logging to a file foo-bar-app.log in the user home directory.
<configuration>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>${user.home}/foobar.log</file>
    <encoder>
      <charset>UTF-8</charset>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="DEBUG">
    <appender-ref ref="STDOUT" />
    <appender-ref ref="FILE" />
  </root>

</configuration>

File appenders can have a complex configuration. In order to keep a log file from growing too large, a rolling policy can specify how the current log file can be rolled over into a series of historical log files which are eventually deleted. A triggering policy determines what will cause the log file to roll.

The figure below provides an extensive example of programmatic configuration to add a ch.qos.logback.core.rolling.RollingFileAppender<E> to whatever configuration has already been set up (e.g. in a logback.xml file), using a log file .foobar/foobar.log in the user's home directory. The triggering policy ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy<E> is configured roll the log file when it reaches 5MB. The rolling policy ch.qos.logback.core.rolling.FixedWindowRollingPolicy is set up to store old log files using the filename format foobar.log.1.zip, foobar.log.2.zip, and foobar.log.3.zip before finally deleting them. The extension .zip indicating that Logback should automatically compress the rolled logs. Play close attention to setting the context and parent of the added configuration elements, as well as the need to start each of the elements.

Additionally logging to a file foo-bar-app.log in the user home directory.
final Path logPath = Paths.get(System.getProperty("user.home")).resolve(".foobar").resolve("foobar.log");

final Logger rootLogger = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
((ch.qos.logback.classic.Logger)rootLogger).setLevel(ch.qos.logback.classic.Level.WARN);
ch.qos.logback.classic.LoggerContext loggerContext = ((ch.qos.logback.classic.Logger)rootLogger).getLoggerContext();

//appender
ch.qos.logback.core.rolling.RollingFileAppender<ch.qos.logback.classic.spi.ILoggingEvent> rollingFileAppender =
    new ch.qos.logback.core.rolling.RollingFileAppender<>();
rollingFileAppender.setContext(loggerContext);
rollingFileAppender.setFile(logPath.toAbsolutePath());

//encoder
ch.qos.logback.classic.encoder.PatternLayoutEncoder patternLayoutEncoder =
    new ch.qos.logback.classic.encoder.PatternLayoutEncoder();
patternLayoutEncoder.setContext(loggerContext);
patternLayoutEncoder.setCharset(StandardCharsets.UTF_8);
patternLayoutEncoder.setPattern("%-5level [%date] %logger{36} - %m%n");
patternLayoutEncoder.start();

//rolling policy
ch.qos.logback.core.rolling.FixedWindowRollingPolicy fixedWindowRollingPolicy =
    new ch.qos.logback.core.rolling.FixedWindowRollingPolicy();
fixedWindowRollingPolicy.setContext(loggerContext);
fixedWindowRollingPolicy.setParent(rollingFileAppender);
fixedWindowRollingPolicy.setFileNamePattern(logPath.getFileName() + ".%i" + ".zip"));
fixedWindowRollingPolicy.setMaxIndex(3);
fixedWindowRollingPolicy.start();

//triggering policy
ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy<ch.qos.logback.classic.spi.ILoggingEvent> triggeringPolicy =
    new ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy<>("5MB");
//start appender
rollingFileAppender.setEncoder(patternLayoutEncoder);
rollingFileAppender.setRollingPolicy(fixedWindowRollingPolicy);
rollingFileAppender.setTriggeringPolicy(triggeringPolicy);
rollingFileAppender.start();

//add appender
((ch.qos.logback.classic.Logger) rootLogger).addAppender(rollingFileAppender);

More extensive documentation on appender configurations can be found in The logback manual, Chapter 4: Appenders.

Clogr

SLF4J goes a long way towards providing a consistent API across logging frameworks, but there are still areas that can be improved such as setting the logging level, as discussed above. Notably most logging implementations by default assume that there will only be one logging configuration on the JVM. Those that allows different configurations often require a complicated setup on a web server. See Logging separation for a discussion for Logback.

The Csar Logging Registrion (Clogr) library, an open-source project by GlobalMentor, Inc., smooths some of the rough edges still present with logging in the Java language. Csar uses the existing SLF4J logger API while adding utilities and log configuration flexibility. The main dependency io.clogr:clogr provides the primary access for retrieving loggers and compartmentalizing configurations. Other Clogr dependencies such as io.clogr:clogr-logback provide additional support for individual logging frameworks.

Loggers via Clogr

Accessing an SLF4J logger using Clogged.
public class MyClass implements Clogged {
  …

    getLogger().info("Clogr is easy.");
  …

The easiest way to acquire an SLF4J logger is to implement io.clogr.Clogged for every class needing access to a logger. The implementing class may then call Clogged.getLogger() to retrieve a Logger instance for that class. In a default configuration this is effectively the same as calling LoggerFactory.getLogger(getClass()) in the implementing class. The power lies in Clogr's ability to switch to local, compartmentalized log configurations per specific threads if so configured, as explained below.

Setting the Clogr Log Level

Programmatically setting the log level using Clogr.
Clogr.getLoggingConcern().setLogLevel(Level.WARN);

You saw above that SLF4J provides no general API for setting the log level programmatically. Clogr rectifies this situation via the io.clogr.LoggingConcern class, which represents the logging configuration for a particular context. The Clogr.getLoggingConcern() method retrieves the appropriate logging concern. If you have included the appropriate Clogr dependency for your logging framework (such as io.clogr:clogr-logback), LoggingConcern.setLogLevel(org.slf4j.event.Level level) will set the log level for the root logger of the logging implementation you are using.

Compartmentalized Configurations

Using the Concern Separation Aspect Registrar (Csar; pronounced /zɑːr/), Clogr has the ability to have multiple logging configurations existing at the same time on the same JVM for any application. The Clogged.getLogger() method discussed above will via Csar determine the correct LoggingConcern in effect for that context. Csar even allows the same code to run in the presence of different logging contexts. The following example, which depends on io.clogr:clogr-logback, uses the default Logback implementation as configured above. One section of code, however, uses a specially configured LogbackLoggingConcern. The configuration is loaded from a packaged resource named other-config.xml using LogbackLoggingConcern.configure(InputStream inputStream).

Accessing different logging configurations transparently in different contexts using Csar.
public class MyClass implements Clogged {
  …

    getLogger().info("foo"); //uses default logging configuration

    LogbackLoggingConcern localLoggingConcern = new LogbackLoggingConcern();
    try(final InputStream configFromResources = getClass().getResourceAsStream("other-config.xml")) {
      localLoggingConcern.configure(configFromResources);
    }

    Csar.run(localLoggingConcern, () -> {
      getLogger().info("bar"); //uses local, customized logging configuration
    }).join();

  …

Review

Summary

Gotchas

In the Real World

Think About It

Self Evaluation

Task

Implement logging in your Booker program.

Implement a --debug command-line flag, with a -d alias, and use this flag, if present, to programmatically set the log level to DEBUG.

Option Alias Description
list Lists all available publications.
load-snapshot Loads the snapshot list of publications into the current repository.
purchase Removes a single copy of the book identified by ISBN from stock.
--debug -d Includes debug information in the logs.
--help -h Prints out a help summary of available switches.
--isbn Identifies a book, for example for the purchase command.
--locale -l Indicates the locale to use in the program, overriding the system default. The value is in language tag format.
--name -n Indicates a filter by name for the list command.
--type -t Indicates the type of publication to list, either book or periodical. If not present, all publications will be listed.

See Also

References

Resources

Acknowledgments