What You Should Know About Logging

A few weeks back, I reviewed code from a young developer. It was impressive work for a topic he didn’t know beforehand, except on one aspect: every output used System.out.println(). That’s understandable: that’s how Java developers learn to code, just like Python developers do their first tests with print. But that’s not something that’ll be handy for a live application.

The Problems with Printing #

What Printing Is Usually Used For #

I’ll focus on Java, since it’s what I know best. So, what’s the issue with using System.out.println?

Per se, none: it’s a useful utility when you start coding, to see what’s going on in your code. Usually, when you begin, you use it for two things:

• to debug, because you don’t understand how you’re code arrived at some point¹;
• to log, in order to have a history of what the program did while it was running.

We’re going to focus on this second aspect. So, why isn’t System.out.println the best way to log your program actions?

Why Printing Isn’t Logging #

First, because it’s not its purpose. System.out is the standard output. It’s often understood as the console output, and is true in most cases². There’s also System.err, the error output, which you’ll rarely use directly, but Throwable.printStackTrace() uses it everytime. It also goes to the console by default. Logging should help you trace back to the origin of an issue, that sometimes happened yesterday or the day before, so you need to be able to easily go back through time. When your program runs on a server, you rarely have access to its console output³ if it even has one with a big enough buffer, and scrolling through two days of logs in a console may be tedious, while we’re more used to search inside a file⁴.

More importantly, if you want to be able to retrace what happened when reading logs, you’ll need timestamping. println() does not do this out of the box. Of course, you could implement a utility method to automatically add it, but then you’d almost be reimplementing a logging API.

There’s also no notion of information level when printing (well, none other than “normal” or “error”). When logging, you usually want to be able to filter information depending on its level. Of course, you want to be able to distinguish anomalous from expected behaviours, but you also want to be able to remove all superfluous logging that developers put to say “Code passed here.” That is, unless you are looking for the origin of an issue around this log. That’s what log levels are for, and I’ll come back to it below.

Logging To the Rescue #

This is where logging comes in. And not just in Java: .NET, Python, JavaScript, PHP… All have their own solution.

But then again, let’s focus on Java for this post. Most often, you’ll rely on an external framework to do the logging. The most widely used today are Log4j 2 and Logback, so I’ll write about things I’ve seen with both of these. I won’t go into details about the configuration or use, but you can have a look at Baeldung’s introduction or others.

Configuring the Output #

With a logging framework, you can configure where you want your logs to be written: in the console (nice for containerized applications or being currently developped on your computer), in files, pushed to a queue… They can be written in several places at once.

A common configuration is to write one file per day and remove files that are more than seven/fifteen/pick-your-number days old. Another one is to make sure that no log file is heavier than N MB and create a new one if it is.

So, not only can you print the logs in files, but you have a real flexibility about what you do.

This is configured in a log4j.xml or logback.xml file.

Creating a Log Pattern #

The XML configuration file doesn’t only hold where the logs are printed, though. There are also parameters allowing you to set how your message will be printed.

Of course, when you log a message with a specific level, you want these to be printed. You also want a timestamp, that will be generated by the framework when logging your message.

But there’s a whole panoply of additional informations you can automatically add to your message, as for instance:

• the class where you are logging;
• the method you are in;
• the line where you call to the log instruction;
• the ID of the thread…

Of course, some information require more time to compute than other and will add an overhead to the logging. If your application is intensively used, this may slow the whole thing. Be mindful of that, and of the fact that there is such a thing as too much information.

Filtering by Log Level #

In Java, there are six levels of logging. In most frameworks I’ve used, those are translated to five levels.

When you log a message, you must specify the level:

1log.debug("Transaction validity check OK, proceeding...");

When running in production, you probably don’t need debug or trace information (they produce a lot of messages), so you’ll configure your framework to produce only INFO, WARN and ERROR logs. To do so, in your log4j.xml/logback.xml, you’ll set the level of your appender to INFO. The framework will know that it means “INFO and anything higher.”

You can even specify this by package. This is useful when you use libraries: you may want to display debug information for your code without including those of external code, because it may be very detailed and dilute the information you’re looking for.

Tips Before Parting #

I’ve addressed the limitations of printing and shown how Java logging frameworks fix them. Here are some final pieces of advice if you’re beginning with those.

Logging Exceptions #

When generating a catch clause through your IDE, you often see something like this:

1} catch (ExampleException e) {
2    e.printStackTrace();
3}

The printStackTrace method provides information that is useful to troubleshooting, but it prints them instead of logging it. You don’t want to have to log the stack trace yourself, but you don’t have to: in most frameworks, pass the exception as the second argument, the first being the message to log before the stack trace (use e.getMessage() if you’re not inspired).

Our example would then become:

1} catch (ExampleException e) {
2    log.error("For the sake of example, we failed here.", e);
3}

Using if #

Log frameworks come with a is<Level>Enabled() method that returns a boolean. You may wonder why use it, since log.debug("something") will only print the message if DEBUG level is enabled anyway.

True, but imagine the following:

1log.debug(buildCpuExpensiveMessage());

When running, the program will first build the message, then pass it to the logger, which will discard it because it’s not debug enabled. So you’ve used CPU (and time) for nothing.

In such cases, it’s better to go this way:

1if (log.isDebugEnabled()) {
2    log.debug(buildCpuExpensiveMessage());
3}

This way, we check that debug is enabled before we build the message.

Knowing whether is<Level>Enabled() should be used as a default is a common question. Here is my own rule of thumb: if the message is a simple String, then you can skip the use of is<Level>Enabled(); if you use a method or an iteration to build the message, then check before.

Whenever you’re in doubt, it’s best to wrap in an if.

SLF4J #

SLF4J provides a common interface and abstraction for most of the Java logging frameworks, which is why I love to use it: no need to wonder whether I’m using Logback, Log4j or something else.

Another thing I love is the possibility to use format Strings. For instance:

1log.debug("The collection contains {} elements.", collection.size());

will print “The collection contains 42 elements.” I find it more elegant than concatenating several Strings, and I know that the formatting will only be done if that logging level is enabled.

But that’s only a triviality compared to the rest of this post.

Epilogue #

This post was quite theoretical. If you’d like me to dive into the technical aspects or examples, or if you have an additional question, please say so in the comments. In the meantime, many others have had a take at it, so your search engine should help you.