wiki:LoggingGuidelines

Logging Guidelines

Description

This note describes guidelines for logging using log4j when developing code, or more specifically, code committed to the subversion repository.

Introduction

log4j Components

log4j supports loggers, appenders, and layouts:

  • Loggers - Normally defined for a class or a package
  • Appenders - Send log output to different devices
  • Layouts - Include desired source information and adapt output to suitable form

Logger Configuration

The logging functionality is controlled by a single configuration file, which for Proteios is found at the path www/WEB-INF/classes/log4j.properties relative to the Tomcat directory Proteios is installed in. Since this file is overwritten everytime you rebuild the software with command "ant dist", any changes that you want to have a longer lifespan should be made in the source configuration file client/servlet/conf/log4j.properties.

Use of different loggers makes it simple to configure the logging to be restricted to, or more detailed, for the class or package you are currently working on. The level of detail can be controlled by a simple filter, selecting what log messages to use depending on the level configured for a specific logger (a log message is either used or not, there does not exist alternatives such as "short", "medium", and "long" versions of the output). All log messages with a level equal to or higher than the one configured are used.

Logger Methods

The level of a log message is defined by the log4j logger method used to create it:

Method Level Intended Use
debug() lowest Detailed information to developer.
info() lowest + 1 General information on application progress.
warn() lowest + 2 Potential problems.
error() lowest + 3 Error not stopping application.
fatal() highest = lowest + 4 Severe error after which application cannot continue.

The coupling between method name/usage and level is not without problems, and what method to choose is not always unambiguous from the intended usage. Especially the choice between debug and info, as well as warn and error is often problematic.

Recommendations and Examples

Call of Logger

The log4j logger is imported by the following command

import org.apache.log4j.Logger;

For performance reasons it is recommended to create a constant logger object to use for logging calls, instead of using nested calls, e.g. use

private static final Logger log = Logger.getLogger(TableFactory.class);
...
log.debug("myStuff = " + myStuff);

instead of

Logger.getLogger(TableFactory.class).debug("myStuff = " + myStuff);

The logger object may be declared protected, if it is intended to be used in subclasses:

protected static final Logger log = Logger.getLogger("org.proteios.method");

If a single logger object is to be used in a class/package, the name log is recommended for the logger. This makes it easy to recognize and find logging calls in the code.

Logger Method Use

Issues influencing the choice of log method/level:

  • Very frequent logging may slow down the application
  • Very frequent logging may result in a bloated log file
  • A close coupling between log method and message type makes it easier to find certain event types by parsing the log file based on the method name/level.

The choice between debug and info calls is mostly based on performance issues.

Calls of warn, error, and fatal are mostly found in conditionals or in the catch section of try-catch blocks, which restricts the frequency of their activation. The choice between these methods is mostly based on the desire to couple the method to the event type triggering it.

Method Level Recommended Use
debug() lowest Logging of frequently processed code, e.g. in inner loops of nested iterations.
info() lowest + 1 Used restrictively, and at key places in the code, e.g. beginning and end of major operations.
warn() lowest + 2 Possibly harmful situations (but not necessarily).
error() lowest + 3 Unexpected situations not stopping the application.
fatal() highest = lowest + 4 Special cases, e.g. startup failure.

General Advice

The following recommendations are intended to make the log output as useful as possible. Please don't be offended if you find that some of them should be self-evident for a programmer, just regard these items as part of a check list.

  • Log messages triggered by a failed assertion should contain the variable values causing the failure, e.g. instead of a message "... size != numItems", use something like "... size (24) != numItems (25)", which gives more information on the conditions of the failure. This is of most help when a user reports a problem, and it is not easy to change the code and repeat the operation.
  • If the object you want to log some property for can be null, be sure to check for a null value before calling the object's methods, otherwise a null pointer exception will follow, making the application halt because of the logging. Either check explicitly for a null value in a conditional, or use the implicit toString() method of the object when creating the log message, if this will produce the desired information (note that while a call log.debug("myStuff = " + myStuff) will work also when myStuff is null, explicitly calling the toString() method log.debug("myStuff = " + myStuff.toString()) will not). This is of course not restricted to logging, but the problem often occurs here, as many logging calls are located in places of the code that are used under a wide range of conditions, and logging calls therefore need to be extra robust.
  • When reporting values of string variables that may contain leading or trailing spaces, e.g. a string input by a user, it is recommended to enclose the string value in double quotes, e.g. log.debug("userEntry = \"" + userEntry + "\""). A special problem is when the string can be both null and be equal to the four-letter word "null", as both will result in the output userEntry = "null". In this case it is best to first explicitly check for a null value, and report this without double quotes, e.g. userEntry = null.

Example of Log Configuration

Example entries in log4j.properties configuration file:

### direct log messages to stdout ###
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}::%M:%L - %m%n
...
### TableFactory logger
log4j.logger.org.proteios.gui.table.TableFactory=debug
...

Logging call in gui/table/TableFactory.java, private method Table addStateInformation(Table table), line 1240:

log.debug("getMaxResults() = " + getMaxResults());

Log output:

17:57:34,134 DEBUG TableFactory::addStateInformation:1240 - getMaxResults() = 20

The options for PatternLayout can be found in the log4j javadoc at http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/PatternLayout.html

The conversion pattern used in the example above can be interpreted as follows (for details see the javadoc for PatternLayout):

Pattern %d{ABSOLUTE} %5p %c{1}::%M:%L - %m%n
Output in Example 17:57:34,134 DEBUG TableFactory::addStateInformation:1240 - getMaxResults() = 20


Conversion Specifier Effect Output in Example
%d{ABSOLUTE} Date in AbsoluteTimeDateFormat (default is time only!) 17:57:34,134
%5p Priority with width of 5 characters DEBUG
%c{1} Class name, 1 of right most components of the full class name TableFactory
:: Verbatim text, here two colons ::
%M Method name addStateInformation
: Verbatim text, here a colon :
%L Line number of logging request 1240
- Verbatim text, here " - " -
%m Application supplied log message getMaxResults() = 20
%n Platform dependent line separator

Note that the %M and %L conversion specifiers for output of method and line number, respectively, are described as "extremely slow" in the javadoc. However, they can also be extremely helpful, so you have to weigh the pros and cons against each other. An example configuration including line number, but no method name is shown below:

Pattern %d{ABSOLUTE} %5p %c{1}:%L - %m%n
Output in Example 17:57:34,134 DEBUG TableFactory:1240 - getMaxResults() = 20

References

  1. The home page for log4j 1.2 can be found at http://logging.apache.org/log4j/1.2/.
Last modified 14 years ago Last modified on Dec 10, 2007, 2:34:01 PM