Java University – Logging in Java (1/2)

Logging in an application has become mandatory, yet we had to wait until java 1.4 to see a native logging library packaged with the default JDK. Obviously, people did not wait for Java 1.4 to start coding their own logging libraries. This article aims to teach you the general purposes of loggers in Java, a comparison between the most known and a basic overview of how to use them. For detailed instructions about how to use the loggers, you can check part 2.

Features expected from loggers

I will start with describing what is expected from a logging library in Java. I mean, we always could have outputted messages using the System.out and System.err. Besides, in most web application servers, these console outputs are forwarded to a file. But actually, we expect a lot more from a logger. We need more logging levels then just “out” and “error”.
Indeed, in logging libraries, there are several levels, the most common are FINE, DEBUG, INFO, WARN, ERROR and FATAL, ordered by verbosity from the less important to the more important. Thanks to this levels, we can start an application with a certain level, and filter every messages from a lower, less important level. For instance, we could start a web application on WARN, we will then only messages outputed by the WARN, ERROR and FATAL levels. Messages from lower levels will be just dropped. Also, we may need to start the application with a general level on WARN and set the level of the io.resourcepool package on DEBUG.
Loggers also provide us a way to customize the way messages are logged using a templating system. We can choose to output the time with or without the date, the current thread, the class and method called, etc.
Moreover, using just a single line of code, we can log in multiple places. It is possible to make the following line output the message in the console and in a debug.log file.

    LOGGER.debug("My first logger!");

Everything can be configured inside a file. This file is usually externalized to leave the user the choice of his logging preferences.
To sum it up, we want loggers with a lot of great features and the lowest overhead possible.

Java loggers history

There are now a lot of java logging libraries to choose from. To understand the pros and cons of each, we need to check how we got here. Log4j was the first logging library to become a reference. But other logging libraries were born around the same time. The multiplication of logging libraries become quickly a problem. Indeed, if you added a dependency which was using another logging library than yours, you had to deal with it and configure this other library. And that was the same story for every different logging libraries you were adding to your project.
In 2002, Java 1.4 got released and brought a native logging library : java.util.logging (JUL). However, it was a bit late… Its logging levels are a different from what we can find in most of the loggers : FINEST, FINER, FINE, CONFIG, INFO, WARNING, SEVERE.
What could unlock the issue is the release of Jakarta Commons Logging (JCL) from apache. The difference between commons-logging and the other libraries is that commons-logging only bring a logging API. It cannot work on its own, it needs an implementation. Concretely, it forces you to code against an interface which will redirect the logs to the concrete implementation. It is then the implementation that will know where to output the message (if it needs to be outputed at all), how to format it, etc. We could then use JCL forwarded to log4j or JCL forwarded to logkit. Actually, log4j and logkit are just runtime dependencies, the compilation is made against JCL.
Well, the logging implementation was really just up to the user.

Comparison between logging API

Jakarta Commons Logging

Jakarta Commons Logging (JCL) was the first logging API in java to be greatly used. It is still vastly used, for example, Spring uses it. Because of it, we may think that the library is the best available.
As far as Spring is concerned, they are using JCL for historical reasons. If they could change the logging library, they would. This is weird, we were just saying that coding against an API makes you free to choose your implementation, so why would we not want to use JCL? Besides, an API has not much work to do, as it is forwarding everything to the implementation. This is bad luck, we can spot two big drawbacks only in the JCL API.
The first one is the way JCL discover the implementation it has to use. Indeed, as I said, JCL is only an API and it needs to find its implementation. This discovery can only be done at runtime and is causing a lot of issues with the classloader. If you are interested to know exactly what the problem is, you should read this article.
The second issue is due to an overhead. Look at the following code:

    private static final Log LOG = LogFactory.getLog(TestLogger.class);
    LOG.debug("Total price is: " + totalPrice + " " + currency);

It is important to note that even if the debug mode is disabled, this line will consume CPU time. The most costly part is the String concatenation. The same String which will be dropped if debug is disabled. Actually, JCL provides a check to overcome the problem:

    if (LOG.isDebugEnabled()) {
       LOG.debug("Total price is: " + totalPrice + " " + currency);
    }

Now the overhead is only on checking a boolean which is close to zero. The drawback I can see, we made it from 1 line of code to 3. Imagine using it on a whole project, it is not very conveniant…

To use JCL within a Maven project:

<dependency>
    <groupId>commons-logging</groupId>
    <artifactId>commons-logging</artifactId>
    <version>1.2</version>
</dependency>

Simple Logging Facade for Java (SLF4J)

As the name suggests, Simple Logging Facade for Java (SL4J) is also a logging API. This API brings a lot of new advantages. First, let me tell you that the developer from log4j is the one that started the SLF4J project. Thus, he had some experiences about logging libraries!
Ok let’s get back to JCL and check what was wrong. Firstly, SLF4J does the binding at compile time! The biggest flaw in JCL is now fixed. I will quickly explain what was the problem and how SLF4J fixed it. SLF4J is said to do a static binding (or early binding) whereas JCL does a dynamic binding (or late binding). Let’s imagine that JCL calls a getImplementation() method on some object. If we are calling a non static method on an object, because of the polymorphism, the real method to be called can only be known at runtime. SLF4J does the binding by calling a static method on a class, thus the binding can be done at compile time!
Now we may wonder how an API can do a static binding on an implementation. This is actually easy, if you look at the StaticLoggerBinder class, we can see a static method called getSingleton(). This is the method which will return the real logging implementation. This method will actually construct a new StaticLoggerBinder(). To be sure to have the right implementation of the loggers, we need to be sure to only have one implementation of SLF4J within the classpath. Only one, be at least one too! In earlier SLF4J versions, forgetting to put an implementation would result in a ClassNotFoundException. With recent versions, we just get a nice message saying:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

