Stephen Cleary’s new logging pattern question about async

I like Stephen Cleary’s new logging pattern once I tested it. However, there is something that I don’t understand:

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.

I would like to get an example of that, because it seems that my code works fine for me with Handle(...)/his True(...) and no throw;.

I made SubscribeAsync throw an exception on purpose.

public async Task StartAsync(CancellationToken cancellationToken)
{
    try
    {
        await SubscribeAsync().ConfigureAwait(false);
    }
    catch (Exception ex) when (Handle(() => _logger.LogError(ex, "Unexpected error.")))
    {
    }
}

public static class ExceptionFilterUtility
{
    public static bool Handle(Action action)
    {
        action();
        return true;
    }

    public static bool Propagate(Action action)
    {
        action();
        return false;
    }
}

My stacktrace is:

[2021-03-13 20:16:32 Error] ElonMuskBot.Core.TradeManagers.LiveTradeManager
Unexpected error.
ElonMuskBot.Core.Exceptions.RequestFailedException: Error while subscribing to the Spot candlestick update stream
   at ElonMuskBot.Core.Clients.SpotBotClient.SubscribeToCandleUpdatesAsync(String symbol, KlineInterval timeInterval, Action`1 onMessage) in E:GitHubelonmuskbotsrcElonMuskBot.CoreClientsSpotBotClient.cs:line 88
   at ElonMuskBot.Core.TradeManagers.LiveTradeManager.SubscribeAsync() in E:GitHubelonmuskbotsrcElonMuskBot.CoreTradeManagersLiveTradeManager.cs:line 54
   at ElonMuskBot.Core.TradeManagers.LiveTradeManager.StartAsync(CancellationToken cancellationToken) in E:GitHubelonmuskbotsrcElonMuskBot.CoreTradeManagersLiveTradeManager.cs:line 38

Answer

I would like to get an example of that, because it seems that my code works fine for me with Handle(…)/his True(…) and no throw;.

The point of that pattern is to capture logging scopes at the point of the throw. Exception handling itself works fine either way, but the captured scopes are different.

The logging scopes are captured properly for synchronous code, since the exception filters are actually executed at the point of the throw. So the exception is logged at the throw, including all logging scopes that are present.

However, it does not work properly for asynchronous code. The exceptions will be logged just fine, but the logging scopes will not be present. This is because the exception filters are executed at the point of the await, not the point of the throw.

So here’s an example that will not properly capture the exception logging scopes:

public async Task SubscribeAsync()
{
  using var _ = _logger.BeginScope("This will not be logged");
  await Task.Yield();
  throw new InvalidOperationException("This will be logged");
}

Since writing that blog post, I’ve developed a better solution that works for both synchronous and asynchronous exceptions and released it as a library. I haven’t gotten around to writing a new blog post (sorry!) but as soon as I do I’ll point the old solution to the newer one.

The newer solution is .NET Core only, since it ties into ILogger. Example usage:

// Don't forget to call IServiceCollection.AddExceptionLoggingScopes() in your startup.
public async Task StartAsync(CancellationToken cancellationToken)
{
  try
  {
    await SubscribeAsync().ConfigureAwait(false);
  }
  catch (Exception ex)
  {
    using (_logger.BeginCapturedExceptionLoggingScopes(ex))
      _logger.LogError(ex, "Unexpected error.");
  }
}

Leave a Reply

Your email address will not be published. Required fields are marked *