Adding Logback to a Maven Project

If you have written a Java project, maybe using Eclipse as IDE, but fundamentally using Maven as build manager, and you ask yourself how to add dependencies to it and, even more importantly, how to tell Maven to include your dependencies in the resulting jar, making it "fat" but also so more easily usable. This post was for you.

I used Logback as sample library, but the story is the same any dependency you are putting in your app.

Unfortunately it aged badly, so I had to ditch it.

Still, I decided to rewrite it and I put the new version in my other blog. Follow the link if interested in it. https://thisthread.blogspot.com/2020/05/jar-with-dependencies-through-maven.html

Go to the full post

Spring log only to file

Logging is one of the most fuzzy area in Java. The standard JUL, java.util.logging, entered the arena late, and it has to compete against well respected libraries like Log4J2, SLF4J and Logback (usually SLF4J with Logback). The Spring guys decided to go for JCL, the Apache Commons Logging, that wraps SLF4J for the actual logging library of your choice, here being Logback.

If you don't have any special requirement, you can happily ignore which actual logger is used, just write your code for the JCL interface, leaving out of your scope any low level dependency.

However, if you want your log going to a file, and not to console, as often is the case, you have to deal with the actual logger. Not a big deal, if Logback is your choice.

Let's modify the function greeting in my GreetingController to log some (un)useful comments:

public String greeting() {
 log.trace("trace hello");
 log.debug("debug hello");
 log.info("info hello");
 log.warn("warn hello");
 log.error("error hello");
 log.fatal("fatal hello");
 return "Hello!";
}

Where log is private static final object of type org.apache.commons.logging.Log initialized through the JCL LogFactory.

This could be enough. Still you should have a mildly surprising output, something like:

2016-05-30 22:14:00.888  INFO (...)  : info hello
2016-05-30 22:14:00.888  WARN (...)  : warn hello
2016-05-30 22:14:00.888 ERROR (...)  : error hello
2016-05-30 22:14:00.888 ERROR (...)  : fatal hello

I edited out details in the middle of the lines, I want to focus on the fact that we miss trace and debug messages, and the fatal one became an error one. If you really want fatal log messages, logback is not your choice, since it does not have this log level, and so they are mapped as simple errors.

The first problem could be easily solved adding an entry in the Spring application.properties file (in source/main/resources). Say that I want to log all messages, from trace up to fatal, generated in my packages rooted in dd.manny. I'll add this line:

logging.level.dd.manny=trace

Good. Now I want Spring to log to a file. By default the file will have name spring.log, and I can decided in which folder to be placed like this:

logging.path=/tmp

Nice and easy. Just one thing. I wanted the log to go exclusively to file. To get this effect I have to configure the actual logger.

For this reason I added a logback configuration file in the src/main/resources folder that is mimic of the default Spring one, but it has no appender for console. The key point is that I keep the log level to INFO and I specify FILE as appender, that is going to be set through the property specified above.

The full Spring Boot project is on github. The relevant files are GreetingController.java, application.properties, and logback.xml.

Go to the full post

Improved SLF4J simple logging

I have written in the past a few introductory posts to SFL4J based on version 1.6.4 that are now obsolete (as Peter correctly pointed out). Here I consider mainly that, since version 1.6.6, SLF4J SimpleLogger supports configuration properties. This makes more attractive the SimpleLogger usage, at least for a tiny project, or for early stages of development.

The process of installing SLF4J has not changed at all in this time, you should go to the official SLF4J download page, fetch the latest package available (currently version 1.7.5), extract the content in your preferred local directory. If, for any reason, you need a previous version, you could go and fetch it from the SLF4J repository.

I have written a tiny two-class Java application to check logging at work. The main class, named Hello, does some logging and then create an object of the other class (that I named Another):

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Hello {
  public static void main(String[] args) {
    Logger logger = LoggerFactory.getLogger(Hello.class);

    logger.info("an info message");
    try { Thread.sleep(472); } catch(Exception e) {}
    logger.error("an error message");
    try { Thread.sleep(123); } catch(Exception e) {}
    logger.trace("a trace message");
    try { Thread.sleep(42); } catch(Exception e) {}
    logger.warn("a warn message");
    try { Thread.sleep(105); } catch(Exception e) {}
    logger.debug("a debug message");

    new Another();
  }
}

