Clean code, clean logs: easy to read, easy to parse (10/10)

There are two groups of receivers particularly interested in your application logs: human beings (you might disagree, but programmers belong to this group as well) and computers (typically shell scripts written by system administrators). Logs should be suitable for both of these groups. If someone looking from behind your back at your application logs sees:

from Wikipedia

then you were probably not reading my tips carefully enough. The reference to famous Clean code book in the title of this series is not accidental: logs should be readable and easy to understand just like the code should.

On the other hand, if your application produces half GiB of logs each hour, no man and no graphical text editor will ever manage to read them entirely. This is where old-school grep, sed and awk come in handy. If it is possible, try to write logging messages in such a way, that they could be understood both by humans and computers, e.g. avoid formatting of numbers, use patterns that can be easily recognized by regular expressions, etc. If it is not possible, print the data in two formats:

log.debug("Request TTL set to: {} ({})", new Date(ttl), ttl);
// Request TTL set to: Wed Apr 28 20:14:12 CEST 2010 (1272478452437)

final String duration = DurationFormatUtils.formatDurationWords(durationMillis, true, true);
log.info("Importing took: {}ms ({})", durationMillis, duration);
//Importing took: 123456789ms (1 day 10 hours 17 minutes 36 seconds)

Computers will appreciate "ms after 1970 epoch" time format, while people would be delighted seeing "1 day 10 hours 17 minutes 36 seconds" text. BTW take a look at DurationFormatUtils, nice tool.

I thought this article is going to be short, but after writing it I decided to split it into 10 parts, each in separate post. Hope you enjoyed my logging series, although still not everything has been covered. This only proves how logging is important and how many pitfalls should be avoided. Remember, logging code should also be clean and reading your logs is supposed to be as pleasant as reading your code.

• Clean code, clean logs: use appropriate tools (1/10)


• Clean code, clean logs: logging levels are there for you (2/10)


• Clean code, clean logs: do you know what you are logging? (3/10)


• Clean code, clean logs: avoid side effects (4/10)


• Clean code, clean logs: concise and descriptive (5/10)


• Clean code, clean logs: tune your pattern (6/10)


• Clean code, clean logs: log method arguments and return values (7/10)


• Clean code, clean logs: watch out for external systems (8/10)


• Clean code, clean logs: log exceptions properly (9/10)


• Clean code, clean logs: easy to read, easy to parse (10/10)

Clean code, clean logs: log exceptions properly (9/10)

First of all, avoid logging exceptions, let your framework or container (whatever it is) do it for you*. Logging exceptions is one of the most important roles of logging at all, but many programmers tend to treat logging as a way to handle the exception. They sometimes return default value (typically null, 0 or empty string) and pretend that nothing has happened. Other times they first log the exception and then wrap it and throw back:

log.error("IO exception", e);
throw new MyCustomException(e);

This construct will almost always print the same stack trace two times, because something will eventually catch MyCustomException and log its cause. Log or wrap and throw back (which is preferable), never both, otherwise your logs will be confusing.

But if we really do WANT to log the exception? For some reason (because we don’t read APIs and documentation?), about half of the logging statements I see are wrong. Quick quiz, which of the following log the NPE properly?

try {
    Integer x = null;
    ++x;
} catch (Exception e) {
    log.error(e);        //A
    log.error(e, e);        //B
    log.error("" + e);        //C
    log.error(e.toString());        //D
    log.error(e.getMessage());        //E
    log.error(null, e);        //F
    log.error("", e);        //G
    log.error("{}", e);        //H
    log.error("{}", e.getMessage());        //I
    log.error("Error reading configuration file: " + e);        //J
    log.error("Error reading configuration file: " + e.getMessage());        //K
    log.error("Error reading configuration file", e);        //L
}

