Click here to Skip to main content
15,040,003 members
Articles / General Programming / Exceptions
Article
Posted 28 Nov 2018

Stats

3.5K views
1 bookmarked

Ensuring an Error is Logged Only Once

Rate me:
Please Sign up or sign in to vote.
2.33/5 (5 votes)
28 Nov 2018CPOL4 min read
By utilizing some fairly mundane features of .NET, we can log errors at the point where the exception occurred; preserving vital debug information while avoiding repetitive error logging.

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:

C#
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:

C#
_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.

C#
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.

C#
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?

C#
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

License

This article, along with any associated source code and files, is licensed under The Code Project Open License (CPOL)

Share

About the Author

Shai Cohen
United States United States
No Biography provided

Comments and Discussions

 
BugOnce you log, you break the expectations of exception handlers Pin
wmjordan28-Nov-18 13:40
professionalwmjordan28-Nov-18 13:40 
I did not down vote the article. Your article has demonstrated a classic pitfall of exception handling.

Let's assume that somewhere in the code is expecting to catch and handle an IOException.
catch (IOException)

Once you logged before that catch, you break the code, since the IOException has been wrapped into the LoggedException and no longer an IOException any more. Consequently anywhere handling specific exceptions have to check, filter and unwrap the LoggedException. It can be a terrible butterfly effect, if you are writing an API library for yourself or your work fellows.
A more efficient way without breaking existing code is to use the Exception.Data collection to record your logging operation and check that when you are to avoid duplicated logging. You can even log what places you have logged into.
// the place where the exception and initial logging takes place
catch(IOException ex){
   LogToFile(ex);
   LogToDb(ex);
   throw; // don't throw a new exception
}
void LogToFile(Exception ex) {
   // do some work to log to file

   // mark that the exception has been logged to file
   ex.Data[LoggerStamps.LoggedToFile] = true;
}
void LogToDb(Exception ex) {
   // do some work to log to database

   // mark that the exception has been logged to database
   ex.Data[LoggerStamps.LoggedToDb] = true;
}

Note: Create a enum named LoggerStamps and place your places identifiers to it.

Existing catches in your and others' code will still work and you can conditionally log once more or skip duplicated logging.
// somewhere else in the code that handles the exception
catch(IOException ex){
   HandleIOException(ex);
   if (ex.Data.Contains(LoggerStamps.LoggedToFile)) {
      // exception has already been logged to file
   }
   if (ex.Data.Contains(LoggerStamps.LoggedToDb)) {
      // exception has already been logged to database
   }
}

GeneralMy vote of 4 Pin
Alek Massey28-Nov-18 11:38
MemberAlek Massey28-Nov-18 11:38 

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Praise Praise    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.