The Last Craft?

Every serious program has logs. Logging errors is part of programming after all, as natural as breathing. You probably have half a dozen services or deamons writing messages to your hard drive right now and you feel safer for it I’m sure. And of course you often send log messages to yourself.

Just the errors at first.

A logger class is pretty simple, it just timestamps messages and shoves them in a file, so hardly much development overhead. OK, so the class that created the log message needs to know about the logger and that’s a little more awkward. We don’t want any Singletons around here thanks very much, so we’ll pass the logger into the constructor of the class doing the logging. Of course we don’t want our client code affected by changing the constructor signature, but if we are lucky we get most of our main entities through factories anyway. That’s handy because it will save the client code having to know about the Logger class as well, otherwise…er…things could get complicated.

The factories have to know where the log file is on this specific machine, so the factories will need to take a configuration object in their constructor. The configuration file itself, and the parser to go with it, can just be in the source tree. There might be one these already and we weren’t planning to use this code in any other projects anyway (were we?), so the extra configuration dependency shouldn’t be that bad.

Errors arrive a bit late though. Really we want to know what happened just before the error and that means logging any suspect behaviour. We don’t want to trigger any kind of alarm on these so we’ll call them LOG_WARNING level or some such and add filtering to our Logger. We’ll have to get the logging level from configuration file of course, but the real problem is that our original class we are monitoring is now getting a bit cluttered. That’s OK, we know what we are doing. We’ll create a decorator for each and place the log calls in that. We can even tell the factories to apply the decorators or not according to the configuration file, and well, shoot me if my middle name isn’t “Aspect Oriented".

And life just doesn’t seem so easy anymore. It seems to take longer than ever to produce ever more code, new developers have to be taught all about our error handling and monitoring systems and to make things worse, today we have a bug.

Debugging is worse than the dentist. Even with watches, breakpoints and single stepping our forty lines a day productivity can drop to fixing a single line over an entire day. That is bad use of resources, resources that could be better spent rewriting that section of code, or writing better tests, or clearer design, or code review, or a good night’s sleep or any other activity that would prevent the bug in the first place. What can be worse than staring at a debugger? Try doing the same thing by staring at log files. It’s like trying to find a gunshot wound with keyhole surgery. To make matters worse, all the other developers have dumped their LOG_WARNING, LOG_NOTICE and LOG_DEBUG messages (where did they come from?) all over your now mission critical log output. It’s a desperate mess. All that extra code and configuration for what? So we could now begin the most spectacularily inefficient process in the whole of software development…?

So, why did we log that first error?

If there really is a chance of error at that point then we should fix the probable root cause. Inspect the code to see if an error really is possible. Wrap tests around the components that could possibly cause the error and confirm that it cannot every time you check in the code. If it’s too complicated to make that assertion then break the code down. Rewrite it if you have to. If you distrust the code that much it shouldn’t be in your system, otherwise every other module has to code defensively around it. That’s clutter you don’t want.

An external library or system? Wrap it. Simulate failure of the external component with mocks to make sure your error trapping is well defined. That error is a possible input to your program and should be as well defined as when a user types in their own log-in details. Building on a firm foundation may feel like you are going slower, but you won’t be. You certainly won’t be if you can save yourself a couple of days debugging time.

You win in other ways. Your code will be clearer with the “debugging” calls taken out and that means fewer bugs because people will understand the code more easily. You code will be simpler to deploy now it has been freed from yet another file dependency. A file that is security sensitive by the way, which gets you into permissions and so platform dependence. But I think the real gain is that a crutch will have been taken away from the developers.

Logs become a dumping ground. Issues that would have provoked a much needed discussion can be too easily glossed over just by logging data “for later". For example you may be logging usage of a web site for later analysis. The factors that effect the analysis will be known by the client and you would save time by finding these out. Perhaps you don’t therefore have to log every last drop of information. Perhaps you only need overall totals or trends. This is something that should be cleared up with the client straight away, because logging everything is a sign that the goals are not very clear.

You also get the right degree of coupling between analysis components and their data. If analysis happens straight away within the same program all of the code pieces will be local to each other. With a more obvious connection we can prevent the inevitable bloat where data is added to the log, but no one feels safe about taking it away. Assuming you need to log it all. Why not place the result straight into the database and give yourself a real time solution? A log is a form of user interface and as a design choice it has to be subject to the same degree of rigour as your other design choices. Once you do you start to throw up cleaner alternatives.

A log is a symptom of a half solved problem.