Telling a story

logging   api  

Traditional logging frameworks (Log4J, LogBack, SLF4J, Cocoa Lumberjack, etc) all follow the same pattern. Two intersecting criteria for choosing what is logged. Firstly a limited range of options based on the concept of severity. i.e. info for general information, debug for debugging information, error for unexpected errors, etc. And secondly, a selection criteria of some arbitrary grouping of logging sources. For example the database code, or the UI, or individual business objects or any combination there of. So what is logged becomes a matter of specifying what severity of logging for various areas of the app. For example info from everywhere, debug from database connectivity, fine detail from the UI, etc.

The problem with this is that it’s relatively dumb way to do things. It tends to either tell you too little to be useful, swamp you with detail you’re not interested in or simply give you the wrong info. Traditional logging frameworks concentrate on defining broad criteria for ‘sweeping’ up information without any thought as to it’s relevance or attempt to target the data that actually caused the problems in the first place. It’s like using a shotgun, blasting away in the general direction, hoping that one of the pellets will hit the target. Except that you turn on screeds of logging in the hope that information you are after is swept up. And that once logged, you can find it in amongst all the trash. To make it worse, the logging frameworks make absolutely no attempt to help you follow information through the system. So working out what logging to turn on is a hit and miss affair of guessing what code is relevant.

A point that cannot be highlighted enough is that logging is about story telling. You should be able to read it like a book and understand what has occurred. Imagine trying to understand Game of Thrones where the film style was to cut to a different characters story every two seconds. It would be very hard to follow. Thats traditional logging. it can be made to tell a story with a lot of effort from developers who are willing to spend a lot of time tuning the logging. But most of the time this does not happen. Resulting in a tirade of text, most of which isn’t relevant.

Lets get back to basics, the purpose of logging is to allow you to debug when something has gone wrong. Note I said ‘Debug’. Thats relevant. Quite often business don’t understand this, and treat logging as an arse covering exercise or some form of weird backup system. They turn loads of it on and hope for the best. No wonder logging frameworks have had to spend so much time optimising for performance. But back to debugging.

Developers need to be able to target a block of information which tells them what happened and most importantly, how to reproduce it. Because only when a problem can be reproduced in a test system, can it be debugged and solved. Logging needs to support this. The idea of using severity/data source based criteria is archaic and doomed to fail.

Instead we need to think about the data itself. So I’m proposing a new way of logging. A key based log. The idea works like this: there is only one type of log statement which takes two values. A key that is used for activation of the log statement, and the message to be logged. Something like this:

-(void) logMessage:(NSString *) message forKey:(id) key;

The idea here is that the key is what is used for selecting logging. For example it could be the account number, user id, customer name or whatever identifies the information being processed. Then I can turn on logging for a specific account, or person or customer or whatever I’m interested in. The resulting log would contain only logging for that target, and give me a precise and concise log of exactly what has occurred. Information I can really use.

But sometimes the data that is available to a log method doesn’t contain the key that’s controlling the logging. For example, I might have some data processing method that’s passed the account’s transactions, but not the account number. So here we activate logging based on keys. Basically once turned on, logging continues until the value that first started it, goes out of scope. Given this example:

-(void) doStuff {
    [logMessage:@"x" forKey:@"a"];
    [self doSubStuff];
    [logMessage:@"z" forKey:@"c"];
    [self doSubStuff];
}

-(void) doSubStuff {
    [logMessage:@"y" forKey:@"b"];
}

Because doSubStuff is called from within doStuff, it’s logging is active if logging for the key ‘a’ is turned on, even though doesn’t directly use that key. The ‘scope’ of the ‘a’ key is the scope of the doStuff method and anything it calls until a new key at the same level is defined. So until the ‘c’ key is used.

But what about loops?:

-(void) doStuff {
    while(something) {
        [logMessage:@"x" forKey:loopValue];
    }
}

Here loopValue contains the key and the scope is anything within the loop and after the key is set.

How exactly I would do all this in Objective C is unknown. But it’s an interesting challenge.

Finally, remember this: Any log line that does not help a developer to diagnose a problem is a waste of text and time.


Comments powered by Disqus