Logging Best Practices for JBoss Projects
What This Is
This document outlines best practices for developers of JBoss projects with regards to logging. The goal of this document is to help make the server logs of JBossAS more readable and consistent, and overall more pleasant and usable for the end user as well as support teams.
Note: this page is a work in progress and is not yet final.
What This is Not
This page is not a help page on how to configure or read logs. For coverage of these topics, see: Logging.
This page also does not cover how to use or replace the JBossAS logging subsystem; for discussion of this topic, see the logging section of the process guide.
Terms
When using the terms "higher" or "lower" in relationship to log levels, "higher" means "increasing severity", so tending towards FATAL/SEVERE level, and "lower" means "decreasing severity", tending towards TRACE/FINEST level.
The Guidelines
In no particular order:
Log a ONE-TIME message at level INFO that shows the name and version of the module. Use your root category for this message. Note: what about multiple instances with different classloaders?
Example:
2007-06-07 11:11:08,519 INFO [org.jboss.foobar] JBoss FooBar version 1.10
To guarantee that the message is only logged once, do it from within a static initializer block.
Example using java.util.logging:
package org.jboss.foobar.whatever;
//...
public class SomeUltimateBaseFactory {
//...
static {
Logger.getLogger("org.jboss.foobar").info("JBoss FooBar version 1.10");
}
//...
}
Use consistent category names. If your project is called "JBoss FooBar", always have your category name start with "com.jboss.foobar" or "org.jboss.foobar". Note: when to use which?
Do not use System.out or System.err as a log. Always prefer the logging framework.
When handling exceptions, either log the exception, or rethrow it. Never do both. This leads to log spam. It is not useful to the user to see the same stack trace 9 times in a row in the log, once for every time it is rewrapped.
When logging an exception, consider whether it is appropriate to log a complete stack trace. Sometimes it might be more appropriate to just log the exception message, and only log the complete trace if debugging is enabled.
Example using java.util.logging:
//...
} catch (IOException ex) {
String msg = "Saving file failed; an exception of type " + ex.getClass().getName() +
" was thrown with the message: " + ex.getMessage();
if (log.isLoggingEnabled(Level.FINE)) {
log.log(Level.WARNING, msg, ex);
} else {
log.warning(msg);
}
}
//...
When an exception has to be wrapped, consider whether it is more appropriate to just change the exception type than to wrap the exception. Does it really add value to have a whole separate stack trace to show the user where you caught and rethrew the exception?
Example:
//...
} catch (IOException ioex) {
final FacesException faex =
new FacesException("Error uploading file: " + ioex.getMessage());
faex.setStackTrace(ioex.getStackTrace());
throw faex;
}
//...
For new projects which use logging, you should be using JBoss Logging, or in lieu of that, a different modern logging API such as slf4j.
Do not programmatically change the log level of any of your categories (or anyone else's, for that matter) from within your module.
Don't log progress, debugging, profiling, or classpath dump messages at level INFO or higher. You may be excited that your service starts up in 46 milliseconds, but end users probably don't care. These types of messages are better logged at DEBUG/FINE or lower. Note: could use some examples here.
Make sure your log messages are logged to the appropriate levels! Specifically, repetitive (periodic) information or information associated with requests should be logged at level TRACE or FINEST. Here's how the levels should be used (taken from the process guide):
FATAL - Use the FATAL level priority for events that indicate a critical service failure. If a service issues a FATAL error it is completely unable to service requests of any kind. Note - JDK logging does not have a corresponding level by default.
ERROR/SEVERE - Use the ERROR/SEVERE level priority for events that indicate a disruption in a request or the ability to service a request. A service should have some capacity to continue to service requests in the presence of ERROR/SEVEREs.
WARN/WARNING - Use the WARN level priority for events that may indicate a non-critical service error. Resumable errors, or minor breaches in request expectations fall into this category. The distinction between WARN and ERROR may be hard to discern and so its up to the developer to judge. The simplest criterion is would this failure result in a user support call. If it would use ERROR/SEVERE. If it would not use WARN.
INFO - Use the INFO level priority for service life-cycle events and other crucial related information. Looking at the INFO messages for a given service category should tell you exactly what state the service is in. A general rule of thumb for INFO is: Will the user normally find this information useful?
DEBUG/FINE - Use the DEBUG level priority for log messages that convey extra information regarding life-cycle events. Developer or in depth information required for support is the basis for this priority. The important point is that when the DEBUG/FINE level priority is enabled, the JBoss server log should not grow proportionally with the number of server requests. Looking at the DEBUG/FINE and INFO messages for a given service category should tell you exactly what state the service is in, as well as what server resources it is using: ports, interfaces, log files, etc.
TRACE/FINEST - Use the TRACE/FINEST level priority for log messages that are directly associated with activity that corresponds requests. Further, such messages should not be submitted to a Logger unless the Logger category priority threshold indicates that the message will be rendered. Use the Logger.isTraceEnabled() method to determine if the category priority threshold is enabled. The point of the TRACE priority is to allow for deep probing of the JBoss server behavior when necessary. When the TRACE level priority is enabled, you can expect the number of messages in the JBoss server log to grow in proportion to the number of concurrent clients/requests and also in proportion to the uptime of the server.
Comments