The other class, Another, is even simpler:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Another {
  public Another() {
    Logger logger = LoggerFactory.getLogger(Another.class);
    logger.info("an info message");
    logger.error("an error message");
  }
}

To build these classes, you need to put in classpath the SLF4J API jar, named slf4j-api-1.7.5.jar (version number may vary).

The minimal configuration to run my application requires to see the same SLF4J API jar in its classpath. Forgetting it leads to a java.lang.NoClassDefFoundError for org/slf4j/LoggerFactory. Otherwise you would get a friendly warning from SLF4J, that could be translated "You didn't say where I should send your log, so I would just swallow your messages, sending them to the NO-OP plugin. If this is not the behavior you expected, you'd better check the documentation":

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 (...)

And if you check the documentation, you would see that you have to put in the classpath another jar, that would determine how the logger should behave.

The NOP implementation is contained in slf4j-nop-1.7.5.jar, if you put this jar in the classpath, you will get the same result as above (nothing logged), without the showed reminder.

If you want SLF4J to delegate to JUL the logging, you should put slf4j-jdk14-1.7.5.jar in the classpath. JUL is the standard Java Logger, (java.util.logging is its package name), included in the JDK since version 1.4, and the SLF4J plugin used in this case acts as a bridge to that log implementation. For my example, I get this output:

Apr 19, 2013 8:18:45 PM Hello main
INFO: an info message
Apr 19, 2013 8:18:46 PM Hello main
SEVERE: an error message
Apr 19, 2013 8:18:46 PM Hello main
WARNING: a warn message
Apr 19, 2013 8:18:46 PM Another 
INFO: an info message
Apr 19, 2013 8:18:46 PM Another 
SEVERE: an error message

Let's finally see what I get if I put in the classpath slf4j-simple-1.7.5.jar, the SLF4J simple logging plugin.

[main] INFO Hello - an info message
[main] ERROR Hello - an error message
[main] WARN Hello - a warn message
[main] INFO Another - an info message
[main] ERROR Another - an error message

In square brackets we have the thread name, then we see the log level, then the logger name, and finally the log message.

The interesting part is that now we can specify a file, named simplelogger.properties, where we could set some configuration variables. More details in the official SLF4J documentation, but let's see a sample configuration file, and which is its impact on the log generation:

#default is System.err
#org.slf4j.simpleLogger.logFile = simple.log

#trace, debug, info, warn, error - default is info
org.slf4j.simpleLogger.defaultLogLevel = trace

org.slf4j.simpleLogger.log.Another = error

#default is false
org.slf4j.simpleLogger.showDateTime = true

#default is milliseconds since startup
org.slf4j.simpleLogger.dateTimeFormat = HH.mm.ss:SSS

#default is true
org.slf4j.simpleLogger.showThreadName = false

If we specify the org.slf4j.simpleLogger.logFile property, the log is redirected to the file named in that way. By default the special name System.err is used, that is a placeholder for the standard error console.

The default loglevel is info, meaning only info and above are usually logged, but we can change it setting the org.slf4j.simpleLogger.defaultLogLevel property. Here I say that I want to see all the logging (being trace the lowest available level).

I can set the loglevel for a specific class (or package), setting a org.slf4j.simpleLogger.log.* property. Here you can see that for the class Another I want to dump only the top level log messages (namely, errors).

Usually date/time is not shown in the log, to have it we should specify that org.slf4j.simpleLogger.showDateTime is true.

If we don't specify the date/time format, and we specify that we want it showed, we see the number of milliseconds from the application startup. The org.slf4j.simpleLogger.dateTimeFormat is used to specify a different format. Here I ask for the its time as hour-minute-second:milliseconds.

If I don't care of the thread name, I can say that I don't want it to be logged, setting the org.slf4j.simpleLogger.showThreadName to false.

With such a simplelogger.properties, the resulting log is something like:

20.51.11:015 INFO Hello - an info message
20.51.11:488 ERROR Hello - an error message
20.51.11:612 TRACE Hello - a trace message
20.51.11:654 WARN Hello - a warn message
20.51.11:760 DEBUG Hello - a debug message
20.51.11:761 ERROR Another - an error message

Go to the full post

ActiveMQ 5.5 and SLF4J 1.6

Working on a simple Hello World example for ActiveMQ, I bumped in a conflict between this Apache Message-Oriented-Middleware (MOM) and the SLF4J logging system. It is nothing serious, but I guess it is worth to enter in some detail on this issue.

SLF4J is the used as logger by ActiveMQ. Unfortunately, still in version 5.5, the SLF4J bundled version is 1.5, that's a pity, because starting from SLF4J version 1.6 if you place no binder in your application classpath, the NOP logger is assumed. The effect is that all your log goes to a logical respective of /dev/null, as to say, it disappears in thin air. That's no fun, but better than the behavior of 1.5: crashing miserably with an error like this:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for
 further details.
Exception in thread "main" java.lang.NoClassDefFoundError: 
    org/slf4j/impl/StaticLoggerBinder
        at org.slf4j.LoggerFactory.getSingleton(LoggerFactory.java:230)
...

So, you really have to plug in a binder. I already had at hand a 1.6 plugin, I tried to used it, but I got another error:

SLF4J: The requested version 1.6 by your slf4j binding is not compatible
 with [1.5.5, 1.5.6, 1.5.7, 1.5.8, 1.5.9, 1.5.10, 1.5.11]

No compatibily.

There are a couple of solution to this issue. Or you use a plugin for that specific version, or you put the SLF4J API jar of your choice in your classpath before the ActiveMQ full jar.

I opted for the second choice, and my classpath is now referring to these jar - in this order:

• slf4j-api-1.6.4.jar
• activemq-all-5.5.1.jar
• slf4j-simple-1.6.4.jar

Actually, the SLF4J plugin could be in any place, but it is crucial that the API SLF4J jar is before the ActiveMQ one.

Go to the full post

Logback filters

Filtering could be a complicated matter, the official Logback documentation would give you a detailed introduction to the subject, but I guess it can be useful having a more limited view on a few basic features.

We can specify the lower level accepted to log in a logger element (including the root element) setting its level attribute. For instance, if we want to log everything from trace up we specify "trace" as level for the root element:

<root level="trace">

A threshold filter could be used to skip from logging any message with a severity higher than the specified level. In this example a console appender is filtered to show only up to info messages:

<appender name="CApp" class="ch.qos.logback.core.ConsoleAppender">
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter"> 
        <level>info</level>
    </filter>
    ...

We can filter so that only messages with a specified severity are logged. This filter accepts only warning messages and discard all the others:

<filter class="ch.qos.logback.classic.filter.LevelFilter">
    <level>WARN</level>
    <onMatch>ACCEPT</onMatch>
    <onMismatch>DENY</onMismatch>
</filter>

For more complex filtering we can create a custom filter and refer to it in our configuration file.

If we want to log only INFO, but just the ones among them containing the "hello" text in it, we could define a MyFilter class like this:

package test;

import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.filter.Filter;
import ch.qos.logback.core.spi.FilterReply;

public class MyFilter extends Filter<ILoggingEvent> {
    @Override
    public FilterReply decide(ILoggingEvent event) {
        if(event.getLevel() != Level.INFO)
            return FilterReply.DENY;

        if (event.getMessage().contains("hello"))
            return FilterReply.NEUTRAL;
        return FilterReply.DENY;
    }
}

In our configuration file we refer to it:

<filter class="test.MyFilter">

This approach keeps the XML configuration file simple, delegating the filtering logic to a custom Java class. On the other side, the configuration file gets a bit more obscure - at first sight it is not clear what the filtering is actually doing.

When the filtering rule is very simple, it won't probably make much sense using this approach, maybe a couple of filters in the XML configuration would be a better solution.

Go to the full post

Loggers and appenders