Surprisingly, only G and preferably L are correct! A and B don’t even compile in SLF4J, others discard stack traces and/or print improper messages. For example, E won’t print anything as NPE typically don’t provide any exception message and stack trace won’t be printed as well. Remember, first argument is always the text message, write something about the nature of the problem. Don’t include exception message, as it will be printed automatically after the log statement, preceding stack trace. But in order to do so, you must pass the exception itself as the second argument.



* There is one, ekhem, exception to this rule: if you throw exceptions from some remote service (RMI, EJB remote session bean, etc.), that are capable to serialize exceptions, make sure all of them are available to the client (are part of the API). Otherwise the client will receive NoClassDefFoundError: SomeFancyException instead of "true" error.

• Clean code, clean logs: use appropriate tools (1/10)


• Clean code, clean logs: logging levels are there for you (2/10)


• Clean code, clean logs: do you know what you are logging? (3/10)


• Clean code, clean logs: avoid side effects (4/10)


• Clean code, clean logs: concise and descriptive (5/10)


• Clean code, clean logs: tune your pattern (6/10)


• Clean code, clean logs: log method arguments and return values (7/10)


• Clean code, clean logs: watch out for external systems (8/10)


• Clean code, clean logs: log exceptions properly (9/10)


• Clean code, clean logs: easy to read, easy to parse (10/10)

Clean code, clean logs: watch out for external systems (8/10)

This is the special case of the previous tip: if you communicate with any external system, consider logging every piece of data that comes out from your application and gets in. Period. Integration is a tough job and diagnosing problems between two applications (think two different vendors, environments, technology stacks and teams) is particularly hard. Recently, for example, we've discovered that logging full messages contents, including SOAP and HTTP headers in Apache CXF web services is extremely useful during integration and system testing.

This is a big overhead and if performance is an issue, you can always disable logging. But what is the point of having fast, but broken application, that no one can fix? Be extra careful when integrating with external systems and prepare to pay that cost. If you are lucky and all your integration is handled by ESB, bus is probably the best place to log every incoming request and response. See for example Mules' <log-component/>.

Sometimes the amount of information exchanged with external systems makes it unacceptable to log everything. On the other hand during testing and for short period of time on production (for example when something wrong is happening) we would like to have everything saved in logs and are ready to pay performance cost. This can be achieved by carefully using logging levels. Just take a look at the following idiom:

Collection<Integer> requestIds = //...

if(log.isDebugEnabled())
    log.debug("Processing ids: {}", requestIds);
else
    log.info("Processing ids size: {}", requestIds.size());

If this particular logger is configured to log DEBUG messages, it will print the whole requestIds collection contents. But if it is configured to print INFO messages, only the size of collection will be outputted. If you are wondering why I forgot about isInfoEnabled() condition, go back to this tip. One thing worth mentioning is that requestIds collection should not be null in this case. Although it will be logged correctly as null if DEBUG is enabled, but big fat NullPointerException will be thrown if logger is configured to INFO. Remember my lesson about side effects?

• Clean code, clean logs: use appropriate tools (1/10)


• Clean code, clean logs: logging levels are there for you (2/10)


• Clean code, clean logs: do you know what you are logging? (3/10)


• Clean code, clean logs: avoid side effects (4/10)


• Clean code, clean logs: concise and descriptive (5/10)


• Clean code, clean logs: tune your pattern (6/10)


• Clean code, clean logs: log method arguments and return values (7/10)


• Clean code, clean logs: watch out for external systems (8/10)


• Clean code, clean logs: log exceptions properly (9/10)


• Clean code, clean logs: easy to read, easy to parse (10/10)

Impressions after GeeCON 2010

Two days ago I came back from Poznań, Poland, where second edition of GeeCON conference took place. After attending the first edition my expectations were very high and sadly I left Poznań a bit disappointed. It is most likely a matter of my personal taste, but still just a few presentations are worth mentioning.

