Logging instead of println

Every program in this course talks to you through System.out.println. When something goes wrong, you add a few more printlns to see what is happening, and delete them once the bug is gone. That works for a program you run once. A real program runs for days on a machine you are not watching, and when it misbehaves you need a record of what it did, when, and where. This lesson swaps the stray printlns for logging: messages with a level, a time and a source, that you can turn up or down without touching the code.

What println gets wrong#

Picture a shop app that has been running on a server for a week. A customer says their order vanished on Tuesday afternoon. You open the program's output and find thousands of lines like adding 250 and here!!, with no times, no idea which part of the program printed them, and the real output mixed in between. Debugging printlns cause each of those problems:

java.util.logging: the logger inside the JDK#

Java ships with a logging library in the package java.util.logging, so you can start without adding anything. Each class gets its own Logger, usually named after the class, kept in a private static final field. Run this and look at the console: the log lines appear in red, because they go to standard error, and Welcome!is the program's real output.

Each message becomes a log record of two lines. The first has the date and time, then the class and the method that logged it, Main main. The second has the level and the message, INFO: Opening the shop. Main.class.getName()is the class's full name, so in a class inside a package the logger would be called something like com.example.shop.Main. And the fine message printed nothing at all. That is levels at work.

Seven levels#

A logger prints a message only if its level is at least the logger's own level. Out of the box that is INFO, so SEVERE, WARNING and INFO appear and everything below is dropped. The dropped messages cost almost nothing, which is why they can stay in the code.

The two gates: logger and handler#

To see the FINE messages while you hunt a bug, the obvious move is log.setLevel(Level.FINE). Try it, and watch the first fine call vanish anyway:

Only message 2 is printed. A record passes two gates. The logger decides whether a message is worth recording at all; a handler decides whether to write it out, and where. The handler that prints to the console belongs to the root logger, the parent of every logger, and it has its own level, also INFO. Message 1 got through the first gate and was stopped at the second. The fix gives the logger its own ConsoleHandler set to FINE, and setUseParentHandlers(false)stops the record from also going to the root's handler, which would print it a second time once it allowed FINE.

Key idea

A log record is printed only if the logger's level and the handler's level both let it through. Raising one of them alone changes nothing.

15:36:21 INFO shop: Opening the shop
15:36:21 FINE shop: Checked the stock

Messages that cost nothing when they are dropped#

Building a message has a cost. log.fine("Cart: " + cart) joins the strings and calls cart.toString() before fine even starts, and then the record is dropped. Two forms avoid the waste. A message with numbered placeholders, {0}, {1}, is only filled in if the record is printed. A Supplier lambda is only called if the record is printed. Step through and watch the counter.

The log says Loaded 1,234 books from library.txt and Average price 12.346, and the output says slowReport ran 0 times: the fine record was dropped, so its lambda never ran. The placeholders are filled by java.text.MessageFormat, which formats numbers for reading. It adds the comma in 1,234 and rounds the price to three decimal places.

Twice. Line A builds its string, calling report(), before finecan say the record is dropped. Line B hands over a lambda that is never called. Line C's lambda is called, because INFO is printed.

Logging an exception#

When you catch an exception and carry on, log it with the exception as the last argument. The record then includes the full stack trace, so the log answers “where did this come from?” long after the program has moved on.

The program prints Total: 770 and logs a WARNING with the exception and its trace under it: at Main.checked(Main.java:22), then at Main.main(Main.java:12). Logging e.getMessage() alone would lose those lines, and they are the most useful part.

System.Logger: the JDK's front door#

Java 9 added a smaller logging interface, System.Logger, that you get from System.getLogger(name). It has one method, log, with its own five levels, and it hands every record to a logging library: java.util.loggingby default, or another one, such as SLF4J, when that library's bridge for System.Logger is on the classpath (for SLF4J, the slf4j-jdk-platform-logging module). Code written against it never has to change when the library does.

Three records appear. DEBUG becomes FINE in java.util.logging, which is dropped at the default level, and ERROR is printed as SEVERE, the name java.util.logging uses. The parameters work the same way, through MessageFormat.

SLF4J and Logback: what most projects use#

Look inside almost any Java project from a company and you will find a different pair: SLF4J (the Simple Logging Facade for Java) and Logback. They split the job in two, the way an interface and its implementation do in interfaces. SLF4J is the interface your code calls. Logback is the library that does the work: formatting, writing to the console and to files. A team can swap Logback for another implementation without changing a line of the code that logs.

They come from Maven Central like any library. Adding Logback is enough, because it brings the SLF4J interface with it:

It reads much like java.util.logging, with three differences you can see. The levels are trace, debug, info, warn and error. Placeholders are plain {}, filled in order, and only when the record is printed. And an exception goes last, after the placeholders' values. Run it with the Exec plugin:

With no settings file, Logback prints one line per record: the time to the millisecond, the thread in brackets, the level, the logger's name, and the message. Its default level is DEBUG, so the debug line shows and the trace line does not. The thread is called com.example.shop.Main.main() because the Exec plugin starts the program on a thread of its own with that name; run it with java directly and it says main. The number is 1234, with no comma: SLF4J's {} uses plain toString, with none of MessageFormat's formatting and none of its quote trouble.

Configuring Logback with logback.xml#

Logback reads its settings from a file called logback.xml in src/main/resources, which Maven puts on the classpath. This one prints a shorter line to the console, writes a fuller one to a file called shop.log, keeps everything at INFO, and turns the shop's own code up to DEBUG:

• An appender is Logback's word for a destination, what java.util.logging calls a handler. This file has two, the console and shop.log, and the root logger sends every record to both. The file holds the same records in the fuller pattern, with the date and the thread.
• In the pattern, %d is the date and time, %-5level the level padded to five characters so the messages line up, %logger{20}the logger's name shortened to about 20 characters (com became c), %msg the message and %n a new line.
• <logger name="com.example.shop" level="DEBUG"/>sets one package's level. Loggers are named after classes, and a setting for com.example.shop covers every logger whose name starts with it. So your own code logs DEBUG while the libraries you use stay at INFO and stay quiet.

What to log, and what never to log#

A log is only as useful as what you put in it. A few habits make the difference between a log that answers questions and a log nobody reads.

• Log events, one record each, in a sentence a stranger could understand: Order 5521 placed by customer 873 for 3 items, not here or ok.
• Include the ids that let someone find the thing later: the order number, the customer number, the file name.
• Pick the level for the reader. If a person must act, it is ERROR (or SEVERE). If the program coped, WARN. If it is a normal milestone, INFO. Everything a developer wants only while debugging is DEBUG or below.
• Log an exception once, where you handle it, with the exception attached. Logging it and then throwing it again means the same error appears in the log two or three times as it travels up.

1import java.util.logging.Logger;
2 
3public class Main {
4    private static final Logger log = Logger.getLogger("cart");
5 
6    public static void main(String[] args) {
7        int[] prices = {250, 1200, 75};
8        int total = 0;
9        for (int p : prices) {
10            System.out.println("DEBUG adding " + p);
11            total += p;
12        }
13        if (total > 1000) {
14            System.out.println("WARNING big order: " + total);
15        }
16        System.out.println("Total: " + total);
17    }
18}

Further reading#

• Java Logging Overview, in the Java SE 25 core libraries guide
• System.Logger in the Java SE 25 API documentation
• The SLF4J user manual
• Logback configuration, from the Logback manual