Thursday, April 15

While I, in no way, feel that I am the expert in this area this is how I select which log level I use for a message. The number of applications that fail to have a coherent strategy for this is mind boggling. Logging should not be a second thought or something that doesn't matter. Especially when fixing a bug is extremely time sensitive, the more information you can concisely pack into a log message the better. So here are the guidelines I use for selecting the log level I am going to use.

Debug - Messages necessary for debugging a piece of functionality. A value of some sort should always be appended to the message as there is very little that can be gleaned from the state of the application if you don't know some values. If there is only one concatenation, I am not concerned with enclosing it in isDebugEnabled, but if there are more than one, if you have an object that calls toString() or if you have multiple log statements, it should be enclosed in isDebugEnabled.

Info - Informational messages, can be anywhere but these should be used very infrequently. These should not be concatenated so there is no real reason to use isInfoEnabled. An example of an info message would be to notify a user who is watching the log that a long running process has finished or something like that.

Warn - Use these whenever the application is in danger of getting into a state that could cause an issue. For instance, if a call to the database returns 2 values when it should have only returned one but it is still valid to just take the top one, it would be prudent to log a warning to say what is happening so, if it ends up causing a problem we can see it in the log. Also, warnings are typically the default level used in production applications by default. That means that, from warn on, you can usually count on the message getting logged even in production. When choosing if I'm going to append information from the state of the application, I try to be very careful to take the impact of that decision into consideration.

Error - This should be self explanatory. I will stop short of saying this should be in every exception handling block, but it should be in most. At the very least it provides a way for us to know when an exception occurs where it is normally swallowed. I will say that we should NEVER, EVER swallow exceptions. By swallowing, I mean: try { ... } catch (Exception e) {//no code to handle the exception}. A log message is the very least we can do. In addition, the method log.error(String message, Throwable t) is the only one to use here. Do not append the output of e.getMessage() as the really useful information is in the stack trace and should be captured.

Fatal - I don't think there is much reason to do this in web applications, but if we do find a place, this is for problems that will probably take the server down. Losing connectivity to the database would be an example of a fatal exception where we would need to restart the machine.

There are two caveats to this list. Some loggers include a trace level. I feel this is unnecessary and, if it is actually done, should probably be done by injection with AOP. The idea of cluttering up the code with "entering this method... ", exiting this method..." makes me shudder. If I wanted to read through 25 lines of log messages in order to get to the real code.... well... I don't want to do that.

The second caveat is some applications have a monitoring tool like Nagios that looks for errors and sends out an alert. If this is the case in your system, you probably either want to be discrete with your use of error, monitor fatal instead of error or implement your own log level for bugs that are serious enough to set off a pager at 3 am. I think, in most cases, I personally like the 2nd option because most applications have no need for Fatal and, when you do get one it is cause for serious concern.

So that's my method. Perhaps some of you out there have others. Remember, sharing is a good thing. :)