Logging
Steven J Zeil
Abstract
Even with the best of unit testing practices, code will fail and will need to be debugged.
Logging messages provide the documentation of both successful and failed executions vital to such debugging.
1 Logging
Programs often need to produce output that is not part of their primary behaviors but that let the operators know what is going on. For example, we might want to see
- Status messages indicating that the program has started, stopped, is still running, or has moved on from one major computation to another.
- Error messages indicating that something has gone wrong.
- Warning messages indicating that something might be going wrong.
- Debugging output designed to track down the cause of an error.
You’ve probably run programs that failed silently, and know how frustrating that can be. You may have run programs that print this kind of output on your screen. You may have run programs where error messages pop up on your screen in dialog boxes that must be dismissed before you can continue. You may have run programs where messages get written into files tucked away in out-of-the-way directories. And you may have run programs that employ a mishmash of these techniques.
Well-managed projects gather these messaging requirements into a logging standard for each project, so that these various messages get handled in a uniform manner throughout the code.
In Martin’s chapter on Error Handling as part of Clean Coding, he showed code that assumed the availability of a log function for handling such outputs. Where did that come from? He took for granted that the program had set up a good logging framework.
2 Logging Frameworks
A typical logging framework provides
- A set of functions for writing messages at a variety of different severity levels (e.g., errors, warnings, info, …).
- A selection mechanism that allows the operator to specify what levels of messages will be seen, and to change that level without changing the program source code.
-
A configuration mechanism that determines where those messages will appear.
A useful reference is Java Logging Best Practices.
2.1 Writing Messages
You’ve probably written or seen code like this:
cerr << "Program is starting" << endl;
if (htmlDoc == nullPtr)
{
cerr << "Error: HTML document is not available." << endl;
exit(1);
}
if (!validated(htmlDoc))
{
cerr << "Warning: HTML document contains invalid or non-standard markup." << endl;
}
// cerr << "Document root is " << htmlDoc->getRootNode().tagName() << endl; // debugging output
process (htmlDoc->getRootNode());
or its Java equivalent:
System.err.println("Program is starting");
if (htmlDoc == null) {
System.err.println("Error: HTML document is not available.");
exit(1);
}
if (!validated(htmlDoc)) {
System.err.println("Warning: HTML document contains invalid or non-standard markup.");
}
// System.err.println("Document root is " + htmlDoc.getRootNode().tagName()); // debugging output
process (htmlDoc.getRootNode());
A logging framework would replace the explicit output with calls that indicate the severity or importance of the message:
logger.Info("Program is starting");
if (htmlDoc == null) {
logger.Error("HTML document is not available.");
exit(1);
}
if (!validated(htmlDoc)) {
logger.Warning("HTML document contains invalid or non-standard markup.");
}
logger.Debug ("Document root is " + htmlDoc.getRootNode().tagName());
process (htmlDoc.getRootNode());
The new code makes it much clearer just how important a message is.
2.2 Selection
And not all of those messages need to be printed all of the time. A logging framework will generally allow you to change which messages are printed. That way we aren’t drowning in detailed debugging info every time we run the program, but can request thar extra when we really need it.
This is typically done in a configuration file in the directory from which the program is launched. Thus the program source code does not need to be changed in order to adjust the level of detail in the output.
For example, a popular Java logging framework: SLF4J, defines the following levels:
- ERROR: When things are going really badly and a computation probably needs to stop.
- WARN: When things are looking dubious, but the program can probably continue on.
- INFO: Things are proceeding normally, and we want to let people know that normal progress is occurring.
- DEBUG: Things we only want to see when a problem has arisen and we are trying to fix it.
- TRACE: Very fine-grain debugging info, that we only rarely want to see even when we are debugging.
A typical default setting is to print the messages at levels INFO and higher, displaying the DEBUG and TRACE messages only upon specific request.
Some frameworks allow you to specify the severity level independently for different classes.
2.3 Configuration
Most frameworks use a configuration file, a data file outside of the program source code, to determine where to send the messages. Usually, there can be more than one destination. Common possibilities include
- Writing to the “console”, usually the window from which the program was launched.
- Writing into a “log file”.
- Sending the messages over the network to a central logging server.
Configuration files often allow for modification of the message format as well. For example, a configuration might add the date & time to each message.