Logging Guidelines
Logging Goals
The following is a list of goals for the logging policy. They are considered essential to succesful logging.
- Context
- Where did logging event happen
- What is the relevant local information
- Analysis
- Being able to filter the log for specific classes
- Be able to pinpoint line, method, and class where an exception happened
- Changing of log levels on the fly
- No, or only small, redundancy in log informations
Premises
The following points are assumed to be available/implemented in the code base, and the rest of this document relies on these premises.
No exceptions are dropped, all are caught and dealt with somewhere.
- Exceptions have meaningful messages providing context information about the exception
- Exceptions are never re-thrown (wrapping a cause in another exception is legal)
- The logging framework automatically prints class- and thread names
- Commons logging is used in the code
Nice to Have, but Not Required
- Log4J as the back-end for the logging. This is due to the large amount of tools for this framework.
Remote controlling of logging levels. For example being able to cherry pick a single class and have logging on, say, trace level for that single class via a JMX interface to the logging framework.
Setting Up A Logger
To instantiate a Log object do
import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; private Log log = LogFactory.getLog(getClass());
Generally think twice before you create a static Log instance since it might end up as a shared instance if you write a library that is shared between several applications in an application container. As a rule of thumb do not use static Log instance in a library. To instantiate a Log for use in static context do
private static Log log = LogFactory.getLog(MySweetApp.class);
By default commons-logging will look for a logging implementation in your class path. We use Log4J. If Log4J is found it will look for a configuration called log4j.xml. For guidelines on how to write a Log4J configuration refer to the native Log4J documentation.
General Logging Guidelines
No static checks for logging level, for example
static final boolean isTraceEnabled = log.isTraceEnabled();
...
// DON'T DO THIS
if (isTraceEnabled) {
log.trace("We're traced!!!1")
}
// BUT DO
if (log.isTraceEnabled()) {
log.trace ("Don't you just love tracing?");
}Log variable values not just plain messages, and if the object has some kind of unique id log this with all messages. For example
// DON'T
log.fatal("Fatality!");
// BUT DO
log.fatal("Inconsistent state. Expected STORED, got '" + getStatus() + "'");Quote strings, for example
log.warn ("Identity '" + identity + "' unknown");Don't log when throwing exceptions: As a rule of thumb, there shouldn't be a log statement before an Exception is thrown. Instead, the Exception should contain at least the same amount of information as the log statement would have contained. This reduces duplicate log entries.
Always Log Handled Exceptions: As a rule of thumb always log when you handle an exception - this regardless whether it is a Fault or Contingency. Logging Faults is pretty much given and should generally be on error or warn levels. Logging of Contingencies is generally logged on debug, but cases of key branch points of the control flow may be on higher levels.
Make proper variable outputs: The utility Logs in sbutil contains methods for converting arrays and similar structures to Strings. Consider using these for easy logging, for example
...
List<String> rodents = getRodents();
ArrayList<List<String>> birds = getBirds();
Logs.log(log, Logs.Level.DEBUG, "Processing small animals", rodents, birds);
...will add an entry to log at debug-level with the String "Processing small animals" followed by the first entries in the arrays rodents and birds.
Another example:
...
String[] birds = new String[]{"Owl", "Blackbird", "Sparrow", "Seagull", "Albatros"};
log.debug("Doing the birds " + Logs.expand(birds));
...will give the log-entry Doing the birds (Owl, Blackbird, Sparrow ...2...)
Fatal
There is reason to assume that the state of the application is compromised in such a way that it is impossible, or requires user interaction, to recover. Example
catch (NoSpaceLeftOnDeviceException e) {
log.fatal ("Error updating storage: " + storage.getFile()
+ "Sleeping until interrupted", e);
while (true) {
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
log.info ("Back online, retrying storage update");
break;
}
}
Error
The class encountered an error and cannot complete the given assignment. The internal state of the class/object might have been compromised. Note: The exception policy states that you do not log exceptions if you pass them on or throw them. As a rule of thumb logging exceptions on error level is done by fault handlers. The following example can be regarded as a local fault barrier:
public void doMassiveIngest (BigRecordStore store) {
...
for (Record rec : store) {
try {
ingest (rec);
} catch (XMLParseException e) {
log.error ("Invalid xml in record '" + rec + "', skipping", e);
}
}
...
}
Warn
The class encountered a condition that should not happen under optimal circumstances, but may happen occasionally. The given assignment was completed, but the result should be verified.
public void doMassiveIngest (BigRecordStore store) {
...
for (Record rec : store) {
try {
ingest (rec);
} catch (XMLParseException e) {
try {
log.warn ("Failed to parse record '" + rec + "', trying sloppy ingest", e);
doSloppyIngest (rec);
} catch (MalformedRecordException e) {
log.error ("Failed sloppy ingest of '" + rec + "', skipping", e);
}
}
}
...
}
Info
This level can be used under normal operations. Any significant events on application level are logged here. Small utility classes would not use this level, even though events are significant in the scope of the class.
public void doMassiveIngest (BigRecordStore store) {
log.info ("Starting ingest of " + store.getSize() + " records from " + store.getUrl());
for (Record rec : store) {
...
}
log.info ("Ingest done. Ingested " + succesCount + " records from " + store.getUrl());
}
Debug
Any significant events on class level. This means that utility classes would log on this level. The information logged should not require massive processing or long waits. Actual data should only be logged sample-wise, fx every ten iteration in a loop. Under intensive operations it is advised to check for the logging level.
public void doMassiveIngest (BigRecordStore store) {
...
for (Record rec : store) {
if (count % 100 == 0) {
log.debug ("Ingested record #" + count + "/" + store.getSize() + ". ETA: " + profiler.getETA() + " for storage " + store.getUrl());
}
}
...
}
Trace
Each (non-trivial (read: get/set)) method must log its name and arguments on the first line. This overrules the codestyle guideline about placing local variable declaration at the top of the block. In case of non-deterministic termination times (network communications) it is advised to log the method-return as well. Under intensive operations it is advised to check for the logging level.
public void doMassiveIngest (BigRecordStore store) {
log.info ("Starting ingest of " + store.getSize() + " records from " + store.getUrl());
...
for (Record rec : store) {
ingestRecord (rec);
...
}
...
log.info ("Ingest done. Ingested " + succesCount + " records from " + store.getUrl());
}
public void ingestRecord (Record rec) {
if (log.isTraceEnabled()) log.trace ("enter ingestRecord(" + rec + ")");
...
if (log.isTraceEnabled()) log.trace ("exit ingestRecord(" + rec + ")");
}
Outstanding Issues
Application/Workflow log
Have a global (cross-module) shared log that tracks only events that are significant on the system level. The target audience of this log is not the programmers, but general system consumers. One use case could be to show the last log line on a website.
It has not yet been decided how such a global log should be constructed. There has been a slight favor for creating it from a digest of the application log. This has the advantage of being manageable without changes in the running code.