Application logging principles

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.

3 comments

  1. Pingback: Reflective Perspective - Chris Alcock » The Morning Brew #221
  2. Glen

    Nice blog Pat, logging is a much underrated subject. One thing that is worth keeping in mind at all times is that you are not the only consumer of the log file. Operational teams and other developers need to read and understand quickly what is being logged and why. They also need to have confidence in what is being logged or they will quickly develop log blindness and ignore potentially serious issues.

    Personally I like to log variable contents inside [] so its easy to see, and shows things like the dreaded additional whitespace. Also doing simple things like this and thinking about your logging style makes it easier to scrape logs with another tool.

    And beware the developer who tries to do something too fancy using logging – I’ve seen systems brought to a halt because of reflection being done over a swathe of objects for assistance during debugging (doesn’t smell good to start with) and worse that reflection was being done regardless of the defined log level 🙁

Leave a Reply