Solving Your Logging Problems With Logback

Logback is a logging framework for Java applications, created as a successor to the popular log4j project. In fact, both of these frameworks were created by the same developer. Given that logging is a crucial part of any application for both debugging and audit purposes, choosing an adequate logging library is a foundational decision for any project. There are several reasons why Logback is a great choice for a logging framework. In this post, we’ll outline its features and how to use it to its full potential.

Logback’s Core Features & Advantages

• Faster execution compared to log4j.
• Native support for slf4j, which makes it easy to switch to a different logging framework, should that be necessary later on.
• Conditional processing of the defined configuration.
• Advanced filtering capabilities.
• Compression of archived log files.
• Support for setting a maximum number of archived log files.
• HTTP-access logging.
• Recovery from I/O failures.

The Logback project is organized in main 3 modules:

• logback-core – contains the basic logging functionality.
• logback-classic – contains additional logging improvements, such as slf4j support.
• logback-access – provides integration with servlet containers, such as Tomcat and Jetty.

In the following sections, we’ll have a look at how we can make the best use of this library a typical Java application.

Naturally, raw logging is just one aspect of understanding and reacting to the runtime of an application, next to monitoring errors, log management and other techniques that create a more holistic picture of our system.

Basic Setup

To start using the Logback, you first need to add the logback-classic dependency to the classpath. Let’s do that with Maven:

<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.2.3</version>
</dependency>

This single dependency is enough, as it will transitively pull in the logback-core and slf4j-api dependencies.

If no custom configuration is defined, Logback provides a simple, automatic configuration on its own. By default, this ensures that log statements are printed to the console at DEBUG level.

Consequently, you can now obtain a Logger instance and start writing log messages using the default, basic config.

First, you can create a Logger by using the slf4j LoggerFactory class:

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

Next, you can use simply use the typical logging APIs corresponding to the log level you’re looking for:

logger.debug("UserService Test");

Logback Configuration Files

To create a configuration for Logback, you can use XML as well as Groovy. The system will automatically pick up and use the configuration automatically, as long as you’re adhering to the naming convention.

There are three valid standard file names you can choose from:

• logback-test.xml
• logback.groovy
• logback.xml

A note worth understanding here is that Logback will search for these files in this exact order.

Going forward, the examples in this tutorial will rely on an XML based, simple logback.xml file.

Let’s see what a basic configuration equivalent to the default one looks like:

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

This configuration defines a ConsoleAppender with a PatternLayout. Log messages on the console will be displayed at level DEBUG or below, using the defined pattern:

18:00:30.143 [main] DEBUG com.stackify.services.UserServiceTest - UserService Test

An interesting and quite useful feature is that the library can automatically reload configuration files when they’re modified. You can enable this behavior by setting the scan=true attribute:

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

By default, the library scans and reloads files every minute.

To view the configuration log, you can add the debug=true attribute:

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

This can also be quite helpful for development, with it really speeds up identifying potential configuration errors.

Variable Substitution

Logback configuration files support defining and substituting variable values.

Simply put, variables can be defined using <property> or <variable> elements, or loaded from an external file or resource:

<property name="fileName" value="file.log" />
<property resource="application.properties" />

The properties defined in the application.properties file will be defined as properties in the logback.xml file.

Next, you can access a variable using the typical ${} syntax:

<file>${fileName}</file>

Moving forward, let’s take a closer look at each of the main configuration elements, to start putting together more complex, and ultimately more useful configurations.

Appenders

In the Logback architecture, appenders are the elements responsible for writing log statements. All appenders must implement the Appender interface.

Furthermore, each appender corresponds to a certain type of output or mode of sending data. Here are some of the most helpful appenders you can configure:

• ConsoleAppender – writes messages to the system console
• FileAppender – appends messages to a file
• RollingFileAppender – extends the FileAppender with the ability to roll over log files
• SMTPAppender – sends log messages in an email, by default only for ERROR messages
• DBAppender – adds log events to a database
• SiftingAppender – separates logs based on a runtime attribute

Let’s see a few configuration examples for some of these.

The ConsoleAppender

The ConsoleAppender is one of the more basic appenders available in Logback, as it can only log messages to System.out or System.err.

The configuration for this appender usually requires specifying an encoder, as we saw in the basic example config from the previous section.

By default, messages are logged to the System.out, but you can change that using the target attribute:

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    ...
    <target>System.err</target>
</appender>

The RollingFileAppender

Logging to file is naturally the way to go in any kind of production scenario where you need persistent logs. However, if all the logs are kept in a single file, this runs the risk of becoming too large and difficult to wade through. It’s also to make the long-term storage/warehousing of log data very difficult.

That’s when rolling files come in handy.

