Logging in Java with slf4j

This document is an introductory text teaching new Java programmers how to log information about their programs, and how to read the information logged for debugging purposes. This is demonstrated with fully functional programs using the simplest possible configuration of Simple Logging Facade for Java frontend. Even so the methologies shown are suitable for full scale production.

Please provide feedback if you like to ravn@runjva.com
-- Thorbjørn Ravn Andersen

Telling your grandmother what you do

Welcome to the world of programming!

Hopefully you'll enjoy your stay, and perhaps even want to live here. If you do so, and you ever need to tell your grandmother what you do for a living then don't despair. Just ask her what

"Bind off 6 (7, 7, 9) sts at beg of next 2 rows. Dec Row (RS): K2, k2tog, k across to last 4 sts, ssk, k2. Rep Dec Row every other row 10 (12, 13, 14) times more -- 38 (40, 46, 48) sts. Continue even to approx 21 1/2 (22, 22 1/2, 23) inches from beg ending with a WS row."

means - most grandmothers know that - and tell her you write those but for computers. She'll nod and understand completely.

If you are like most learning programmers you have NO idea what the quote above means at all. Well, it is part of a knitting recipe for a sweater[ 1 ] and that is what programming is basically all about - writing knitting recipes for computers.

Programming is a craft it takes years to master

Peter Norvig writes in his online article Teach Yourself Programming in Ten Years - a recommended read - that it takes 10 years or perhaps 10000 hours of deliberate practice to develop expertise in an area. For programmers that means writing programs and reading programs, but unfortunately there is not yet a general tradition of experienced programmers mentoring new programmers in person, so you will have to learn a lot on your own.

By using the techniques described in this document you will have a greater chance to avoid some very embarrassing and exhausting experiences in your future jobs, and hopefully not having to unlearn a habit or two.

If you need to get experience while studying or preparing to get a job, I would recommend that you locate an Open Source project which you are genuinely interested in - for instance if you need it in your own projects - and help them. This can both be programming, but also writing documentation - as good documentation requires thorough understanding of the software being documented. This also gives you experience working with a team which communicate electronically and use tools that allow multiple developers to work on the same project without disturbing each others files.

By choosing an Open Source project you can demonstrate what you have done to a future employer as part of the interview if they ask what experience you have.

"And you try and tell the young people of today that ..... they won't believe you."

Java was designed by Sun Microsystems, which happened to make a living at the time selling computers running the Sun dialect of the Unix operating system. It is not a surprise then that Java programs tend to look like other Unix programs, which were designed to work on the computer you see in the picture below.

Picture shows Ken Thompson and Dennis Ritchie working at the first real Unix machine. Please note that there is real paper in the "typewriters", the closet behind the men is the computer, and that the circular containers on top of the computer contain program and data on paper tape. Things were different in 1973.

Under Unix every program has three input/output connections available - namely

standard input - this provides the things the user type to the program. (Java: System.in)
standard output - this is normal information (Java: System.out)
standard error - this is information about error situations (Java: System.err)

The Unix philosphy was stated by McIlroy[ 3 ] to be " Write programs that do one thing and do it well. Write programs to work together. Write programs to handle text streams, because that is a universal interface. ". This means you can let the output of one program be the input of another program - called a pipe - encouraging small specialized programs being combined to complete a larger task, like creating a list of words in a file by first extracting all words, sorting them, and then eliminate duplicates. Unfortunately this has not caught on in Java, mostly because the Java environment takes too long to start for small programs to be really usable. The concepts are still the same, however.

So the simplest possible Java program uses System.out to print out the line "Hello World":

  1: public class HelloWorld {
  2:    public static void main(String[] args) {
  3:       System.out.println("Hello World");
  4:    }
  5: }

This should be named "HelloWorld.java", and is compilable from the command line with "javac HelloWorld.java", and the compiled class can then be invoked with "java HelloWorld".