The biggest surprise and most fabulous piece of lecture has been given by Dawid Weiss on Java in high-performance computing. He managed to combine great show with lots of non-trivial examples. Lots of humour, brilliant slides and great contact with the audience. One of the most charismatic speakers I have seen. But on the other hand it was not a stand-up comedy, where you have lots of fun during the lecture but you don’t gain anything useful after them. Dawid given plenty of examples and micro-benchmarks during his speech, making us believe that tuning, benchmarking and even studying bytecode and assembly language might be interesting. Bravo for Dawid, I was really proud to see Polish speaker doing so well. Dawid also mentioned about his library HPPC, besides I found pretty amazing search clustering tool called Carrot2, authored by his company.

Dawids’ speech has been mentioned several times by Holly Cummins in her lecture: Java Performance Tuning - not so scary after all. It was quite good presentation with nice demo and good slides. It is true that all performance-related Java speeches are similar (few months ago I have seen Kirk Pepperdine presentation on Warsaw JUG and it had pretty similar structure) but still it is worth to know as much as possible when you need to instantly discover performance bottlenecks in your application.

But before Holly I must mention about Ed Burns’ talk Secrets of the Rockstar Programmers. Presentation was based mainly on his book and consisted many audio-video interviews. Two things that stayed in my mind are levels of programmers ignorance and underlying the importance of using your good tools. Learning all these silly keyboard shortcuts and knowing absolutely everything about your debugger capabilities is important and makes you much more productive in both reading and writing code.

Oliver Gierkes' talk maybe wasn’t outstanding, but the tool he presented, Hades, was. If you are writing DAO layer using JPA, Hades greatly simplifies development. Basic idea behind this tool is that you provide only an interface for DAO service and Hades will do its best to dynamically implement your DAO. Basic CRUD with paging and sorting is given out-of-box, but Hades can also generate queries based on method name and arguments. If you enjoy GORM, definitely try this library. And my enthusiasm has nothing to do with the SpringSource memory stick I got for asking a question ;-).

Although I am a backend guy, I found HTML5 Web Sockets: All-You-Can-Eat Real Time! presentation by Peter Lubbers very interesting. Co-author of Pro HTML5 Programming uncovered weaknesses of AJAX and Comet and presented a remedy: Web Sockets. After some brief theory behind asynchronous web communication, he showed few examples of web applications using Comet and web sockets. Firebug and Wireshark were used to help us deeply understand what is happening behind the scenes. Very good, straightforward lecture without unnecessary "presentation sugar".

After asking the last question on the conference (I asked Charles Nutter and Thomas Enebo to compare Groovy and JRuby, it seems they are technically and semantically equivalent, so it is basically a matter of your personal preference), me and a other employees from my company left. GeeCON 2010 was a good conference, but only a few presentations were memorable. Some speakers seemed to be not prepared enough, others bored me completely. I will attend the conference next year, but I would really like to see more great, charismatic speakers like Scott Davis, Mark Richards, Ted Neward or Neal Ford I happened to see on Java Developers Day.

Clean code, clean logs: log method arguments and return values (7/10)

When you find a bug during development, you typically run a debugger trying to track down the potential cause*. Now imagine for a while you can’t use a debugger. For example, because the bug manifested itself on a customer environment few days ago and everything you have are logs. Would be able to find anything in them?

If you follow the simple rule of logging each method input and output (arguments and return values), you don’t even need debugger any more. Of course, you must be reasonable but every method that: accesses external system (including database), blocks, waits, etc. should be considered. Simply follow this pattern:

public String printDocument(Document doc, Mode mode) {
    log.debug("Entering printDocument(doc={}, mode={})", doc, mode);
    String id = //Lengthy printing operation
    log.debug("Leaving printDocument(): {}", id);
    return id;
}