After performing some basic Logback configuration, we can see how to set appenders and loggers, so that Logback could send its output both to console and a file, specifying a different behavior in different classes.

We have already know how to use an appender to send output to the console, now we see how to create a file appender, and also how to create a configuration logger, to describe a relation between a SLF4J logger, as defined and used in our code, and an appender.

Here is an XML Logback configuration file:

<configuration debug="true">
  <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />
  <appender name="CApp" 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="FApp" class="ch.qos.logback.core.FileAppender">
    <file>TestLogback.log</file>
    <encoder>
      <pattern>%date %level [%thread] %logger{10} [%file:%line]: %msg%n</pattern>
    </encoder>
  </appender>
  <logger name="test.TestLogback" level="info">
    <appender-ref ref="FApp" />
  </logger>
  <root level="trace">
    <appender-ref ref="CApp" />
  </root>
</configuration>

You see that this configuration file is set to be in debug mode, and it has a status listener element set to output its feedback to the standard console. More on Logback configuration debug in the previous post.
Same for the CApp appender, console appender already seen in the previous post.
The FApp appender is a FileAppender. We specify its name and the format internally used.
The logger element works like a root element, the biggest difference is due that root does not need a name, while a logger has to provide it, to be used by the SLF4J logger factory to retrieve the settings.
We can specify the additivity attribute in the logger, defaulted to true, if not explicitly set to false, it means that this logger uses the appenders specified by its ancestors (if any) and adds the one(s) specified in this element's belly. False means that all the existing appenders are discarded and only the one specified there are used.
The logger level is explicitly set to "info", this logger and all the ones on hierarchy below are affected by this.

We can get the same result by a groovy configuration file:

import static ch.qos.logback.classic.Level.DEBUG
import static ch.qos.logback.classic.Level.INFO
import ch.qos.logback.classic.encoder.PatternLayoutEncoder
import ch.qos.logback.core.status.OnConsoleStatusListener
import ch.qos.logback.core.ConsoleAppender
import ch.qos.logback.core.FileAppender

statusListener(OnConsoleStatusListener)

appender("CApp", ConsoleAppender) {
  encoder(PatternLayoutEncoder) {
    pattern = "%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36}: %msg%n"
  }
}

appender("FApp", FileAppender) {
  file = "TestLogback.log";
  encoder(PatternLayoutEncoder) {
    pattern = "%date %level [%thread] %logger{10} [%file:%line]: %msg%n"
  }
}

logger("test.TestLogback", INFO, ["FApp"])
root(DEBUG, ["CApp"])

The lack of semicolons at the end of lines is a perlish Groovy variation on Java syntax.

Go to the full post

Autoscanning Logback configuration

A reason for breaking the decoupling between SLF4J and the underlying concrete logging framework is for changing the current log configuration without having to restart the application.

Logback has a feature that could be used to get a similar result leaving all the configuration stuff in a file. The idea is specifying in the configuration if Logback has to check again the configuration file and, if a change is detected, reload the properities.

This is achieved adding a couple of attributes to the configuration element for XML files (scan="true" scanPeriod="30 seconds" in my case, where I wanted to rescan the file each half minute - default value for scanPeriod is one minute).
For Groovy configuration we just have to add A call to scan("30 seconds").

I had a bumpy beginning of a relation with this feature, I couldn't make it work. But this was a good way to keep in touch with the internal Logback debug setting to get information on what was going.

Here is the XML configuration file that I used to test the autoscanning feature:

<configuration scan="true" scanPeriod="30 seconds" debug="true">
  <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />
  <appender name="capp" class="ch.qos.logback.core.ConsoleAppender"> 
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"> 
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{40}: %msg%n</pattern> 
    </encoder> 
  </appender>
  <root level="all"> 
    <appender-ref ref="capp" /> 
  </root> 
</configuration>

The configuration element has three attributes, the first two ones for scanning and the third, named "debug", set to true, to let Logback giving debug feedback. I couldn't find how I could do the same in a Groovy configuration file (if someone knows, please, drop a comment).
Then I added a statusListener element specifying as associated class the one to send output to the standard console, and that was it.