Line 1 declares this to be the class named HelloWorld - there is no "package" line so it is just HelloWorld instead of e.g. com.bigcoorporation.HelloWorld. Line 2 is the magic words needed to be able to invoke the class file from the command line as "java HelloWorld". Line 3 prints the line "Hello World" to standard output.

Now, why did that happen?

One of the unfortunate side effects of programming for a living is that people are using your programs, and they tend to find that your programs do not work as they expect - this is traditionally called a "bug"[ 2 ] - and it is then your responsibility to identify and correct the problem.

In most cases, all you have to work with is the user describing what happened and what was expected. The program has ended and is for all practical purposes unavailable to you. Hence a way of saving information from within the program for later is needed, much in the same way that logbooks are used on ships to aid in navigation. The term "logging" is used in general for the process of systematically saving information for later.

Several logging solutions are available to Java programmers. All of these generally share the ability to log:

The area of the code containing the log statement.
The time when the log statement was invoked.
An importance level of this log statement.
An exception (with accompanying stack trace).
A log message.

This has proven to be very helpful for logs intended for the human reader. Facilities available in some logging frameworks include:

storing events in a database
alert users by email, instant messaging or any other electronic means

(but that is too advanced to be covered in this introduction - it is just to give you an idea of what is possible)

The HelloWorld program rewritten to use the SLF4J logging solution (full instructions are in appendix A) and put in the "demo" package, looks like:
====

package demo;

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

public class HelloWorld {
   public static void main(String[] args) {
      Logger log = LoggerFactory.getLogger(HelloWorld.class);
      log.info("Hello World");
   }
}

=====

and generates the following output:

====

2009-06-07 10:38:21 demo.HelloWorld main
INFO: Hello World

=====

The first line contains a date and time stamp, the name of the logger - here "demo.HelloWorld" - and the name of the method containing the log.info statement - here "main". The second line contains the importance level - here "INFO" - and the message passed - here "Hello World". Note how much of this information was derived automatically!

If we add a method call with a wait, we can see that the timestamp changes, and that the method names in the log correctly indicates if the log statement is done from "main" or "waitTwoSeconds".

====

package demo;

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

public class HelloWorld2 {
    public static void main(String[] args) throws Exception {
        Logger log = LoggerFactory.getLogger(HelloWorld2.class);
        log.info("Hello World");
        waitTwoSeconds(log);
        log.info("Done");
    }

    private static void waitTwoSeconds(Logger log) throws Exception {
        Thread.sleep(2000);
        log.info("Slept 2 seconds");
    }
}

=====

with the following output:

=====

2009-06-07 10:53:52 demo.HelloWorld2 main
INFO: Hello World
2009-06-07 10:53:54 demo.HelloWorld2 waitTwoSeconds
INFO: Slept 2 seconds
2009-06-07 10:53:54 demo.HelloWorld2 main
INFO: Done

=====
If you were shown this log, you would be able to determine that the program had run as expected to the statement logging "Done" in the main method of demo.HelloWorld2 and you should not look for problems happening before that statement.

Logging information stored in variables

If you need to add information stored in a variable, slf4j allow you to specify this with {}. (Note: Example works with Java 5 and later)

====

package demo;

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

public class ZeroToFour {
    public static void main(String[] args) throws Exception {
        Logger log = LoggerFactory.getLogger(ZeroToFour.class);
        for (int i = 0; i < 5; i++) {
             log.info("i = {}, i*i = {}", i, i * i);
        }
    }
}

====

which outputs

====

2009-06-07 13:23:57 demo.ZeroToFour main
INFO: i = 0, i*i = 0
2009-06-07 13:23:57 demo.ZeroToFour main
INFO: i = 1, i*i = 1
2009-06-07 13:23:57 demo.ZeroToFour main
INFO: i = 2, i*i = 4
2009-06-07 13:23:57 demo.ZeroToFour main
INFO: i = 3, i*i = 9
2009-06-07 13:23:57 demo.ZeroToFour main
INFO: i = 4, i*i = 16