Because you are logging both the beginning and the end of method invocation, you can manually discover inefficient code and even detect possible causes of deadlocks and starvation – simply by looking after "entering" without corresponding "leaving". If your methods have meaningful names, reading logs would be a pleasure. Also analyzing what went wrong is much simpler as on each step you know exactly what has been processed. You can even use a simple AOP aspect to log a wide range of methods in your code. This reduces code duplication, but be careful, since it may lead to enormous amount of huge logs (do you know what you are logging?)

You should consider DEBUG or TRACE levels as best suited for these types of logs. And if you discover some method are called too often and logging might harm performance, simply decrease logging level for that class or remove the log completely (maybe leaving just one for the whole method invocation?) But it is always better to have too much rather than too few logging statements. Treat logging statements with same respect as unit tests – your code should be covered with logging routines as it is with unit tests. No part of the system should stay with no logs at all. Remember, sometimes observing logs rolling by is the only way to tell whether your application is working properly or hangs forever.

* If you start by writing failing test case exposing the bug, my congratulations, I am proud of you!

• Clean code, clean logs: use appropriate tools (1/10)


• Clean code, clean logs: logging levels are there for you (2/10)


• Clean code, clean logs: do you know what you are logging? (3/10)


• Clean code, clean logs: avoid side effects (4/10)


• Clean code, clean logs: concise and descriptive (5/10)


• Clean code, clean logs: tune your pattern (6/10)


• Clean code, clean logs: log method arguments and return values (7/10)


• Clean code, clean logs: watch out for external systems (8/10)


• Clean code, clean logs: log exceptions properly (9/10)


• Clean code, clean logs: easy to read, easy to parse (10/10)

Clean code, clean logs: tune your pattern (6/10)

Logging pattern is a wonderful tool, that transparently adds meaningful context to every logging statement you make. But you must consider very carefully which information to include in your pattern. For example, logging date when your logs roll every hour is pointless as the date is already included in the log file name. On the contrary, without logging thread name you would be unable to track any process using logs when two threads work concurrently – the logs will overlap. This might be fine in single-threaded applications – that are almost dead nowadays.

From my experience, ideal logging pattern should include (of course except the logged message itself): current time (without date, milliseconds precision), logging level (if you pay attention to it), name of the thread, simple logger name (not fully qualified) and the message. In Logback it is something like:

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} %-5level [%thread][%logger{0}] %m%n</pattern>
    </encoder>
</appender>

You should never include file name, class name and line number, although it’s very tempting. I have even seen empty log statements issued from the code:

log.info("");

because the programmer assumed that the line number will be a part of the logging pattern and he knew that "If empty logging message appears in 67th line of the file (in authenticate() method), it means that the user is authenticated". Besides, logging class name, method name and/or line number has a serious performance impact. I have prepared some simple benchmark with the following configuration:

<appender name="CLASS_INFO" class="ch.qos.logback.core.OutputStreamAppender">
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} %-5level [%thread][%class{0}.%method\(\):%line][%logger{0}] %m%n</pattern>
    </encoder>
    <outputStream class="org.apache.commons.io.output.NullOutputStream"/>
</appender>
<appender name="NO_CLASS_INFO" class="ch.qos.logback.core.OutputStreamAppender">
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} %-5level [%thread][LoggerTest.testClassInfo\(\):30][%logger{0}] %m%n</pattern>
    </encoder>
    <outputStream class="org.apache.commons.io.output.NullOutputStream"/>
</appender>

NullOutputStream is used to eliminate I/O overhead during the test. The following micro benchmark issues 1,5 million logging statements to CLASS_INFO and 30 million statements to NO_CLASS_INFO logger. The latter one places some static text instead of dynamically generated class information. First 1/3 of iterations were discarded to allow JVM warm-up.