Ok, we fixed one JCL issue, what about the second. SLF4J provides a formatter which works using substitution. Our previous example could be rewritten like this:

        private static final Logger LOGGER = LoggerFactory.getLogger(TestLogger.class);
        LOGGER.debug("Total price is: {} {}", totalPrice, currency);

The {} act as placeholders for the parameters. Now the second problem which was the concatenation overhead is fixed too. We do not have to call the isDebugEnabled() method has there are no concatenation taking places. By the way, notice how the APIs look alike.

To use SLF4J within a Maven project:

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.12</version>
</dependency>

Comparison between logging libraries

Before starting the comparison, you need to know, I will only discuss about them as an implementation of the SLF4J API. Indeed, SLF4J provides bridges from and to other implementations or even APIs. For instance, there is a bridge allowing to redirect log4j to SLF4J or JCL to SLF4J, etc. and the redirect can go both ways ! This way, if you want to drop SLF4J and go back to JCL, you can forward SLF4J to JCL. These bridges work by replacing the logging classes. If we want to forward log4j to SLF4J, we need to delete the log4j jar from the classpath and replace it with the log4j-over-slf4j. Here is the official page listing all the bridges available.

Fonctionnement des bridges avec SLF4J
How SLF4J bridges are working

java.util.logging JUL

This is the JDK library packaged with the JDK 1.4 in 2002. Actually, JUL is quite an exception about the rule I just said. Indeed, producing a bridge for JUL is quite complex: we cannot just drop the jar from the classpath as it is part of the JDK. SLF4J provides a bridge anyway, but it comes with a massive overhead and it is not recommended to use it. For this exact same reason, it is not recommended to use this logging library as you are basically coercing people into using JUL. The only reason I can see to use JUL is if you are working on a project with a limit on the number of dependencies.

        private static final Logger LOGGER = Logger.getLogger(TestLogger.class.getName());
        LOGGER.log(Level.INFO, "Total price is: {0} {1}", new Object[] { totalPrice, currency });

As we can see, on one hand, the JDK also overcomes the concatenation issue. On the other hand, the syntax to log is a bit inconvenient.

Log4j version 1.x

Log4j was the first library to be widely used. The advantages? Almost everyone has already used it. The advantages on new projects? If we do not mind spending some minutes to learn how to use another implementation, I would say there are none. The project has been forsaken by apache for a while (the last feature was added in 2007) and it has been known to have some memory leaks. Also, the migration from log4j 1.x to log4j2 has been made easy.

To use log4j 1.x in Maven project:

<dependency>
    <groupId>log4j</groupId>
    <artifactId>log4j</artifactId>
    <version>1.2.17</version>
    <scope>runtime</scope>
</dependency>

Logback

Logback is the reference implementation of SLF4J. It has been designed by the log4j developer. He is the one naming different reasons to drop log4j 1.x and switch to SLF4J with logback. To quickly sum up the pros: logback is more performant, has a lot of tests, speak natively the SLF4J API and thus does not need any bridge, moreover, logback can recover from write errors. With log4j 1.x, if you remove or modify a file the logger is using, log4j will never recover and you will not be able to see any more logs. Besides, logback brings some features not available to other loggers. For instance, the prudent mode. This mode allows multiple loggers to write to the same file without losing any messages. This is achieved by using lock on file, which adds an overhead. This is disabled by default. Logback allows an HTTP access to logs on Tomcat and Jetty servers.

To use logack in Maven project:

<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-core</artifactId>
    <version>1.1.3</version>
    <scope>runtime</scope>
</dependency>

Log4j2 alias log4j in version 2.x

Log4j version 2.0 has been released in July 2014. This version aims to fix every log4j 1.x reproaches. To start with, log4j2 is sold in two parts: log4j-api and log4j-core. It is possible to use log4j-api in place of SLF4J. I would not recommend this as the API is very recent and I (still) have not found something that log4j-api can do and that SLF4J cannot do. Moreover, there is a bridge which can forward SLF4J to log4j2. SLF4J being widely spreads on a lot of projects, I would recommend to stick with it.

Fonctionnement des bridges sur log4j2
How log4j2 bridges are working

Let’s talk about log4j-core, the implementation of log4j2. Log4j2 was released after logback, it could thus pick a lot of advantages and improvements from it. The reproach made to logback is the possible loss of logs during loggers reconfiguration.
One great feature brought by log4j2 is the AsyncLogger. This logger can log messages in a non-blocking way. Actually, it adds the event to a queue, that will be dequeued by another thread. If we only speak about performance, this is currently the fastest implementation. Why is this logger faster than the other? Actually it uses a queue implementation named LMAX Disruptor. This library can be used to do inter-thread communication without lock. Take special care as the disruptor library is an optional dependency of log4j2, you need to add it to your classpath explicitly (minimum version 3.0.0)!

To use log4j2 in a Maven project:

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-api</artifactId>
    <version>2.2</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.2</version>
    <scope>runtime</scope>
</dependency>

<!-- If we want to use AsyncLoggers -->
<dependency>
    <groupId>com.lmax</groupId>
    <artifactId>disruptor</artifactId>
    <version>3.3.2</version>
    <scope>runtime</scope>
</dependency>

Leave a Comment