A friend asked me if I had any good links about logging in applications and I realised that I haven’t blogged about it. I think logging is an important part to any good application, so I thought I’d emphasis some principles I tend to follow when applying logging.

Logging cannot be considered in isolation of the exception handling strategies

Often I hear about teams who think that logging is a completely isolated concern for a system and exception handling is another. Though they seem like it, systems where exception handling strategies that don’t consider logging strategies and vice versa end up in a very confused state.

As a rule of thumb, my default position on exception handling looks like this:

• If you can handle an exception, recover from it and continue
• If you can’t handle an exception, but you can translate it, then do so and continue.
• If you can’t handle an exception and you won’t translate it, then propagate it to someone who can.

Weaving in logging, it becomes a little bit more complicated.

• If you’re going to handle an exception, you may choose to log the details. Ideally you might choose to log them at a finer level if it’s not a critical exception.
• If you translate an exception and still propogate that, log the exception only if you aren’t going to propogate it (previous rule applies here to what level).
• If you can’t handle an exception and you won’t translate it, don’t bother logging it. Ensure that someone higher up is going to apply the first two rules. There’s nothing more horrid than seeing multiple stack traces, reporting the same problem and there’s too much noise for the signal to be of any use.

Defend the user against stack traces

Applying the previous set of guidelines, then I always try to have one place in my application (at the outer most level possible) to prevent stack traces from appearing out of nowhere to the user. You might still choose to display it to a user for them to submit it back to a support team, or to simply log it to a file to be sent off. What should be avoided at all costs is crashing the application in spectacular fashion with only a stack trace as evidence.

Handling this at the outer most layer, hopefully from a single location, gives a few more benefits. You might choose to log additional information about the application, or render it in a different manner that proves useful for fixing problems.

Think of what would information would help you at 3am in the morning

The reason we log things is to have additional information about what is going on, when things aren’t going as expected. I like to think about what it would be like, to be called at 3am, only to diagnose an issue.

This is particularly difficult to do on iterative projects because you need to balance out enough logging with the cost of changing that logging. I try to add logging to parts of code that are fairly stable and whose implementation patterns will unlikely change.

If you TDD your code, and you reach for the debugger, you need to add some logging

TDD reduces the need to debug, however it never removes the need entirely. Debugging is a useful tool during development that lets us discover information our logs fail to tell us. Unfortunately it’s rare that we can apply this technique when our code is in production, therefore notice what information helps you when you debug and add its equivalent to a log somewhere.

If information logged is part of a fundamental business process, add some tests

I don’t necessarily test all log statements I add to code, however the cost of adding tests around some log statements if often worth it, especially if it’s critical information supporting a business process.

The pattern I use to test loggers is:

1. Get a reference to the logger under test
2. Save the logging level for that logger (to restore after the test runs)
3. Turn up the logging level to the level you expect
4. Execute the code that should trigger the logging
5. Verify the correct message and information was logged
6. (After the test – i.e. teardown) restore the logging level to the original value

Organise sets of information into groups and associate those groups with different log levels

Logging everything to a single level can often be too overwhelming. The trick to getting the right level of logging and information is to have a clear, shared understanding with the team about what information should be logged at what level.

Most programs tend to follow two schools of philosophy in their design, one that I’m going to call ‘scriptable’, the other, ‘visual’. Those in the ‘scriptable’ camp tend to come from a unix background where being able to use pipes to direct input and output into different programs provides a simple, yet very powerful paradigm. Those found in the ‘visual’ camp tend to come from a windows background where almost everything has a GUI, and people mostly use a mouse to execute the functions.

Of coures there are different advantages and disadvantages to both approaches.

For example, discovering functionality in a ‘scriptable’ program is often not obvious simply by executing it. Without the program providing well written, detailed documentation and addtional examples, an end user can spend considerable time discovering how to do something trivial, rather than simply do it. Remembering special codes or parmaters, or the order it expects them in can be considered especially tediuous. Of course, the benefits of the having this interface allows the program to be automated as part of a larger job. The power of this approach is particularly useful for system administrators who may need to do something as part of a common job, or for developers who don’t want to reinvent the wheel.

The ‘visual’ approach, on the other hand, requires less documentation as long as the interface is easy to use and intuitive to the user (although this is often not the case). For people from a less technical background, using a ‘visual’ manner for discovering behaviour is a powerful paradigm and sometimes the user’s only option given their individual set of knowledge. Unfortunately, using this approach in isolation also means excluding the possibility of automating any functionality provided (or at least making it significantly more difficult).

I see people unconsciously make the choice between these two modes all the time. If I was to generalise, Java and Rubyists tend to gravitate towards the ‘scriptable’ interfaces (providing libraries, jars) while a lot of .Net people tend to gravitate towards the ‘visual’ (providing exes).

My preference for writing applications obviously leans towards a mixed approach where I would always want to prioritise the ‘scriptable’ interface above the ‘visual’ one. My thinking here is that the ‘scriptable’ interface should give enough separation between the functionality and the way an end user interacts with it that the ‘visual’ interface should be easy to drive out. In my experience, doing it the other way around leaves people coupling a lot more of their functionality into the graphical user interface, often making the ‘scriptable’ interface more difficult to extract.

Don’t get me wrong, as an end user, I almost always want a user interface for things that I’m going to do very infrequently. The developer in me also wants assurance that, in case that infrequent becomes frequent, I have the easy option of automating it later.