How to successful log in programming

In a previous article, "Thoughts on successful logging", I wrote about why and how logging is done and, rudimentarily, about best practices in logging. This article now shows how successful logging can be done: Where and what should be logged and how the impact of logging on the overall performance (meaning: usage of resources and time to interpret log-messages) can be optimized.


Where and what to log or: What happens if logging goes wrong.

The simple answers to these two questions "Where?" and "What?" would be: Log everywhere, log all, then you have all the informations about your program in your log at any time. But most times, alas, there are no simple answers in life (or especially: in programming) and following these two answers will result in a couple of problems:

1. The log will explode with log messages, finding crucial messages will become difficult.
2. The log will get verbose because one incident raising a log condition might be logged more often than once (see below for an explanation).
3. The verbosity might be misleading. This can be the case when one incident is logged in different places in the code and therefore seems to deliver different meanings (at first sight).
   
4. Logging methods will be called more often than actually necessary and (thereby) increase the size of memory usage / log files etc. .
5. Gathering the informations more often than needed for the log message (i.e. retrieving additional informations, concating the message from them ...) and calling the log method will decrease the overall performance of the program or of parts of it.
   

Taking these problems serious and pondering a little about them will reveal that successful logging also demands a certain programming style, namely the kind that allows programmers to put the logging lines onto the right place. So let's first talk about the "where" to log, finding this answer will additionally help to clear how to log, seen from a programmers point of view.


A first example: Where to log or not to log. That is not the question.

Logging is like error (exception) handling: If you do it in the wrong place, you get too much or, alternatively, too less information. So the question you have to ask yourself is: Am I in a state of "misbehaviour" (or success) at this point that justifies a log message and - even more important - do I have all informations in this place to produce a log message I can read and am sure what exactly happened? Remember: The moment you do not work on the program every day you should be able to interpret the log message in a couple of seconds, too.

Let us assume we have methods openFile() and createFile() which return a file handle if the file could be opened / created or null if this is not possible. Then, owning a file handle we have the following methods on it: fileHandle.readContent(), fileHandle.writeContent() and fileHandle.deleteFile(). We then want to write the methods emptyFile() and moveFile(). The pseudo.code for this might look like:

function fileHandle prepareFile(String fileName) {
fileHandle = openFile(fileName);
if(fileHandle == null) {
logError("Cannot open a file.");
fileHandle = createFile(fileName);
if(fileHandle == null) {
 logError("Cannot open a file.");
}
return null;
}
// Eventually do some additional action here which justifies this method
return fileHandle;
}

function boolean emptyFile(String emptyFileName) {
fileHandle = prepareFile(emptyFileName);
if(fileHandle!=null) {
fileHandle.writeContent("");
fileHandle.close();
return true;
}
return false;
}

function boolean moveFile(String source, String destination) {
sourceFileHandle = prepareFile(source);
destinationFileHandle = prepareFile(destination);
if(sourceFileHandle==null || destinationFileHandle==null) {
return false;
}
else {
destinationFileHandle.writeContent(sourceFileHandle.readContent());
sourceFileHandle.deleteFile();
sourceFileHandle.close();
destinationFileHandle.close();
return true;
}
}

Obviously, this code will also produce misbehaviour (just look at the moveFile() - method and imagine what will happen if the source file cannot be opened). But moreover the log messages will not help you finding an error. At first, you only get the message "Cannot open file." - which file? But only changing the log line to logError("Cannot open file " + fileName + "."); will not do the trick either, though it is a lot better.

That obviously is because you can call one of the methods (emptyFile() or moveFile() ) and always only get the same log message. You do not exactly know where the error happened. The method prepareFile() is not the right place to log the message because it has not all informations needed ("am I emptying or moving a file?") to create a significant conclusion of the error that happened. The scope of the method prepareFile() is not suffice to log enough information to be precise.

Let us rewrite the methods for the sake of better logging:

function fileHandle prepareFile(String fileName) {
fileHandle = openFile(fileName);
if(fileHandle == null) {
fileHandle = createFile(fileName);
// Do not log here - this would be verbose!
return null;
}
// Eventually do some additional action here which justifies this method
return fileHandle;
}

function boolean emptyFile(String emptyFileName) {
fileHandle = prepareFile(emptyFileName);
if(fileHandle==null) {
logError("emptyFile: File " + emptyFile + "could not be prepared.");
return false;
}
else {
fileHandle.writeContent("");
fileHandle.close();
return true;
}
}

function boolean moveFile(String source, String destination) {
sourceFileHandle = prepareFile(source);
if(sourceFileHandle==null) {
logError("moveFile: Cannot prepare source file " + source + ".");
return false;
}
destinationFileHandle = prepareFile(destination);
if(destinationFileHandle==null) {
logError("moveFile: Cannot prepare destination file " + destination + ".");
sourceFileHandler.close();
return false;
}
destinationFileHandle.writeContent(sourceFileHandle.readContent());
sourceFileHandle.deleteFile();
sourceFileHandle.close();
destinationFileHandle.close();
return true;
}

As you can see, two things happened: Firstly, the logging will create better error messages, that kind you really know what happened. And secondly, more astonishing, the error handling improved. This, clearly, is based on the fact that logging and error-handling often go hand-in-hand (and you surely could do better code using exception handling and finally blocks). Or, asked in an other way: Why does anybody in 90 percent of all cases want to log? Yes: In case errors happened.

The improvement, of course, has it's price too: We needed an additional five lines to accomplish it. But this should only show one thing: Next time you think of the whereabouts of logging, simply think of the whereabouts of error-handling.


What to log.

The answer of the "where to log" already gave some answers to the "what to log" question. Errors, better said exceptional behaviour of the code (or the state of the program) surely is worth to be logged. As listet in the previous article, the purpose of logging changes as the programming work changes too. From simple checks if the program code works as desired to maintainance of the program, i.e. performance logging and logging of the proper (or improper) working of complete modules. This kind of logging should be added from the beginning on too, to a certain degree. It helps you to better understand your code at develop time and maintain the program later on in one big shot. Only make sure that verbosity will not be an issue at any time.

This can be achieved in quite a few ways and always depends on the functional blocks you want to monitor with logging. Let us assume you want to watch the processing time of a page created by your web application. A good idea would be to define a maximum time you allow the page to be rendered. Log only if this time-limit is exceeded, this way your log will only get flooded in case the program works too slow. In other cases, when performance is not an issue, try to get the basic conditions on how logging is useful (like "used time" while logging the performance) and follow them, this will keep your log slim and dandy.


Logging: A conclusion.

Let us conclude with a list of "best practices" for logging. These points merely are explained in the article and summarized in the following six points:

1. Try to formulate your logging messages that way that you can quickly recall the cause for the logging only by reading the message.
2. Treat logging like error (or success) handling: Find the right place for your logging message that has all informations you want to know. Improving the error/exceptional code handling will naturally create the places you can log easy and good. Don't log at every opportunity.
3. Often, less is more. Try to concentrate on vital log messages and avoid verbosity.
4. Sometimes, more is more. Think of the life-cycle of your program not only the time you code it, your program will go productive and certain logging messages (i.e. performance logging for memory or speed or database usage etc.) can too be very useful later on.
   
5. Use a logging (logging-API or Framework, self-written logging) that has different on-and-offswitchable log levels ("debug", "info", "error", "fatal") and is able to log into a kind of persistence layer, be it files, databases or something similar. The moment your program goes productive you will love this option for latter error analysis.
6. Use a logging (API, Framework, self-written) that interferes as little as possible with the rest of your code. It must not use too much resources or be overcomplex to use. Anyway, it should be able to be configured at run-time, i.e. switching debug-levels on or off, switching file logging on or off etc. .

So, happy logging! And might the information be with you... .