In my list of unsavory exception practices, I mentioned logging overload as a common issue. It often arises in code like this:
private void DoFirstThing()
{
try
{
// ... thing to do goes here ...
}
catch (Exception e)
{
this.Log("DoFirstThing", e);
throw;
}
}
private void DoSecondThing()
{
try
{
// ... more things to do ...
}
catch (Exception e)
{
this.Log("DoSecondThing", e);
throw;
}
}
private void DoEverything()
{
try
{
SetItAllUp();
DoFirstThing();
DoSecondThing();
TearItAllDown();
}
catch (Exception e)
{
this.Log("DoEverything", e);
throw;
}
}
We can see that some of the individual actions have exception logging, but so does the entire outer block. Deeper actions within may also have the same logging. The end result is a log file littered with redundant rethrown exceptions. We probably only care about logging the deepest occurrence and skipping the rest.
When faced with the same problem recently, I came up with a simple solution. (Keep in mind this only works if your system has a common exception logging abstraction — external code, as always, will do what it will.)
The answer lies in the oft-neglected Data dictionary, present on every exception instance since .NET 2.0. If we stash a piece of information in there indicating the exception has already been logged, we can skip logging on any rethrow.
Here is a reference implementation, using TraceSource as the diagnostic output:
public sealed class ExceptionLog
{
private const string LoggedKey = "ExceptionLog.Logged";
private readonly TraceSource traceSource;
public ExceptionLog(TraceSource traceSource)
{
this.traceSource = traceSource;
}
public void Write(string context, Exception exception)
{
if (MarkLogged(exception))
{
this.traceSource.TraceEvent(TraceEventType.Error, 0, "An exception occurred during '{0}': {1}", context, exception);
}
}
private static bool MarkLogged(Exception exception)
{
IDictionary data = exception.Data;
if ((data == null) || data.IsReadOnly)
{
return true;
}
if (!data.Contains(LoggedKey))
{
data[LoggedKey] = true;
return true;
}
return false;
}
}
[TestClass]
public class ExceptionLogTest
{
[TestMethod]
public void ShouldWriteExceptionOnFirstOccurrence()
{
TraceSource traceSource = new TraceSource("Test", SourceLevels.Error);
try
{
TestTraceListener listener = new TestTraceListener();
traceSource.Listeners.Add(listener);
ExceptionLog log = new ExceptionLog(traceSource);
Exception exception = new Exception("Something happened.");
log.Write("Bad Thing", exception);
Assert.AreEqual(1, listener.Events.Count);
StringAssert.StartsWith(listener.Events[0], "|Error| An exception occurred during 'Bad Thing': System.Exception: Something happened.");
}
finally
{
traceSource.Close();
}
}
[TestMethod]
public void ShouldNotWriteExceptionIfAlreadyWritten()
{
TraceSource traceSource = new TraceSource("Test", SourceLevels.Error);
try
{
TestTraceListener listener = new TestTraceListener();
traceSource.Listeners.Add(listener);
ExceptionLog log = new ExceptionLog(traceSource);
Exception exception = new Exception("Something happened (twice).");
log.Write("Bad Thing", exception);
log.Write("Second Bad Thing", exception);
Assert.AreEqual(1, listener.Events.Count);
}
finally
{
traceSource.Close();
}
}
[TestMethod]
public void ShouldWriteAgainIfDataDictionaryIsNull()
{
TraceSource traceSource = new TraceSource("Test", SourceLevels.Error);
try
{
TestTraceListener listener = new TestTraceListener();
traceSource.Listeners.Add(listener);
ExceptionLog log = new ExceptionLog(traceSource);
Exception exception = new BadException("Something happened (null).");
log.Write("Bad Thing", exception);
log.Write("Bad Thing", exception);
Assert.AreEqual(2, listener.Events.Count);
Assert.AreEqual(listener.Events[0], listener.Events[1]);
}
finally
{
traceSource.Close();
}
}
[TestMethod]
public void ShouldWriteAgainIfDataDictionaryIsReadOnly()
{
TraceSource traceSource = new TraceSource("Test", SourceLevels.Error);
try
{
TestTraceListener listener = new TestTraceListener();
traceSource.Listeners.Add(listener);
ExceptionLog log = new ExceptionLog(traceSource);
Exception exception = new ReadOnlyException("Something happened (read-only).");
log.Write("Bad Thing", exception);
log.Write("Bad Thing", exception);
Assert.AreEqual(2, listener.Events.Count);
Assert.AreEqual(listener.Events[0], listener.Events[1]);
}
finally
{
traceSource.Close();
}
}
private sealed class BadException : Exception
{
public BadException(string message) : base(message)
{
}
public override IDictionary Data
{
get { return null; }
}
}
private sealed class ReadOnlyException : Exception
{
public ReadOnlyException(string message) : base(message)
{
}
public override IDictionary Data
{
get { return new ReadOnlyDictionary<object, object>(new Dictionary<object, object>()); }
}
}
private sealed class TestTraceListener : TraceListener
{
public TestTraceListener()
{
this.Events = new List<string>();
}
public IList<string> Events { get; private set; }
public override void Write(string message)
{
throw new NotImplementedException();
}
public override void WriteLine(string message)
{
throw new NotImplementedException();
}
public override void TraceEvent(TraceEventCache eventCache, string source, TraceEventType eventType, int id, string format, params object[] args)
{
string message = string.Format(CultureInfo.InvariantCulture, format, args);
this.Events.Add(string.Format(CultureInfo.InvariantCulture, "|{0}| {1}", eventType.ToString(), message));
}
}
}
Note the allowance for the Data dictionary to be completely absent or read-only. Since Exception is wide open for extension, there is no telling what you might get when you access such virtual properties.
This doesn’t work for every possible situation; for example, inner exceptions could be rewrapped in new outer exception instances and logged again. Nevertheless, it’s a good start and probably good enough for the 80% case.