import org.junit.Test;
import org.perf4j.StopWatch;
import org.perf4j.slf4j.Slf4JStopWatch;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class LoggerTest {

    private static final Logger log = LoggerFactory.getLogger(LoggerTest.class);
    private static final Logger classInfoLog = LoggerFactory.getLogger("CLASS_INFO");
    private static final Logger noClassInfoLog = LoggerFactory.getLogger("NO_CLASS_INFO");

    private static final int REPETITIONS = 15;
    private static final int COUNT = 100000;

    @Test
    public void testClassInfo() throws Exception {
        for (int test = 0; test < REPETITIONS; ++test)
            testClassInfo(COUNT);
    }

    private void testClassInfo(final int count) {
        StopWatch watch = new Slf4JStopWatch("Class info");
        for (int i = 0; i < count; ++i)
            classInfoLog.info("Example message");
        printResults(count, watch);
    }

    @Test
    public void testNoClassInfo() throws Exception {
        for (int test = 0; test < REPETITIONS; ++test)
            testNoClassInfo(COUNT * 20);
    }

    private void testNoClassInfo(final int count) {
        StopWatch watch = new Slf4JStopWatch("No class info");
        for (int i = 0; i < count; ++i)
            noClassInfoLog.info("Example message");
        printResults(count, watch);
    }

    private void printResults(int count, StopWatch watch) {
        log.info("Test {} took {}ms (avg. {} ns/log)", new Object[]{
                watch.getTag(),
                watch.getElapsedTime(),
                watch.getElapsedTime() * 1000 * 1000 / count});
    }

}

As it turned out, on my computer the logger that produces class information reflectively worked 13 times slower (115 vs. 8.8 microseconds per logging statement, see chart below). Being a Java developer suggests that 100 microseconds is acceptable, but this also means more than 1% of the server time is wasted when logging , let’s say, 100 statements per second. Is it worth it?



Somewhat more advanced feature of logging frameworks is Mapped Diagnostic Context. MDC is simply a map managed on a thread-local basis. You can put any key-value pair in this map and since then every logging statement issued from this thread is going to have this value attached as part of the pattern. I need some more complex, multi threaded example to show you the benefits of this utility, so please be so kind and wait for my next articles.

• Clean code, clean logs: use appropriate tools (1/10)


• Clean code, clean logs: logging levels are there for you (2/10)


• Clean code, clean logs: do you know what you are logging? (3/10)


• Clean code, clean logs: avoid side effects (4/10)


• Clean code, clean logs: concise and descriptive (5/10)


• Clean code, clean logs: tune your pattern (6/10)


• Clean code, clean logs: log method arguments and return values (7/10)


• Clean code, clean logs: watch out for external systems (8/10)


• Clean code, clean logs: log exceptions properly (9/10)


• Clean code, clean logs: easy to read, easy to parse (10/10)

Clean code, clean logs: concise and descriptive (5/10)

Each logging statement should contain both data and description. Consider the following examples:

log.debug("Message processed");
log.debug(message.getJMSMessageID());
log.debug("Message with id '{}' processed", message.getJMSMessageID());

Which log would you like to see while diagnosing failure in an unknown application? Believe me, all the examples above are almost equally common. Another anti-pattern:

if(message instanceof TextMessage)
    //...
else
    log.warn("Unknown message type");

Was it so hard to include actual message type, message id, etc. in warning string? I know something went wrong, but what, what was the context? Third anti-pattern is "magic-log". Real life example: most programmers in the team knew that 3 ampersands followed by exclamation mark, followed by hash, followed by pseudorandom alphanumeric string log means "Message with XYZ id received". Nobody bothered to change the log, simply someone hit the keyboard and chose some unique "&&&!#" string, so that it can be easily found by himself.

As a consequence, the whole logs file looks like a random sequence of characters. Somebody might even consider that file to be a valid Perl program. But the logs file should be readable, clean and descriptive. Don't use magic numbers, log values, numbers, ids and include their context. Show the data being processed and show its meaning. Show what the program is actually doing. Good logs can serve as a great documentation of the application code itself.

Did I mention not to log passwords and any personal information? Don't!

• Clean code, clean logs: use appropriate tools (1/10)


