Thursday, September 11, 2014

Java Application Logging Guidelines

Here are some guidelines or "best practices" for logging; they're hard-earned lessons from my own 17+ years' experience writing Java code as well as several other sources.

First and foremost: use slf4j​ exclusively as logging API, with logback ​as the underlying logging implementation.​ slf4j is a flexible API that can utilize any of the popular logging frameworks (logback, log4j, java.util.logging, etc) at runtime to provide the low-level logging implementation. As such, the only dependency in application components should be on the slf4j API; no class should reference any other logging interfaces.

Read your logs often to spot incorrectly formatted messages.​ 

This seems obvious, but I'm always surprised/appalled by how many developers blindly send stuff to log without ever looking at most of it in runtime. If you read nothing else in these guidelines, please please please at least heed this advice.

​Use Levels Appropriately

For every logging statement, think about which level is most appropriate.
  • ERROR – something irreparably wrong has happened that should be investigated immediately. No system can tolerate items logged on this level. Examples: NPE, database unavailable, mission critical use case cannot be continued.

  • WARN – the process might be continued, but take extra caution. This can indicate an obvious problem where some codified work-around exists (for example: “Current data unavailable, using cached values”), or a potential problem and suggestions (for 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 – an important business process or system event has happened. Generally, an administrator or advanced user should be able to understand INFO messages and quickly find out what the application is doing. Another use for INFO messages is to indicate significant changes to the state of the application (e.g., database update, external system request).

  • DEBUG – information that is useful only to developers. DEBUG level should be disabled in any deployment environment other than DEV and possibly TEST, so it is not to be relied upon for routine troubleshooting by non-developers.


Do not use isXyzEnabled() checks around log statements.

For example:
if (log.isDebugEnabled())​ 
    log.debug("Something happened");​
This idiom clutters the code and provides no real performance benefit when using slf4j's pattern substitution. There are very rare cases when having explicit condition is justified, e.g., when we can prove that constructing a specific logging message is expensive​.

Review the information that gets logged

Every time you issue a logging statement, take a moment to examine what exactly will land in the log file. Read your logs afterwards and spot problems, etc.

Here are some common pitfalls to avoid:
  • Avoid NPEs like this:
    ​log.debug("Processing request with id: {}", request.getId());​
    This can be dangerous because request might be null.​​

  • Be careful when logging collections. Collections can include objects that are expensive or impossible to log, such as entities fetched via JPA/Hibernate. Instead, consider logging just summary information about the elements of a collection, such as IDs.

Implement toString() carefully.

Create toString() for each class that appears anywhere in logging statements, preferably using ToStringBuilder (but not its reflective counterpart).
Watch out for arrays and non-typical collections. Arrays and some strange collections might not have toString() implemented by calling toString() of each item. Use the Arrays.deepToString() JDK utility method.

Read your logs often to spot incorrectly formatted messages.​

Yes, it's already said above. But it's important enough to repeat.

​Avoid side effects.

​Logging statements should have no impact on the application’s behavior.​ Too much logging or incorrect implementation of toString() can impact application performance. Failed logging statements can cause a business process to terminate due to an exception (see the request.getID() example above). Avoid these situations by double-checking the safety of logging statements and write unit tests that trigger all possible logging scenarios.

​​Be concise and descriptive.

​​​​Most logging statements should include both data and description. Always include relevant context in the statement. 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.​

Consider these examples:
log.debug("Message processed"); // No data, only description
log.debug(message.getJMSMessageID()); // No description, only data
log.debug("Message with id '{}' processed", message.getJMSMessageID());​
The last one is clearly preferred. The first two do not provide enough information to diagnose a problem or understanding what's happening.

​​Log more details when communicating with external systems​.

​When communicating with external systems, consider logging all the incoming and outgoing data. The overhead of doing this can be large, so consider the decision carefully and use the DEBUG level for such log statements so that they won't affect production performance under normal circumstances. Because this kind of logging is mostly useful during development and testing, consider using the following pattern:
Collection​ entities = findSomeEntities();
if (log.isDebugEnabled()) {
    log.debug("Processing entities: {}", entities);
} else {
    log.info("Processing {} entities", entities.size());
}
With this pattern, full details about the entities will be logged only when the logger is configured at the DEBUG level, otherwise only summary information is logged. Remember the other guideline above and make sure that entities can not be null to avoid a NPE when logger is configured at INFO. Yes, this violates the guideline to NOT do log level checking in code, but this is a great example of understanding the reasons for a guideline and when it should not apply. In this case, which should be used rarely, the isDebugEnabled() check actually makes the logging better, not just adds clutter to the code.

Log Exceptions Properly

​As a general rule, it should be preferred to not log exceptions at all, but rather re-throw (or wrap and throw) them to let a higher layer handle them. But at some point (usually at the highest layer of the application, such as the controllers), logging exceptions is necessary.
Follow these guidelines when doing so:
  • ​​If you re-throw or wrap-and-rethrow the exception, do not log it. This is bad:
    try {
        // ....
    } catch (IOException ex) {
        log.error("Something bad happened", ex);
    ​    throw new MyCustomException(ex);
    }
    
    That is a problem because it results in duplicate statements of the same stack trace in the log file.

  • ​When an exception is logged, make sure to use the correct call that will result in complete and useful details. The correct form is:
    log.error("Describe what was going on here", ex);
    The following are all incorrect, none will produce the desired result in the log file. Don't do any of these:
    log.error(ex); 
    log.error("" + ex); 
    log.error(ex.toString()); 
    log.error(ex.getMessage()); 
    log.error(null, ex); 
    log.error("{}", ex); 
    log.error("{}", ex.getMessage()); 
    log.error("Describe what was going on here: " + ex); 
    log.error("Describe what was going on here: " + ex.getMessage()​);
    

Read your logs often to spot incorrectly formatted messages.​

One last time, this is the most important advice. Heed it. Seriously.


Sources:

1 comment:

Unknown said...

Thanks for excellent clear guidelines. I've recommended this article as mandatory reading for my current project.

Love you last recommendation - people who know me, would think I added this.