====

All objects can be logged in this way, and the toString() method is called to get the string to log. Note that int, long, double, floats, chars are not objects, but that in Java 5 and later they are invisibly converted correctly.

Logging problems

All programs regardless of programming language must have a way to handle problems. In Java this is done by "throwing exceptions" which causes the Java Virtual Machine to stop the normal execution of your program, and start looking for code which can "catch the exception thrown" - if none is found in the current method, the method calling it is investigated and if none is found there the method which called it is investigated, etc. This continues until either a suitable "try-catch-clause" has been found or the program ends with an error message and a stack trace:

A stack trace looks like:
===

java.lang.ArithmeticException: / by zero
    at demo.CatchException.doStuff(CatchException.java:20)
    at demo.CatchException.main(CatchException.java:12)

===

The first line lists the full name of the exception, a colon, and the error message. The next line tells where the exception was thrown, here in the method doStuff() in the class demo.CatchException (the exact location is on line 20 in the file CatchException.java which contains the source code for the class). The rest of the lines is on the same form, but tells where the call to the previous line happened.

In the above example, main() calls doStuff() on line 12, and in doStuff() on line 20 the exception is thrown.

The full program looks like:

====

1: package demo;
2:
3: import org.slf4j.Logger;
4: import org.slf4j.LoggerFactory;
5:
6: public class CatchException {
7:
8:   public static void main(String[] args) {
9:        Logger log = LoggerFactory.getLogger(CatchException.class);
10:
11:       try {
12:            doStuff(log);
13:        } catch (Exception e) {
14:            log.error("Something happened", e);
15:        }
16:    }
17:
18:     public static void doStuff(Logger log) {
19:        log.info("1/1 = {}", 1 / 1);
20:        log.info("1/0 = {}" ,1 / 0);
21:    }
22:}

Here is a sample run with line numbers.
====

1: 2009-06-07 12:59:27 demo.CatchException doStuff
2: INFO: 1/1 = 1
3: 2009-06-07 12:59:27 demo.CatchException main
4: SEVERE: Something happened
5: java.lang.ArithmeticException: / by zero
6:     at demo.CatchException.doStuff(CatchException.java:20)
7:     at demo.CatchException.main(CatchException.java:12)

=====

Line 19 in the program logs "1/1 = {}" with the argument 1. This results in line 1-2 in the output. Line 1 contains a timestamp and the class and method. Line 2 contains the severity of the log statement - here INFO - and the log message with {} replaced with arguments.

Line 20 tries to log "1/0 = {}" with the argument 1/0, but dividing by zero causes the JVM to throw an ArithmeticException which cancels the execution of line 20 and begins the search for a suitable try-catch-clause. There is not one in doStuff() so the JVM goes back to the place where doStuff was called - this is line 12 in main() - which is inside a suitable try-catch-clause!

The exception thrown is therefore assigned to the variable e in line 13, and an error is logged on line 14. This results in line 3-7 in the output. Line 3 contains the timestamp and the class and method of the logging statement. Line 4 contains the severity of the log statement - here SEVERE - and the message logged. Line 5-7 contains the stack trace contained in the exception.

What SHOULD I log?

When you think about what you should log, you might consider thinking of the worst case scenario, where you need to locate and fix a Heisenbug - a problem which you cannot reproduce reliably or at all- only using the log from when it happened to the customer.

This means doing a "log.debug" call for every piece of work or decision taken with arguments describing what has been done, and a "log.info" call for every important piece of work with arguments.

Fortunately, this is usually not necessary! But such production scenarios exist - all you have is your log. You might as well think about it when you write your code.

Usually the log.debug is used by the developers to debug methods, and they are switched off in production scenarios so they are just skipped.

Use log.info about things you would consider important enough to warrant logging but not enough for any more than that.

Use log.warn to note unusual things - preferably in detail - that might warrant a second glance from a system operator.

