Ensuring an Error is Logged Only Once

Introduction

It's your run-of-the-mill try/catch block and you've just caught an error. Should you log it? Has it already been logged? You definitely don't want to log it multiple times, but how can you tell?

According to MSDN, this is a real issue:

Avoid exception reporting or logging lower in the call stack.
...
Such catch blocks should not log the exception or report it to a user while in the bowels of the call stack. If the exception is logged and rethrown, the callers higher in the call stack may do the same, resulting in duplicate log entries of the exception. ...

This poses a problem as it is desirable to log the error closest to the point it occurred because then, you have access to the method parameters, which you can log as well to greatly helping you debug the exception. But according to MSDN above, this will lead to duplicate log entries.

Let's take a look at some code to illustrate the issue:

public void CreateBookings(string[] people)
{
	try
	{
		foreach (string person in people)
			CreateBookingForPerson(person);
	}
	catch (Exception e)
	{
		_logger.LogError(e);
	}
}

public void CreateBookingForPerson(string person)
{
	_bookingRepo.CreateBooking(person);
}

Note that we are only catching and logging errors in the first method: an error occurring in CreateBookingForPerson will bubble up and be logged in the catch block in the method CreateBookings.

Now let's say we have an array of 10 people to process; and on the fourth item, an error occurs on the following line:

_bookingRepo.CreateBooking(person);

The error will bubble up until it is caught by the catch block in CreateBookings. Here's the problem: at this point, we no longer have access to the person item that caused the error: we can log that an error occurred but we have lost the why (the details). If the exception was instead caught inside of CreateBookingForPerson, we would still have access to which item caused the error, a crucial bit of information for debugging the problem.

However, of course, if we did decide to add a logging try/catch to CreateBookingsForPerson, the error would end up being logged twice: something we are trying to avoid.

Solution

So what's the solution? The core concept is this: when an exception is caught:

1. Log the exception and wrap it in a custom exception-type LoggedException.
2. Throw this newly created LoggedException.
3. Ignore / do not log exceptions of type LoggedException.

Let's first look at the code for the LoggedException class.

public class LoggedException : Exception
{
	public LoggedException(string message)
	: base(message)
	{
		LogException(message, null);
	}

	public LoggedException(string message, Exception innerException)
	: base(message, innerException)
	{
		LogException(message, innerException);
	}

	private void LogException(string message, Exception innerException)
	{
		//hook up logging framework of choice
	}
}

The class is fairly straightforward; it's simply a wrapper around the built-in Exception class. Logging of the error details occurs during instantiation by calling LogException. LogException is where you would hook up your logging framework of choice. As an added bonus, we have now centralized our logging functionality. If we ever want to swap out the logging framework, the only code changes required would be inside of LogException.

And really, that's it. However, the real magic happens during the implementation of the LoggedException class.

Implementation

Let's take another look at our code from the introduction, but this time using LoggedException.

public void CreateBookings(string[] people)
{
	try
	{
		foreach (string person in people)
			CreateBookingForPerson(person);
	}
	catch (Exception e) when (!(e is LoggedException))
	{
		string errorMsg = "An error occurred while creating bookings.";
		throw new LoggedException(errorMsg, e);
	}
}

public void CreateBookingForPerson(string person)
{
	try
	{
		_bookingRepo.CreateBooking(person);
	}
	catch (Exception e) when (!(e is LoggedException))
	{
		string errorMsg = $"An error occurred while creating a booking for person {person}.";
		throw new LoggedException(errorMsg, e);
	}
}

Once the error has been logged, both catch blocks throw a LoggedException. A LoggedException tells catch blocks higher up the stack that the exception has already been logged. With this mechanism in place, our error logging can include the additional details required to quickly pinpoint the problem.

Did you notice the when keywords on each catch block?

catch(Exception e) <code>when</code> (!(e is LoggedException))

These are exception filters, one of the major new features of C# 6. They allow you to specify a condition for entering a catch block. At first glance, you might be tempted to dismiss this as just some additional syntactic sugar, but it is so much more. The big deal here is that exception filters do not unwind the stack. That's huge! The details are beyond the scope of this article, but for a more in-depth discussion, this article does a great job. It is worthwhile to note that implementing exception filters is not a requirement.

Conclusion

By utilizing some fairly mundane features of .NET, we can altogether avoid the rather troublesome issue of repetitive error logging. This approach enables access to the local variables at the point where the exception occurred, providing the additional details to quickly pinpoint the problem.

Avoid exception reporting or logging lower in the call stack.
...
Such catch blocks should not log the exception or report it to a user while in the bowels of the call stack. If the exception is logged and rethrown, the callers higher in the call stack may do the same, resulting in duplicate log entries of the exception. ...

Problem solved.

History

• 2018-11-28: Initial version