Log at the correct level

We all know the importance of having good, clear, and useful log messages in our applications (if not then I suggest you read "Release It" from the Pragmatic bookshelf). However it is not always apparent that log messages are written at the correct level.

For example, Log4J has a number of log levels; trace, debug, info, warn, error and fatal. While it looks like its clear what you should log at each level, some major players get it wrong.

I’ve spent the last day looking into issues in JBoss Portal where my custom login module wasn’t working correctly. There was nothing unusual in the log, nor were any errors written to the screen, no indication as to what the problem might have been. After much staring at the config files, it turned out that the package name was wrong, resulting in a ClassNotFoundException. 2 seconds to fix and a few minutes to start the portal and we’re elected.

However, all of this could have been avoided if JBoss was logging something as important as a ClassNotFoundException at a level other than TRACE (see JIRA, TWITTER). At least ERROR, and probably even FATAL (given the severity of not having a login module) would have been appropriate.

The same issue can be seen with exceptions from the portlets themselves. JBoss logs these at INFO level, which is inappropriate as an exception emitting from the portlet’s execution stack will have resulted in the user experiencing an error.

So what are appropriate uses of the log levels?

TRACE – method entry/exit points, logging of method parameters, any other information that is only useful when tracing why something has gone wrong. This level will generate orders of magnitude more data than the other levels, so should only be enabled selectively on classes when diagnosing issues. Of course, that is not to say that it should only be written selectively, it should be everywhere (introduced using Aspects for the majority of cases), and it must be wrapped by if (logger.isTraceEnabled() when using string concatenation for performance reasons).

DEBUG – information relevant for the majority of debug cases, where we aim to get to the bottom of the problem without resorting to TRACE logging. E.g. database access information, generated SQL statements, etc. As with TRACE, these messages must be wrapped in if (logger.isDebugEnabled()).

INFO – informative messages from the application. e.g. Database insert took 500 ms, or HTTP POST received containing 600 bytes. These messages should be wrapped in if (logger.isInfoEnabled()).

WARN – something MAY be going wrong, but we’ve managed to recover from it for now. e.g. HTTP connection dropped, retrying.

ERROR – something HAS gone wrong, but its limited to the scope of a single user, or single operation. e.g. Database constraint violation, key already exists.

FATAL – something HAS SERIOUSLY went wrong. These errors affect multiple users, or multiple operations on the system. They usually need immediate action as the system may no longer be in operation. e.g. Database error: Database has gone away.

Using these simple rules, its not difficult to choose the correct level to log at. By doing so you’ll make life easier for the next guy.