• Clean code, clean logs: logging levels are there for you (2/10)


• Clean code, clean logs: do you know what you are logging? (3/10)


• Clean code, clean logs: avoid side effects (4/10)


• Clean code, clean logs: concise and descriptive (5/10)


• Clean code, clean logs: tune your pattern (6/10)


• Clean code, clean logs: log method arguments and return values (7/10)


• Clean code, clean logs: watch out for external systems (8/10)


• Clean code, clean logs: log exceptions properly (9/10)


• Clean code, clean logs: easy to read, easy to parse (10/10)

Clean code, clean logs: avoid side effects (4/10)

Logging statements should have no or little impact on application behavior. Recently a friend of mine gave an example of a system that threw Hibernates' LazyInitializationException only on some particular environment. As you’ve probably guessed from the context, some logging statement caused lazy initialized collection to be loaded when session was attached. On this environment the logging levels were increased and collection was no longer initialized. Think how long would it take you to find a bug without knowing this context?

Another side effect is slowing the application down. Quick answer: if you log too much or improperly use toString()/string concatenation, logging has a performance side effect. How big? Well, I have seen server restarting every 15 minutes because of a thread starvation caused by excessive logging. Now this is a side effect! From my experience, few hundreds of MiB is probably the upper limit of how much you can log onto disk per hour.

Of course if logging statement itself fails and causes business process to terminate due to exception, this is also a huge side effect. I have seen such a construct to avoid this:

try {
    log.trace("Id=" + request.getUser().getId() + " accesses " + manager.getPage().getUrl().toString())
} catch(NullPointerException e) {}

This is a real code, but please make the world a bit better place and don’t do it, ever. Anyway, I have already warned you about NPEs.

• Clean code, clean logs: use appropriate tools (1/10)


• Clean code, clean logs: logging levels are there for you (2/10)


• Clean code, clean logs: do you know what you are logging? (3/10)


• Clean code, clean logs: avoid side effects (4/10)


• Clean code, clean logs: concise and descriptive (5/10)


• Clean code, clean logs: tune your pattern (6/10)


• Clean code, clean logs: log method arguments and return values (7/10)


• Clean code, clean logs: watch out for external systems (8/10)


• Clean code, clean logs: log exceptions properly (9/10)


• Clean code, clean logs: easy to read, easy to parse (10/10)

Clean code, clean logs: do you know what you are logging? (3/10)

Every time you issue a logging statement, take a moment and have a look what exactly will land in your log file. Read your logs afterwards and spot malformed sentences. First of all, avoid NPEs like this:

log.debug("Processing request with id: {}", request.getId());

Are you absolutely sure that request is not null here? Another pitfall is logging collections. If you fetched collection of domain objects from the database using Hibernate and carelessly log them like here:

log.debug("Returning users: {}", users);

SLF4J will call toString() only when the statement is actually printed, which is quite nice. But if it does... Out of memory error, N+1 select problem, thread starvation (logging is synchronous!), lazy initialization exception, logs storage filled completely – each of these might occur.

It is a much better idea to log, for example, only ids of domain objects (or even only size of the collection). But making a collection of ids when having a collection of objects having getId() method is unbelievably difficult and cumbersome in Java. Groovy has a great spread operator (users*.id), in Java we can emulate it using Commons Beanutils library:

log.debug("Returning user ids: {}", collect(users, "id"));

Where collect() method can be implemented as follows:

public static Collection collect(Collection collection, String propertyName) {
    return CollectionUtils.collect(collection, new BeanToPropertyValueTransformer(propertyName));
}

Unfortunately the method above is not yet part of Commons Beanutils framework, but I have already filed up the request to make our lives easier (BEANUTILS-375).

