Your code should log exceptions from within an exception filter, not a
The old pattern of “log-and-propagate” looks like this:
The logging should be moved into an exception filter like this:
Similarly, the old pattern of “log-and-handle” looks something like this:
The logging should be moved into an exception filter like this:
Both of these examples assume the presence of a couple simple utility methods:
The remainder of this blog post goes into the “why” behind the new pattern.
Semantic Logging / Structured Logging
Long gone are the days of text file logging; modern logging systems support rich, contextual logs. This means you can add data fields to your log messages, and then use those additional pieces of data when debugging an issue. It’s very satisfying to be able to filter by an HTTP status code range, or take the top three servers where user
Steve had a
Structured logging is so important that every modern logging system supports it. For example, .NET Core style logging uses message templates, which looks something like this:
The code above will create a log message like
"Result: 4". What’s not immediately obvious is that the log message also has structured data attached to it: a data field called
result has the (integer) value
4. When this is consumed by a logging provider that understands structured data, the
result field is stored along with the log message, and can be used for searching or filtering.
If you would like to follow along at home, create an ASP.NET Worker Service (which is really just a Console app with ASP.NET-style logging and dependency injection all set up for you). Then replace
Worker.ExecuteAsync with this:
When you run it, you should see this in the output:
So far, so good, and hopefully that’s nothing new.
In addition to adding structured data to a single log message, most modern logging frameworks also support logging scopes of structured data. So you can create a logging scope that attaches structured data to every log message within that scope:
Now, when the
Result: 4 message is logged, it will capture additional structured data items:
3. It should be clear that strategically placing data items in logging scopes can greatly assist debugging. Any time you’ve stared at an error message or unexpected result and wondered “what was the input that caused this?”, that’s the perfect place to add a logging scope.
Tip: The Console logger ignores logging scopes by default; they have to be manually enabled.
If you’re following along at home, enable logging scopes for the Console logger by updating
CreateHostBuilder in your
Program.cs, adding a call to
ConfigureLogging that removes the existing Console logger and adds a new one that sets
Now, when you run the code, you’ll see the logging scope written to the Console as a part of the information message:
Now the logs have a clear context.
So, let’s talk about logging exceptions. Most methods do not log their own exceptions; any exceptions are propagated out of the method, possibly through many other methods, and eventually logged at a much higher level in the code.
The problem with this approach is that the logging scope is lost once the stack is unwound.
Here’s the kind of situation that causes this problem.
Worker.ExecuteAsync is going to wrap its call in a
catch and log the exception. This is a very common pattern in most code bases today:
The problem, as stated above, is that the logging scope is already gone by the time
LogError is called. So our logging output looks like this:
The logs have the exception details, including the stack trace, but they do not have the structured data from the logging scope. When sent to a logging backend, there is no
denominator data that is attached to this log message. Losing that logging scope data is a problem.
To fix this, we first need a minor segue into how exceptions work.
How Exceptions Work
When an exception is thrown, the runtime will search the stack for a matching handler. So the runtime walks up the stack looking at each
catch block and evaluating whether it matches the exception (e.g., the exception type matches). When a matching handler is found, then the stack is unwound to that point and the
catch block is executed.
The important part of this behavior is that there are two distinct steps: find, then unwind.
Exception filters have been around for a very long time; .NET 1.0 (2002) supported them, and Structured Exception Handling existed even way before that. C# only got exception filter capabilities in C# 6.0 (2015), and so far they haven’t really become common in most codebases. That may change now, though.
Exception filters allow you to hook into the “find” part of “find, then unwind”. By providing an exception filter, you can control whether a specific
catch block matches the exception.
The key thing to keep in mind about exception filters is that because they hook into the “find” part of the process, this means they run where the exception is thrown, not where the exception is caught. This is a little mind-bendy at first, but it makes sense: exception filters are run before the stack is unwound.
Solution: Move Exception Logging into an Exception Filter
So, now we have the pieces necessary for fixing the problem. We just need to log exceptions from within an exception filter. Since the exception filter runs where there exception was thrown, the logging data scope is still present. The stack hasn’t been unwound yet, so all that rich semantic data is still available.
There’s just one quirk: the exception filter must return a boolean value, indicating whether or not the
catch block matches. In our case, the logging is just a side effect; logging the exception has no effect on whether the
catch block matches. So, I use a type like this that just provides methods to “execute this side effect and then return a boolean”:
Once you do a
using static ExceptionFilterUtility;, you can use it like this:
And there you go! Our error log message now has the full data context of where the exception was thrown, instead of where it was caught:
The full data logging scope is now preserved.
True or False?
I’ve defined two helper methods -
False - to apply side effects and then return a boolean. I recommend using
False if the body of your
catch is nothing more than
throw;. When an exception is thrown, the exception filter is run and the exception is logged, and then the
false result means that the exception filter does not match the exception, and the runtime continues searching for a matching handler.
Another scenario is if the
catch block actually handles the exception. Say, if we know there is an exception that is safe to ignore. In that case, use the
True helper method so that the exception matches the
catch block and the stack is unwound and the exception is handled there.
Both helpers are useful in different scenarios.
The solution here unfortunately does not work well with
async code. This is because
async will cause exceptions to be caught and then re-thrown at the point of the
await. So, the exception filter runs at the point of the
await instead of where the exception was originally thrown.
Modern exception-logging code should do its logging from within an exception filter. As logging data scopes become more and more common, this pattern will enable much more helpful logs for your system.