Learn Clogr

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:

Selectivity: How do you turn them off—or at least some of them?
Location: They get printed on the user's console; what if we want to store them in a file?
Severity: How do we tell the debugging messages from normal status information?

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.

Unless you specifically writing to the console to communicate with the user, don't use System.out.println(…).

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);

You should always log an exception at the point where you handle it (e.g. at the point you present it to the user) in addition to notifying the user. That is error handling should usually have two separate statements: one for notifying the user, and another for logging the error. The user notification message should be internationalized, and may be simply an explanation of the general error condition.

System.out.println(getResources().getString("error-saving-settings-message));
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());

An even easier way to acquire a logger is to call Clogged.getLogger() using the Clogr library. See Clogr below.

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

Another common pattern for logger acquisition is to store it in a static variable for each class that intends to do logging, and use that logger throughout the code in the class. Note that this will require referencing the class statically via FooBar.class rather than dynamically via getClass(). Static loggers are not recommended.

public class FooBar {

  private static final Logger logger = LoggerFactory.getLogger(FooBar.class);
  …

Storing the logger as a static variable may provide faster logger access, but reduces the flexibility of the code by preventing distinct logger settings to be configured for different execution contexts of the application within the same JVM (as Clogr allows; see below). Avoid acquiring loggers statically unless you have a pressing need to do so. See Should Logger members of a class be declared as static? and When Static References to Log objects can be used.

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>

If you are bridging JUL back to SLF4J, as in the above example, you'll also need the following lines of code at the beginning of your program, as JUL is so tightly integrated into the JDK:

SLF4JBridgeHandler.removeHandlersForRootLogger();  //remove normal JUL logging...
SLF4JBridgeHandler.install();  //...and route JUL logging to SLF4J

See org.slf4j.bridge.SLF4JBridgeHandler for more information.

Configuration Files

If you want to use a different logging configuration just for testing, place a separate configuration in src/test/resources/logback-test.xml.

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>

The pattern %-5level indicates the log level should be included with a fixed width of five characters. See The logback manual, Chapter 6: Layouts for more information.

All Logback configurations in logback.xml can be reproduced manually in your source code. Although it is recommended to keep your configurations in static files to allow flexibility and separation from program logic, there may be times when configuring a logger programmatically if it depends on certain runtime values. See the sections on Setting the Log Level and Appenders for examples of programmatic configuration.

You can also put Logback into debug mode by setting <configuration debug="true"> in the configuration file. An alternate approach for turning on debug mode is to pass -Dlogback.debug=true to the JVM. Turning on debug mode will not set the logger level to DEBUG! Setting a certain log level is explained in Setting the Log Level below. See LOGBACK-527: Please add system property to enable debugging of config loading.

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>

Some Logback format options such as %class, %method, %file, and %line take a significant amount of time to calculate may slow down your program's execution.

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>

Logback configuration files allow substitution of environment variables using the form ${env-var}. The example above uses the environment variable user.home, which you learned about in the lesson on I/O. See The logback manual, Chapter 3: Logback configuration; Variable substitution for more information.

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.

Including a Clogr logging framework dependency will normally automatically include the core Clogr dependency, the SLF4J dependency, and the logging framework dependency. This will also register the specific logging framework with Clogr. For example adding Clogr with SLF4J+Logback is as simple as adding the io.clogr:clogr-logback dependency to a project. This dependency will automatically bring the core io.clogr:clogr dependency and register default Clogr logger access to use Logback.

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

Don't use System.out.println(…) for logging purposes.
Use SLF4J for your logging API.
Use Logback for your SLF4J implementation.
Use Clogr to make SLF4J access easier and more flexible.

Gotchas

If you perform manual formatting in your log message strings, this could negatively affect application performance, as you may be formatting messages for low-priority messages that never wind up getting logged.
Don't install an SLF4J bridge for the logging framework you are using as your main SLF4J implementation.
If you log an error at different levels in the call stack, such as location where the error occurred and later where the error was displayed, you will wind up with multiple messages in the log output, which may mislead you into thinking that more than one error occurred.
Saving static references to loggers can prevent context-based logging configurations from functioning correctly. Avoid static loggers, especially in libraries.

In the Real World

Most projects are migrating to SLF4J. You should do the same.
Try to log each error at one place, preferably high in the hierarchy so as to provide more information about the semantics and context of what went wrong.

Think About It

If a System.out.println(…) remains in your code, ask yourself whether it is part of the application's primary purpose to communicate information with the user via the console at this point; if not, replace the System.out.println(…) with a call to a logger method.

Self Evaluation

Why is using System.out.println(…) for logging so problematic?
How is SLF4J different from the other logging frameworks? What benefits does this bring?

References

The logback manual

Learn Clogr

Evolution of Logging in Java

`System.out.println(…)`

Log4j

JUL

Logback

Apache Commons Logging

SLF4J

Log Level

Loggers

Logger Factories

Logging Configuration

Dependencies

Adapters

Bridges

Configuration Files

Setting Log Level

Layouts

Appenders

Clogr

Loggers via Clogr

Setting the Clogr Log Level

Compartmentalized Configurations

Review

Summary

Gotchas

In the Real World

Think About It

Self Evaluation

See Also

References

Resources

Acknowledgements