Use log.error for those things that require immediate attention. Like waking up people at 03:00...

Log the output of "new java.util.Date()" when starting the program. Perhaps also with the name of the machine and its IP-number. This helps you identifying restarts, get the full timestamp of the restart, plus keeping track of multiple machines with identical configuration.

For files, consider logging the absolute file name when opening a file. This might help you identifying problem with the wrong file being read or written.

Appendix A - Setting up SLF4J

SLF4J is a frontend which allow the usage of any of several logging frameworks without changing code and recompiling. In order to run the examples, you need to download and unpack the latest release of SLF4J from http://slf4j.org/download.html . To get the same output as this document you will need to tell slf4j to use the logging framework built into Java from 1.4 onwards.

Amongst the unpacked files you will find slf4j-api-1.5.8.jar and slf4j-jdk14-1.5.8.jar (numbers vary slightly) which need to be added to your classpath.

To compile a program with slf4j from the command line , use
===

javac -g -cp .../slf4j-api-1.5.8.jar demo/CatchException.java

===
and to run it with slf4j and the jdk14 backend on a Unix system (Linux, Mac etc.), use:
===

java -cp .:.../slf4j-api-1.5.8.jar:.../slf4j-jdk14-1.5.8.jar demo.CatchException

===
(Note that the argument after "-cp" is period-colon-pathtoslf4japi-colon-pathtoslf4jjdk. I.e. three locations separated with a colon)

To run it under Windows with slf4j and jdk14 backend, use:
===

java -cp .;.../slf4j-api-1.5.8.jar;.../slf4j-jdk14-1.5.8.jar demo.CatchException

===
(Note that the argument after "-cp" is period-semicolon-pathtoslf4japi-semicolon-pathtoslf4jjdk. I.e. three locations separated with a semicolon)

For Eclipse , right-click on a Java project in the Package Explorer, choose Properties, choose Java Build Path, choose Library pane, click "Add External Jars" and add each of the two jar files.

This allows you to use the logging framework built into Java with slf4j. Other frameworks exist and most can be used through slf4j by including the correct jar file instead of slf4j-jdk14-1.5.8.jar when the program is started. See http://www.slf4j.org/ for the latest list of native and wrapped implementations.

Regardless of which logging framework is being used, its usual rules apply - slf4j is just a simple, common frontend - so if you want to configure the jdk14 logging you must read the official Sun documentation . It is a bit hard to read, so I suggest you see if your specific problem is covered at http://www.exampledepot.com/egs/java.util.logging/pkg.html

Appendix B: Questions you might think

Q: Isn't it slow to have lots of "log.debug" calls if they have been switched off?

A: No. Logging frameworks are optimized to handle this very quickly, and it is not a problem.

Q: I have read that it is necessary to use "isDebugEnabled()" to make logger calls fast in log4j. Does that also apply to me?
A: Log4j predates slf4j, and this does not apply to slf4j. However it requires you to use the {}-placeholders, as they delay the actual creation of the full string to be logged as much as possible, notably after the event has been determined to need to be logged.

Q: What is the recommended way to declare the logger variable inside an object (and not a static method)?

A: You should declare it like this

    private final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(this.getClass());

Note: This will not work for static methods. Here you should start each method with requesting a Logger object similar to:

   public static doStuff() {
       final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(ThisClass.class);
       log.info("in doStuff()");
  }

http://www.bhg.com/crafts/knitting/wearables/too-cute-knit-cowl-neck-sweater/?page=2 - the quote is the "armhole shaping" part
The origin of the word is that in 1945 a moth was found to cause a malfunction in the Mark I computer. It can be seen at http://www.history.navy.mil/photos/images/h96000/h96566kc.htm
See the chapter on The Unix Philosophy from "The Art of Unix Programming" by Eric S. Raymond (who has a lot of very recommended reading at http://www.catb.org/~esr/writings/ like the ground shaking "The Cathedral and the Bazaar".