= 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 [[http://logging.apache.org/log4j/1.2/publications.html|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| 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.