Go to the full post

Configuring Logback

At startup Logback checks if there is a configuration file in the application classpath. First choice is logback.groovy, logback-test.xml and logback.xml are the fallback options. If none of these files is available, a default configuration is used, and the output is sent to standard console.

Here is an XML configuration file that would give a result close to the default.:

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

The appender element describes a logging destination. Here the standard output console is used.
In the appender element is defined its associated encoder, where we define the pattern we want to use in the log generation.
The pattern describes a string where the first field is the time of current log line generation, the second is the thread name where the log was generated, the third is the log level, fourth is the logger name (with the max number of significative character that should be used - twelve is unreasonable low, but it could make sense in such a silly test). Finally we have the log message itself and a newline. The resulting pattern is very close to the default one.
The root element describes the root logger, that has a log level set to trace (instead of the default debug). The appender element inside root is where we can specify which appender (here CApp) should be used in this context.

It is easy to rewrite the same configuration with Groovy:

appender("CApp", ch.qos.logback.core.ConsoleAppender) {
    encoder(ch.qos.logback.classic.encoder.PatternLayoutEncoder) {
        pattern = "%d{HH:mm:ss.SSS} [%thread] %-5level %logger{12}: %msg%n"
    }
}
root(ch.qos.logback.classic.Level.TRACE, ["CApp"])

Similar structure, less verbose, and much more flexibility. The only issue is that we need Groovy in the application classpath.

Go to the full post

Breaking SLF4J decoupling

The main reason to use SLF4J as façade to the logging framework that we actually use is to decouple our Java application to the concrete logging system. That means that usually we won't make from our application any assumption on which actual logger framework is in the background.

But sometimes we need a more pragmatic approach. Besides, if we are using Logback, maybe we are not even interested in portability, and we are using SLF4J as interface because Logback is built to work in this way.

The need of changing the log level programmatically is one of those tasks that requires to delve in the actual logging framework details. It is not a common task, we usually prefer to use a configuration file, but maybe we can't afford to stop and start our application, so we have to be more creative than usual.
The SLF4J Logger does not have any visibility on it, we have to go down to the real logger object.

Firstly, let's write an utility method to check the current log level:

void checkLogging() {
    if(log.isTraceEnabled())
        System.out.println("Log trace enabled");
    else if(log.isDebugEnabled())
        System.out.println("Log debug enabled");
    else if(log.isInfoEnabled())
        System.out.println("Log info enabled");
    else if(log.isWarnEnabled())
        System.out.println("Log warn enabled");
    else if(log.isErrorEnabled())
        System.out.println("Log error enabled");
    else
        System.out.println("Log disabled");
}

The member variable log is defined in this way:

private static final Logger log = LoggerFactory.getLogger("test.TestLogback");

If this does not look clear to you, you could have a look to my previous post on how to set up a Java application to work with SLF4J and Logback.

We could change the logger level only for one specific logger, but here we changes the root logger level, to show, as a bonus, how the log level on an ancestor impacts on the current one when, as in this case, no specific log level is specified in the configuration file for it:

checkLogging(); // 1

org.slf4j.Logger sl = LoggerFactory.getLogger("root"); // 2
if(sl instanceof ch.qos.logback.classic.Logger) { // 3
    ch.qos.logback.classic.Logger cl = (ch.qos.logback.classic.Logger)sl; // 4

    cl.setLevel(Level.ALL); // 5
    checkLogging(); // 6

    cl.setLevel(Level.ERROR); // 7
    checkLogging();

    cl.setLevel(Level.OFF); // 8
    checkLogging();
}

1. The default log level for a Logback logger is debug.
2. The object returned is an SLF4J Logger, I defined it showing its class full name to stress this fact.
3. It comes handy here that Logback implements the SLF4J interfaces. To ensure that the concrete logging framework is Logback, we can just check the actual type of the logger retrieved from the logger factory.
4. We safely downcast the logger to the Logback specific type.
5. Enabling full logging for the root logger.
6. Root is an ancestor of any logger, our current logger, and no intermediate one, has explicitly set its log level, so the change of the root log level reflects directly on it.
7. Another change in root (and descendants) log level.
8. Log is disabled.