To address this well-known limitation, Logback provides the RollingFileAppender, which rolls over the log file when certain conditions are met. The appender has two components:

• RollingPolicy – which determines how the rollover is performed
• TrigerringPolicy – which determines when the file is rolled over

To better understand these policies, let’s create an appender which makes use of a TimeBasedRollingPolicy and a SizeTriggeringPolicy:

<appender name="rollingFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>log-%d{yyyy-MM-dd}.log</fileNamePattern>
        <maxHistory>30</maxHistory> 
        <totalSizeCap>3GB</totalSizeCap>
    </rollingPolicy>
    <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
        <maxFileSize>3MB</maxFileSize>
    </triggeringPolicy>
    <encoder>
        <pattern>[%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
</appender>

The TimeBasedRollingPolicy implements both a RollingPolicy and a TriggeringPolicy.

The example above configures the fileNamePattern attribute based on the day – which means the name of each file contains the current date, and also that the rollover will happen daily.

Notice how we’re limiting the log data here – maxHistory is set to a value of 30, alongside a totalSizeCap of 3GB – which means that the archived logs will be kept for the past 30 days, up to a maximum size of 3GB.

Finally, the SizeBasedTriggeringPolicy defined configures the rollover of the file whenever it reaches 3 MB. Of course that’s quite a low limit, and a mature log-viewing tool can certainly handle a lot more than that.

You can now see how we’ve slowly moved out from basic examples to a more realistic configuration you can actually start using as the project moves towards production.

The SiftingAppender

This appender can be useful in situations when you want logs to be separated based on a runtime attribute, such as the user session.

The implementation of this appender relies on creating nested appenders and using one of these for logging depending on a discriminator. The default discriminator used is MDCBasedDiscriminator.

To see this functionality in action, let’s configure a SiftingAppender which separates logs into different files based on the userRole key:

<appender name="roleSiftingAppender" class="ch.qos.logback.classic.sift.SiftingAppender">
    <discriminator>
        <key>userRole</key>
        <defaultValue>ANONYMOUS</defaultValue>
    </discriminator>
    <sift>
        <appender name="fileAppender" class="ch.qos.logback.core.FileAppender">
            <file>${userRole}.log</file>
            <encoder>
                <pattern>%d [%thread] %level %mdc %logger{50} - %msg%n</pattern>
            </encoder>
        </appender>
    </sift>
</appender>

For the discriminator to have access to the userRole key, you need to place it in the MDC (Mapped Diagnostic Context). Simply put, MDC allows you to set information to be later retrieved by other Logback components, using a simple, static API:

MDC.put("userRole", "ADMIN");
logger.info("Admin Action");

This will write the log message in a file called ADMIN.log.

Layouts and Encoders

Now that you’re starting to understand how appenders work and just how flexible and powerful they are, let’s focus on another foundational component in Logback.

The components responsible for transforming a log message to the desired output format are layouts and encoders.

Layouts can only transform a message into String, while encoders are more flexible and can transform the message into a byte array, then write that to an OutputStream. This means encoders have more control over when and how bytes are written.

As a result, starting with version 0.9.19, layouts have been deprecated, but they can still be used for a transition period. If you do still use layouts actively, Logback will print a warning message:

This appender no longer admits a layout as a sub-component, set an encoder instead.

While they’re starting to be phased out, layouts are still widely used and quite a powerful component on their own, so they’re well-worth understanding.

Some of the most commonly used layouts are PatternLayout, HTMLLayout and XMLLayout – let’s have a quick look at these in practice.

The PatternLayout

This layout creates a String from a log message based on a conversion pattern.

The pattern is quite flexible and allows declaring several conversion specifiers – which can control the characteristics of the output String such as length and color and can also insert values into the output String.

Let’s see an example of a PatternLayout that prints the name of the logging thread in green, the logger name with a length of 50 characters and displays the log levels using different colors, with the %highlight modifier:

<appender name="colorAppender" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
        <pattern>%d %green([%thread]) %highlight(%level) %logger{50} - %msg%n</pattern>
    </layout>
</appender>

The output of this configuration shows log lines with the format we defined:

To avoid the deprecated use of layouts, you can also wrap the PatternLayout in an encoder; Logback provides a convenient PatternLayoutEncoder designed for this layout:

<appender name="colorAppender" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
        <pattern>%d %green([%thread]) %highlight(%level) %logger{50} - %msg%n</pattern>
    </encoder>
</appender>

The HTMLLayout

The HTMLLayout displays log data in an HTML table format, to which you can add custom styles.

Let’s configure an HTMLLayout using a LayoutWrappingEncoder to avoid the deprecation:

<appender name="htmlAppender" class="ch.qos.logback.core.FileAppender">
<file>log.html</file>
    <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
        <layout class="ch.qos.logback.classic.html.HTMLLayout">
            <pattern>%thread%level%logger%msg</pattern>
        </layout>
    </encoder>
</appender>

In the example above, the layout is used by a FileAppender to print logs to a log.html file.

Here’s what the content of the HTML file will look like, using the default CSS:

So far, we’ve used in the layout examples the two main encoders available: PatternLayoutEncoder and LayoutWrappingEncoder. The purpose of these encoders is to support the transition from layouts to encoders.

Of course, future versions of Logback will add additional encoders with more powerful capabilities.

Loggers

Loggers are the third main component of Logback, which developers can use to log messages at a certain level.

The library defines 5 log levels: TRACE, DEBUG, INFO, WARN, ERROR; each of these has a corresponding logging method: trace(), debug(), info(), warn(), error().

In previous examples, we’ve seen a configuration of the root logger:

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

This sits at the top of the logger hierarchy and is provided by default, even if you don’t configure it explicitly, with a ConsoleAppender with the DEBUG level.

Let’s now define another logger, with an INFO level, which uses the rollingFileAppender:

<logger level="info" name="rollingFileLogger">
    <appender-ref ref="rollingFileAppender" />
</logger>

If you don’t explicitly define a log level, the logger will inherit the level of its closest ancestor; in this case, the DEBUG level of the root logger.

As you can see, the name attribute specifies a logger name that you can later use to retrieve that particular logger:

Logger rollingFileLogger = LoggerFactory.getLogger("rollingFileLogger");
rollingFileLogger.info("Testing rolling file logger");

What’s interesting here is that you can actually also configure the log level programmatically, by casting to the ch.qos.logback.classic.Logger class, instead of the org.slf4j.Logger interface:

ch.qos.logback.classic.Logger rollingFileLogger 
  = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger("rollingFileLogger");
rollingFileLogger.setLevel(Level.DEBUG);
rollingFileLogger.debug("Testing Log Level");

Parameterized Logging

In some cases, the log message may contain parameters which have to be calculated. But, keep in mind that, if the log level for the message is not enabled, then the calculation is not really necessary.

One way to avoid this and therefore improve performance is to check the log level before logging the message and constructing the parameter:

if (logger.isDebugEnabled()) {
    logger.debug("The bonus for employee: " 
      + employee.getName() + " is " 
      + employeeService.calculateBonus(employee));
}

As you can see, this is simple but can get a bit verbose. Another alternative is to make use of Logback message format:

logger.debug("The bonus for employee {} is {}", 
  employee.getName(), employeeService.calculateBonus(employee));

This format ensures that the logger will first verify is the log level is enabled, and only afterward will it determine and use the value of the parameters in the log message.

Logger Additivity

By default, a log message will be displayed by the logger which writes it, as well as the ancestor loggers. And, since root is the ancestor of all loggers, all messages will also be displayed by the root logger.

To disable this behavior, you need to set the additivity=false property on the logger element:

<logger level="info" name="rollingFileLogger" additivity=false>
   ...
</logger>

Filtering Logs

Deciding what log information gets processed based on the log level is a good way to get started, but at some point, that’s simply not enough.

Logback has solid support for additional filtering, beyond just the log level, This is done with the help of filters – which determine whether a log message should be displayed or not.

Simply put, a filter needs to implement the Filter class, with a single decide() method. This method returns enumeration values of type FilterReply: DENY, NEUTRAL or ACCEPT.

The DENY value indicates the log event will not be processed, while ACCEPT means the log event is processed, skipping the evaluation of the remaining filters.

Finally, NEUTRAL allows the next filters in the chain to be evaluated. If there are no more filters, the message is logged.

Here are the primary types of filters we have available: LevelFilter, ThresholdFilter and EvaluatorFilter.

The LevelFilter and ThresholdFilter are related to the log level, with the difference that LevelFilter verifies if a log message is equal to a given level, while the ThresholdFilter checks if log events are below a specified level.

Let’s configure a LevelFilter that only allows ERROR messages:

<appender name="STDOUT_LEVEL_FILTER_APPENDER" 
  class="ch.qos.logback.core.ConsoleAppender">
    <filter class="ch.qos.logback.classic.filter.LevelFilter">
        <level>ERROR</level>
        <onMatch>ACCEPT</onMatch>
        <onMismatch>DENY</onMismatch>
    </filter>
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
    <target>System.err</target>
</appender>

As you can see, the filter is associated to an appender which outputs the messages to the System.err target.

Similarly, you can configure the ThresholdFilter by specifying the level attribute below which the filter rejects messages:

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

Next, let’s have a look at the EvaluatorFilter, which we can use for more complex conditions.

The EvaluatorFilter

The EvaluatorFilter implements the same decide() method as the two level-based filters above and uses an EventEvaluator object to determine whether a log message is accepted or denied.

There are actually two implementations available:

• GEventEvaluator – contains a condition written in Groovy
• JaninoEventEvalutor – uses a Java expression as an evaluation condition

Both evaluators require additional libraries on the classpath: groovy-all for the first EventEvaluator and janino for the second.

Let’s take a look at how to define a Java-based EventEvaluator.

First, you need the janino dependency:

<dependency>
    <groupId>org.codehaus.janino</groupId>
    <artifactId>janino</artifactId>
    <version>3.0.7</version>
</dependency>

The evaluation condition has access to several objects, among which: event, message, logger, level. Based on these, you can configure a filter using a JaninoEventEvaluator:

<appender name="STDOUT_EVALUATOR_FILTER_APPENDER" 
  class="ch.qos.logback.core.ConsoleAppender">
    <filter class="ch.qos.logback.core.filter.EvaluatorFilter">      
        <evaluator class="ch.qos.logback.classic.boolex.JaninoEventEvaluator">
            <expression>return (level > DEBUG &amp;&amp; 
              message.toLowerCase().contains("employee"));</expression>
        </evaluator>
        <OnMismatch>DENY</OnMismatch>
        <OnMatch>ACCEPT</OnMatch>
    </filter>
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
</appender>

The example above configures a filter that only accepts log messages that have a level higher than DEBUG and contain the “employee” text.

Finally, for more high-level filtering, Logback also provides the TurboFilter class.

The TurboFilter

This filter behaves in a similar way to the Filter class, with the distinction that it’s not associated to a specific appender. Instead of accessing a logger object, it’s connected to the logging context and is invoked for every logging request.

Here’s a simple implementation of this class – the DuplicateMessageFilter:

<configuration> 
    <turboFilter 
      class="ch.qos.logback.classic.turbo.DuplicateMessageFilter">
        <AllowedRepetitions>2</AllowedRepetitions>
    </turboFilter>
</configuration>

This configuration only allows 2 repetitions of the same log message (meaning 3 instances of it) and eliminates all subsequent ones.

Conditional Processing of Configuration Files

Logback supports <if>, <then>, <else> elements which control whether a part of the configuration is processed or not. This is a unique feature among logging libraries and requires the previously mentioned janino library.

To define the conditions evaluated to control the processing of configuration, you can use the Java language. Furthermore, the expressions only have access to context or system properties.

A common use case is enabling different configuration on different environments:

<property scope="context" resource="application.properties" />
<if condition='property("env").equals("dev")'>
    <then>
        <root level="TRACE">
            <appender-ref ref="STDOUT" />
        </root>
    </then>
</if>

This example configures the root logger to display messages of all levels to the console, but only for the development environment, defined through an env=dev property in the application.properties file.

Extending Logback

Beyond the many features that Logback already contains, its architecture allows for the possibility of creating custom components that you can use in the same way as the default ones.

For example, here are several ways you can extend Logback’s functionality:

• create a custom appender by extending the AppenderBase class and implementing the append() method
• create a custom layout by subclassing the LayoutBase class and defining a doLayout() method
• create a custom filter by extending the Filter class and implementing the decide() method
• create a custom TurboFilter by extending the TurboFilter class and overriding the decide() method

The configuration of the custom elements is the same as that of the standard elements.

Let’s define a custom TurboFilter that will ignore all log messages of a specific logger:

public class IgnoreLoggerFilter extends TurboFilter {
    private String loggerName;

    @Override
    public FilterReply decide(Marker marker, Logger logger, 
      Level level, String format, Object[] params, Throwable t) {
        if (loggerName == null) {
            return FilterReply.NEUTRAL;
        } else if (loggerName.equals(logger.getName())) {
            return FilterReply.DENY;
        } else
            return FilterReply.NEUTRAL;
    }
    public void setLoggerName(String loggerName) {
        this.loggerName = loggerName;
    }
}

The logger that the filter will ignore is specified through the loggerName property.

Next, you can easily configure the custom filter:

<turboFilter class="com.stackify.logging.IgnoreLoggerFilter">
    <LoggerName>colorLogger</LoggerName>
</turboFilter>

Conclusion

You have a number of options to chose from when it comes to logging in the Java ecosystem. Out of all of these, Logback is certainly a great choice and a very powerful library. It also brings several improvements over log4j, such as better overall performance, more advanced filtering possibilities, automatic reloading of configuration files, automatic removal of archived log files and many other advanced and useful features. And, due to the native slf4j support, we also have the unique option to easily switch to a different logging library at any point, if we want to. Overall, the maturity and impressive flexibility of Logback have made it the go-to option next to Log4J2, for most of the Java ecosystem today.

Take a look at some of the most common and most detrimental practices that you can run into when making use of logging in a Java application.