How not to do logging: catch-log-throw

Posted at 07:00 on 18 September 2014

Way back in the mists of time, I worked on a project whose log files started spiralling out of control.

This wasn't actually surprising, because the codebase in question was riddled with method after method that looked something like this:

public Widget GetWidget(int id)
{
    log.Debug("Getting widget with id " + id);
    try {
        var result = repository.GetWidget(id);
        if (result != null) {
            log.Debug("Successfully got widget with id: " + id);
        }
        else {
            log.Debug("No widget found with id: " + id);
        }
        return result;
    }
    catch (Exception ex) {
        log.Warn("Error fetching widget with id " + id, ex);
        throw;
    }
}

I'd objected to this about a year previously, but had encountered some stiff resistance from our team's Best Practices Guy, who had been responsible for it in the first place.

The problem here is that the same exception was being logged multiple times, complete with deep stack traces, cluttering up the log files, making them very difficult to read and in the process making them grow out of control.

This is what catch-log-throw does.

But it doesn't just cause problems with your infrastructure. It makes your code hard to read, hard to review, and easy to miss things. Our Best Practices Guy denied this when I said so, claiming that it was perfectly clear what it was doing, but you'll see what I mean when I strip out the logging statements:

public Widget GetWidget(int id)
{
    return repository.GetWidget(id);
}

Two things become obvious here:

• The method is anaemic. In fact, the entire business layer was anaemic.
• The catch-log-throw block is disguising the fact. It made the method look like it was doing something important when it wasn't. A sort of Bavarian Fire Drill in code.

If you really do need this level of detail in your logs (and you usually don't), a cleaner way to do it is to use an aspect-oriented framework such as Castle DynamicProxy or PostSharp. There's really no need to clutter up your codebase with noise like this.

As a general rule, you should only log exceptions in catch { } blocks where they are not being re-thrown. If you're catching it to recover from it and continue, log it as a warning; if you're reporting an error to the end user, log it as an error. In general, a catch { } block should either log the exception or re-throw it. Unless you have a very good reason to do so, it shouldn't do both.