If you assemble this code in a your application you should get the same output I got:

Log debug enabled
Log trace enabled
Log error enabled
Log disabled

Go to the full post

Logback setup

Logback has been created to be the log4j successor, and designed as a native implementation of the SLF4J API - at least in its "classic" flavor. Its strong relation to SLF4J makes it probably the most interesting logger framework to couple with SLF4J.

It is easy start working with Logback. Once you have set SLF4J up in your developing environment, you have tested it with its native simple logger and maybe also with JUL, the JDK standard logger, Logback will be just a piece of cake.

Here is a minimal application that logs a message and then terminates:

package test;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class TestLogback {
    private static final Logger logger = 
        LoggerFactory.getLogger("test.TestLogback");

    public static void main(String[] args) {
        logger.debug("Hello from Logback.");
    }
}

I forgot to mention that slf4j-api-1.6.4.jar should be in the application classpath. If that was missing, you can't expect more than a spectacular failure:

Exception in thread "main" java.lang.NoClassDefFoundError: org/slf4j/LoggerFactory
at chapters.introduction.HelloWorld1.main(HelloWorld1.java:23)
Caused by: java.lang.ClassNotFoundException: org.slf4j.LoggerFactory
at java.net.URLClassLoader$1.run(Unknown Source)
at java.security.AccessController.doPrivileged(Native Method)
at java.net.URLClassLoader.findClass(Unknown Source)
at java.lang.ClassLoader.loadClass(Unknown Source)
at sun.misc.Launcher$AppClassLoader.loadClass(Unknown Source)
at java.lang.ClassLoader.loadClass(Unknown Source)
... 1 more

Adding that jar to the classpath is not enough, though we have a slight improvement. SLF4J complains about no concrete framework available to do the real job:

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.

Not knowing what to do, it defaults to the native no-logging plugin. Well, better than crashing.

We have to add to the application classpath another couple of JARs, Logback specific. To get them, we go to the Logback download page, download its compressed file (current latest version is 1.0.0) and expand it on your file system. The files we need to add to our classpath are logback-core-1.0.0.jar and logback-classic-1.0.0.jar.

The "classic" Logback JAR acts as a SLF4J plugin, working as an adapter from the SLF4J logging calls to the "core" Logback functionality. If no "core" is available, trying to run the application results in a crash:

Failed to instantiate SLF4J LoggerFactory
Reported exception:
java.lang.NoClassDefFoundError: ch/qos/logback/core/joran/spi/JoranException
at org.slf4j.LoggerFactory.bind(LoggerFactory.java:128)
at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:108)
at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:279)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:252)
(...)

The SLF4J LoggerFactory was trying to instantiate the Logback logger, but in the middle of its job it found out that there was something missing in it, and so it had to (brutally) reject the request.

Go to the full post

Not logging could be expensive

We don't mind to pay a fair price in terms of execution time and storage when logging. But if we still have to pay a substantial price even when the logging is off, we could start to wonder about the quality of our logging system.

In the C/C++ world is relatively easy to keep such unwanted cost limited, using low level mechanism as macros and defines. Things are less immediate in the Java world, still we can achieve good results, if the logger is designed properly, as SLF4J shows.

There is a tiny cost that we can't avoid to pay for each logging call, regardless if the logging is currently enabled for the severity associated to the message or not, and that is the actual cost to check it. It looks quite unavoidable, if we want to keep the log configurable at execution time, and in any case it is just a cheap read and compare operation, so we could usually live with it.

But let's think to a case like this:

SomeComplicatedStuff scf;
// ...
log.debug("The value is: " + scf);

SomeComplicatedStuff is some class that provides an expensive toString() method. We don't mind to pay for its huge cost when debugging, but notice that firstly we build the message, implicitly calling SomeComplicatedStuff.toString() and only later, inside the logging method, we check if we actually should log it. Doesn't matter whether logging is active or not, we still pay for the call to the SomeComplicatedStuff toString() method.

A solution is duplicating the check on the log status:

SomeComplicatedStuff scf;
// ...
if(log.isDebugEnabled())
    log.debug("Log config file: " + logConfigFile);

It works, but this code is painful to write and maintain. It would be better to move the check in the logging methods and delay the string building after the check. Good news is that is the SLF4J approach. Bad news is that we have to rework the way the parameters are passed to the logging methods.

In the case above we were passing a String, created joining a constant one and a variable generated calling implicitly SomeComplicatedStuff.toString(). The logging method can't do anything to avoid the cost of calling toString(), it is just too late. We should have a way to delay the creation of the String to be logged after. The SLF4J decision is to design these methods like simplified String.print(). They have only one tag in the destination string, a couple of opening/closing curly brackets:

SomeComplicatedStuff scf;
// ...
log.info("Log config file: {}.", logConfigFile);

Doesn't look too bad, after all, but there are a couple of caveats.

1) Primitive values can't be passed to the logging methods.

This usually is a minor issue, if we are not afraid of the price of wrapping a primitive in an object. Besides, in Java 5 and above, autoboxing shields the process. Only if you are working with an ancient Java version you are forced to explicitly wrap your primitive value by the relative wrapper class.

2) No more than two objects can be passed as parameter to the logging string.

At first sight this look awful, but we can use the fact that Java arrays are objects, and pass all the objects that we want to be logged in a single array instance:

SomeComplicatedStuff scf1, scf2, scf3;
// ...
log.info("Values: {}, {}, {}", new Object[] {scf1, scf2, scf3} );

Not the most elegant piece of code ever seen, and even a bit counterintuitive, but it works.

Bear in mind that we get this behavior only when just one Object array is passed to a logger method. If a String and two Object arrays are passed, they are seen a two unrelated variables, and as such printed.

Go to the full post

JUL configuration

Once you have set SLF4J up, and done a bit of practice using the simple logger native plugin, you would probably start using it coupled to a "real" log framework, like the standard JDK logging facility, friendly known as JUL, from its fully qualified package name: java.util.logging.

To use JUL as logging framework in an application we have just to change the application classpath, removing the previous SLF4J plugin jar and adding slf4j-jdk14-1.6.4.jar instead. This is enough to SLF4J to get that JUL is our requested logging target.

By default JUL will use its default configuration. Usually we'd like to specify our specific configuration, let's see an example.

I wrote a very simple configuration file, named logging.properties, containing this few lines:

#test log
.level= ALL
handlers= java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level= ALL

An hash character, '#', has the same meaning of of a double slash in Java: consider whatever is after, till the end of line, as a comment.
In the second line we see how to specify the generic log level for the application: all the messages have to be generated.
The third line is about which handler have to be used. The console handler is a simple one that sends the log messages to standard error. By default it prints only messages with severity info and above.
In the fourth line we configure the console handler to manage all the messages, overriding its standard behavior.

It is not overkilling, we have to specify both that all the messages have to be generated (line 2) and managed by our handler (line 4).

A simple way to use a JUL configuration file is passing it to Java from the command line:

> java -classpath .;C:/slf4j-1.6.4/slf4j-api-1.6.4.jar;C:/slf4j-1.6.4/slf4j-jdk14-1.6.4.jar 
-Djava.util.logging.config.file=logging.properties test.MyLogTester

We asked java to run a class, test.MyLogTester, loading a file, logging.properties, as java.util.logging.config.file, so that it will be used to set the options for the JDK logger.

We can do the same programmatically. It could be handy to work in this way, for instance, to use different profiles without being forced to stop and restart the application:

Properties prop = System.getProperties();
prop.setProperty("java.util.logging.config.file", "logging.properties"); // 1
try { LogManager.getLogManager().readConfiguration(); } catch(Exception e) {} // 2

1. It doesn't make much sense to use an hard-coded file name, but this is just an example.
2. This error handling is very weak. We should have checked for IOException and SecurityException, and give some feedback to the user in case of failure.

A simple little method to check how the log behavior changes for different loggers and configurations:

void slf() {
if (!log.isTraceEnabled())
    System.out.println("Trace not enabled");
else
    log.trace("trace");

if (!log.isDebugEnabled())
    System.out.println("Debug not enabled");
else
    log.debug("debug");

if (!log.isInfoEnabled())
    System.out.println("Info not enabled");
else
    log.info("info");

if (!log.isWarnEnabled())
    System.out.println("Trace not enabled");
else
    log.warn("warn");

if (!log.isErrorEnabled())
    System.out.println("Error not enabled");
else
    log.error("error");
}

It is interesting to check if a log level is enabled before calling the relevant log message, so that we can have a different output when testing different configuration files.

Go to the full post

SLF4J SimpleLogger

We have seen how to setup SLF4J, the Simple Logging Facade for Java, and how to use its native SimpleLogger for start using it immediately.

This is a case where the name it is very close to the essence: the SLF4J SimpleLogger is actually a very simple logger. Still, it could be useful to spend some time exploring it in some detail.

There is something even simpler than SimpleLogger. If we don't want to have any log at all, we can use NOPLogger, implemented in the slf4j-nop-1.6.4.jar library (version number may vary). As its name suggests, each logging method in this class is implemented as a no-op. We can call them till we get blue in the face, still we won't generate anything.

Compared to it, SimpleLogger is not that extreme. To make it available to the project, we place slf4j-simple-1.6.4.jar in the specific Java Build Path. It probably makes sense using it only in very simple projects or some testing, as a temporary replacement for a real logger.

There is no way of configuring a SimpleLogger, we have to use it as it is:

• Only info, warn, and error message are generated;
• trace and debug methods are no-ops;
• the log message format is immutable;
• the log destination stream is System.err.

[Update: Since version 1.6.6, SLF4J SimpleLogger has gained more functionality. Please refer to the post written for the (currently) latest version, 1.7.5]

Go to the full post

SLF4J setup

The SLF4J acronym stands for Simple Logging Facade for Java. It is very similar to Apache Commons Logging (also known as JCL), of which it is kind of a successor.

SLF4J makes the Java code that uses it almost independent to the actual underlying log framework. In a tiny project this is usually not an issue, but especially when developing a library, or same other kind of modular code, that is meant be used by possibly unknown clients, this independence from the actual logging tool (Standard JDK, log4j, backlog, ...) could easily be a key factor.

Let's start form scratch, first step is downloading the library. You can find it on slf4j.org. At the time of writing this post, 1.6.4 is the latest available version.

SLF4J is provided as a compressed file, download it and expand it in some location available to your developer workspace. Then add the slf4j-api-1.6.4.jar (version number may vary) to the Java Build Path of your project.

Finally you can create, compile, and even run (with probably unexpected results) a simple SLF4J-based application:

// ...
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class HelloWorld {
    private static final Logger log = LoggerFactory.getLogger(HelloWorld.class);
    // ...

    public static void main(String[] args) {
        log.info("Hello World");

        // ...
    }
}

If you expected to get somewhere (on the standard output or error console would be a good guess) an hello message, well, you would be disappointed, because what you get is this:

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.

Thinking better we should admit that SLF4J is right. It doesn't know which logging framework to use, it doesn't even know if we would like to see any feedback or that would be terribly embarrassing. So it assumes it is better to be silent, and uses a default no-op implementation (slf4j-nop-1.6.4.jar) that simply eats up any log we send to it.

If we want to have a basic feedback, so that we could see if anything is working as expected, we can use a simple logger provided by SLF4J. We just have to add the library slf4j-simple-1.6.4.jar to our application Java Build Path. Now we should get from our application a better output:

0 [main] INFO HelloWorld - Hello World

That's it. SLF4J is up and running. As we have seen, it is very easy to switch to a different logging framework, just change a jar in the build path. Removing the SLF4J native simple logging framework and adding slf4j-jdk14-1.6.4.jar (native SLF4J plugin to the standard JDK logger, also known as JUL: java.util.logging) it is all we need to make our application ready to run and producing a JDK log:

06.12.2011 18:48:30 HelloWorld main
INFO: Hello World

Go to the full post