The last thing is improper implementation or usage of toString(). First, create toString() for each class that appears anywhere in logging statements, preferably using ToStringBuilder (but not its reflective counterpart). Secondly, watch out for arrays and non-typical collections. Arrays and some strange collections might not have toString() implemented calling toString() of each item. Use Arrays #deepToString JDK utility method. And read your logs often to spot incorrectly formatted messages.

• Clean code, clean logs: use appropriate tools (1/10)


• Clean code, clean logs: logging levels are there for you (2/10)


• Clean code, clean logs: do you know what you are logging? (3/10)


• Clean code, clean logs: avoid side effects (4/10)


• Clean code, clean logs: concise and descriptive (5/10)


• Clean code, clean logs: tune your pattern (6/10)


• Clean code, clean logs: log method arguments and return values (7/10)


• Clean code, clean logs: watch out for external systems (8/10)


• Clean code, clean logs: log exceptions properly (9/10)


• Clean code, clean logs: easy to read, easy to parse (10/10)

Clean code, clean logs: logging levels are there for you (2/10)

Every time you are making a logging statement, you think hard which logging level is appropriate for this type of event, do you? Somehow 90% of programmers never pay attention to logging levels, simply logging everything on the same level, typically INFO or DEBUG. Why? Logging frameworks have two major benefits over System.out: categories and levels. Both allow you to selectively filter logging statements permanently or only for diagnostics time. If you really can’t see the difference, print this table and look at it every time you start typing "log." in your IDE:

ERROR – something terribly wrong had happened, that must be investigated immediately. No system can tolerate items logged on this level. Example: NPE, database unavailable, mission critical use case cannot be continued.

WARN – the process might be continued, but take extra caution. Actually I always wanted to have two levels here: one for obvious problems where work-around exists (for example: "Current data unavailable, using cached values") and second (name it: ATTENTION) for potential problems and suggestions. Example: "Application running in development mode" or "Administration console is not secured with a password". The application can tolerate warning messages, but they should always be justified and examined.

INFO – Important business process has finished. In ideal world, administrator or advanced user should be able to understand INFO messages and quickly find out what the application is doing. For example if an application is all about booking airplane tickets, there should be only one INFO statement per each ticket saying "[Who] booked ticket from [Where] to [Where]". Other definition of INFO message: each action that changes the state of the application significantly (database update, external system request).

DEBUG – Developers stuff. I will discuss later what sort of information deserves to be logged.

TRACE – Very detailed information, intended only for development. You might keep trace messages for a short period of time after deployment on production environment, but treat these log statements as temporary, that should or might be turned-off eventually. The distinction between DEBUG and TRACE is the most difficult, but if you put logging statement and remove it after the feature has been developed and tested, it should probably be on TRACE level.

The list above is just a suggestion, you can create your own set of instructions to follow, but it is important to have any. Although my experience is that always, everything is logged without filtering (at least from the application code), having the ability to quickly filter logs and extract the information with proper detail level might be a life-saver.

The last thing worth mentioning is infamous is*Enabled() condition. Some put it before every logging statement:

if(log.isDebugEnabled())
    log.debug("Place for your commercial");

Personally, I find this idiom being just a clutter that should be avoided. The performance improvement (especially when using SLF4J pattern substitution discussed previously) seems irrelevant and smells like a premature optimization. Also, can you spot the duplication? There are very rare cases when having explicit condition is justified – when we can prove that constructing logging message is expensive. In other situations, just do your job of logging and let logging framework do its job (filtering).

• Clean code, clean logs: use appropriate tools (1/10)


• Clean code, clean logs: logging levels are there for you (2/10)


• Clean code, clean logs: do you know what you are logging? (3/10)


• Clean code, clean logs: avoid side effects (4/10)


• Clean code, clean logs: concise and descriptive (5/10)


• Clean code, clean logs: tune your pattern (6/10)


• Clean code, clean logs: log method arguments and return values (7/10)


• Clean code, clean logs: watch out for external systems (8/10)


• Clean code, clean logs: log exceptions properly (9/10)


