Logging from Hell ...

logging   practices  

Over the years I've come across a number of logging implementations that were notable for all the wrong reasons. So I thought it might be a good read to tell your about them.

Method madness

One that I still come across from time to time. The basic philosophy is simple - log every entrance (and sometime exit) to every method.

The reasoning is that every method call is printed in the log so you can see the flow of execution. Therefore you can understand what the program is doing. Really?

Here's a typically Objective C example:

-(void) myMethod {
    NSLog(@"In myMethod");
    // ...
}

It seems inocuous enough, but the reason I don't like this is that the log becomes littered with thousands of lines of methods names. Whilst you get to know what methods are called, you have no idea why or what data they are processing. Lots of noise, but no substance.

A good debugger and the use of break points is a much better solution.

Method madness on steroids

I've only come across this once and that was on a Java server project.

In one way what was done was smarter that most of the Method madness logging I have come across. To save effort, the developer had coded up a filter class and plugged it into the server so that it was called automatically at every method entry and exit. So I'll give him credit for saving the developers from having to type any code in the codebase.

The steroids part comes from then taking the login one step further and automatically logging every parameter to each method call. The author insisted that this was an excellent way to see what was going on inside the project.

It was at a the same time, bother more informative and less informative because whilst it showed you more info, it also created massive logs full of information you didn't want. Finding what you needed was almost impossible.

Alphabet street

Long before I was dealing with Java logging frameworks such as slf4j that automatically log the class and method names, I came across this little gem. It's best explained with an example which I'll update to Objective C.

-(void) myMethod {
    NSLog(@"A");
    if (x) {
        NSLog(@"B");
        // ...
    } else {
        NSLog(@"C");
        // ...
    }
}

Given that the logs only printed what you told them to print, all the log looked like was:

A
B
D
A
A
C
F
B
D
...

And given the author would start each methods logging at "A", this was without doubt, the most useless logging I have ever encountered.

It took me a week of work to strip the code of this rubbish.

So lets be positive

I like to think of myself as a generally positive person so I'll end this post with a discussion on how I like to do logs.

Generally speaking I think a log is all about one thing - telling a story. So my logging takes one of two forms. Either telling the log what the app is doing, or logging a particular value that is relevant at the time. So by reading the log, you get to follow the chain of events and see the data that supports it.

Here's my contrived version of myMethod:

-(void) myMethod {
    if (x == nil) {
        NSLog(@"x is nil, responding by doing ...");
        // ...
     } else {
        NSLog(@"Doing something else with x: %@", x);
        // ...
    }
}

It's a rather silly example but there is both types of statements here. Telling the reader of the log both what the app is doing and giving them the value of x so they can see why.

So make sure your logs tell a story. Remember, it's quite likely you won't be the person reading it.


Comments powered by Disqus