• Clean code, clean logs: easy to read, easy to parse (10/10)

Clean code, clean logs: use appropriate tools (1/10)

Many programmers seem to forget how logging application behavior and its current activity is important. When somebody puts:

log.info("!@#$%");

happily somewhere in the code, he probably don't realize the importance of application logs during maintenance, tuning and failure identification. Underestimating the value of good logs is a terrible mistake. I have collected few random advices that I find especially useful when it comes to writing logging routines and I will present them in a series of short articles. First tip (out of ten) is about logging libraries and tools.

In my opinion, SLF4J is the best logging API available, mostly because of a great pattern substitution support:

log.debug("Found {} records matching filter: '{}'", records, filter);

In Log4j you would have to use:

log.debug("Found " + records + " records matching filter: '" + filter + "'");

This is not only longer and less readable, but also inefficient because of extensive use of string concatenation. SLF4J adds nice {} substitution feature. Also, because string concatenation is avoided and toString() is not called if the logging statement is filtered, there is no need for isDebugEnabled() anymore. BTW, have you noticed single quotes around filter string parameter?

SLF4J is just a façade, as an implementation I would recommend Logback framework, already advertised on my blog, instead of well established Log4J. It has many interesting features (some of them will be discussed in future tips) and, in contrary to Log4J, is actively developed.

The last tool to recommend is Perf4J. To quote their motto:

Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()

I've added Perf4J to one existing application under heavy load and seen it in action in few other. Both administrators and business users were impressed by the nice graphs produced by this simple utility. Also we were able to discover performance flaws in no time. Perf4J itself deserves its own article, but for now just check their Developer Guide.

To summarize, this is the ideal pom.xml excerpt to start with:

<repositories>
    <repository>
        <id>Version99</id>
        <name>Version 99 Does Not Exist Maven repository</name>
        <layout>default</layout>
        <url>http://no-commons-logging.zapto.org/mvn2</url>
    </repository>
</repositories>


<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.5.11</version>
</dependency>
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>0.9.20</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>jul-to-slf4j</artifactId>
    <version>1.5.11</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>log4j-over-slf4j</artifactId>
    <version>1.5.11</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>jcl-over-slf4j</artifactId>
    <version>1.5.11</version>
</dependency>
<dependency>
    <groupId>commons-logging</groupId>
    <artifactId>commons-logging</artifactId>
    <version>99.0-does-not-exist</version>
</dependency>

To test this, try the following code:

SLF4JBridgeHandler.install();

org.apache.log4j.Logger.getLogger("A").info("Log4J");
java.util.logging.Logger.getLogger("B").info("java.util.logging");
org.apache.commons.logging.LogFactory.getLog("C").info("commons-logging");
org.slf4j.LoggerFactory.getLogger("D").info("Logback via SLF4J");

As you can see, no matter which logging framework is used (we don't even have Log4J and Commons-Logging on our CLASSPATH, see 99.0-does-not-exist version!), every logging statement is printed using Logback (see how it works). So even if your favorite libraries stick to Commons-Logging (very bad thing! [1], [2]) or even worse to Log4J, you don't need to include them in your project.


UPDATE: Ceki Gülcü (founder of the Log4J, SLF4J and Logback projects) suggested simplier approach to get rid of commons-logging dependency (see his comment).

• Clean code, clean logs: use appropriate tools (1/10)


• Clean code, clean logs: logging levels are there for you (2/10)


• Clean code, clean logs: do you know what you are logging? (3/10)


• Clean code, clean logs: avoid side effects (4/10)


• Clean code, clean logs: concise and descriptive (5/10)


• Clean code, clean logs: tune your pattern (6/10)


• Clean code, clean logs: log method arguments and return values (7/10)


• Clean code, clean logs: watch out for external systems (8/10)


• Clean code, clean logs: log exceptions properly (9/10)


• Clean code, clean logs: easy to read, easy to parse (10/10)