Mvc: Provide a way to log exceptions before the stack unwinding

[zihotki]

Currently the framework allows you to use exception filters in order to log unhandled exceptions. But unfortunately at the moment when a filter is executed the stack is already unwinded. How does it affect the exception logging? Well, since C# 6.0 we have exception filters for try/catch block and exception filters can be used to log an exception at the moment when the stack is not unwinded. And that gives us an easy way to implicitly add contextual information to log messages by putting them into logical call context. In my examples I'll use Serilog library since it implements such functionality (see the documentation about LogContext here). Consider the following example:

```c#
public void Run(ILogger logger)
{
try
{
logger.Information("Message without additional properties");

    using (LogContext.PushProperty("packageId", 434))
    {
        logger.Information("Message with packageId");

        using (LogContext.PushProperty("itemId", 22))
        {
            logger.Information("Message with packageId and itemId");

            throw new Exception("Boom!");
        }
    }
}
catch (Exception e) when (LogException(e))
{
    // no op, the catch block won't be called
}

}

private bool LogException(Exception e)
{
Log.Logger.Exception(e, "An error occured. Will log also packageId and itemId");
return false;
}

Running this code will produce raw log messages similar to:

{ level: "Info", message: "Message without additional properties"}
{ level: "Info", message: "Message with packageId", fields.packageId: 434}
{ level: "Info", message: "Message with packageId and itemId", fields.packageId: 434, fields.itemId: 22}
{ level: "Error", message: "An error occured. Will log also packageId and itemId", fields.packageId: 434, fields.itemId: 22, exception: "..."}
```

But when we tried to implement global exception handler using exception or action filters we found that the framework doesn't allow us to inject the code inside of the try/catch block in Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker which executes the action. Since C# 6.0 has been released and people start looking into using exception filters trick for logging, it'll be good if the framework provides some additional injection points.

[Eilon]

Hi @zihotki , are you asking for a feature to allow running arbitrary code when any exception is thrown and/or caught in the system? That would probably need a feature request to https://github.com/dotnet/corefx. There's nothing in ASP.NET Core itself that could do this. It can only have its own catch to do logging of the original exception stack, which it already does.

[zihotki]

@Eilon Yes, at the moment when the exception is thrown. And no, .Net Core as well as .Net Framework already have a way for doing that by using exception filters - http://www.thomaslevesque.com/2015/06/21/exception-filters-in-c-6/ but only before the exception is handled, as soon as it's handled (the catch block runs) the stack is being unwinded. So like I mentioned in the ticket, the only blocking part in Asp.Net Core is the try/catch blocks that handle exceptions in Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker. But looking at the code it's quite hard to find a good way to make it supported without dramatically changing the logic, unfortunately :(. Also the same can be achieved by changing the way how the data is cleaned from call context.

[Eilon]

Exception filters must be hand-written by the code that is catching the exception, it's not something that ASP.NET Core can do automatically for a developer. The ControllerActionInvoker only looks at unhandled exceptions. If you have a controller that wants to handle exceptions, either handle it within the controller action, or write an IExceptionFilter and then the ControllerActionInvoker will ask your filter to try to handle the exception.

[zihotki]

@Eilon Sorry but you completely missed my point. My point was that if we have action which has a using block and an exception occures in the using block then at the moment when an ExceptionFilter or ActionFilter is executed the stack is already unwinded and Dispose method is called due to additional try/catches in the ControllerActionInvoker. Exception Filters from C# 6 allow to run some action before disposing the object (before stack unwinding). So the initial suggestion was to run IExceptionFilter in the context of Exception Filter from C# 6 instead of running it in the context of Catch like it's currently implemented.

So if we have something like this:
```c#
public class DisposableObject : IDisposable
{
public DisposableObject()
{
Debug.WriteLine("+++ Created");
}

public void Dispose()
{
    Debug.WriteLine("--- Disposed");
}

}

public class ExceptionLogger : IExceptionFilter
{
public void OnException(ExceptionContext context)
{
// all using blocks in action already disposed
// and all Finally blocks are already run
Debug.WriteLine("!!! Filter");
}
}

[Route("api/[controller]")]
public class ValuesController : Controller
{
[HttpGet]
public IEnumerable Get()
{
using (var obj = new DisposableObject())
{
throw new Exception();
}

    return new string[] { "value1", "value2" };
}

}

The output will be:

+++ Created
--- Disposed
!!! Filter

My idea was to run Asp.Net `IExceptionFilter` in the Exception Filter block from C# 6 so that the output would be:

+++ Created
!!! Filter
--- Disposed
```

[Eilon]

@zihotki thanks, I think I see what you're saying. I think the issue is that C#'s new "exception filter" feature is something only the person who is writing the code can use. It's essentially a C# language feature, not an actual .NET feature. A framework such as MVC can't intercept these to run additional custom code. All MVC can do it catch the exception once it leaves the app's code and it can then run its own MVC IExceptionFilter.

[adamsitnik]

It's essentially a C# language feature, not an actual .NET feature.

It's an old CLR feature, which was not used so much before C# 6.0. This blog post describes it really well.

Most probably you have sth like this now somewhere in the request flow in ASP.NET / Kestrel impl:

try
{
    UserCode();
}
catch(Exception ex)
{
    exceptionFilter?.Handle(ex);
}

What @zihotki ask you is to extend it by sth like:

try
{
    UserCode();
}
catch (Exception ex) when (BeforeStackUnwind(exceptionFilter, ex))
{
  // will never get here
}
catch (Exception ex)
{
    exceptionFilter?.Handle(ex);
}

private bool BeforeStackUnwind(IExceptionFilter filter, Exception ex)
{
    filter?.BeforeStackUnwind(ex); // call the custom code if present
    return false; // return false to proceed to the next exception handler
}

[davidfowl]

This is interesting. @Eilon we should consider this but maybe it needs to be a new method or another interface on an IExceptionFilter. It might make the state machine in the ControllerActionInvoker crazier though but @rynowak can handle it 😄

[aidansteele]

@davidfowl I apologise for the impatience, but has there been any progress on this issue? I’d love the possibility of richer exceptions :)

Also, this issue seems related to https://github.com/aspnet/Logging/issues/677 - but it’s beyond my understanding. Is it the same issue?

[rynowak]

IExceptionFilter and others give you access to an ExceptionDispatchInfo, which (in practice) is supposed to be based on the actual context of the exception. What's the delta between that and what's being asked for?

[davidfowl]

I think it was being able to execute code before finally blocks run.

[rynowak]

So my expectation is that this is in support of doing fancy-pants things like using ambient/stack/execution context to provide additional information that needs to be present for logging. Is that right?

If that's the intended usage then I think this feature would have a very bad tradeoff of complexity/cost to value. This doesn't pass the "Dan Test"... how do we explain to users what this is for and when they are recommended by us to us it vs more conventional techniques? I wouldn't feel good about adding more features to the filter pipelines (we have two of them now) that we wouldn't recommend to users.

I'm leaving aside right now the fact that if we add this surrounding the action method itself, there are probably 5-6 more places just in MVC we'd also want to add it for consistency. I'm also leaving aside for now the fact that WebAPI had this feature - it was a lot of work to implement, had bugs that were hard to chase down, and was kinda vexing to everyone who used it. @davidfowl - if you like this idea, I'd encourage you to compare it to the webapi global error logging feature and think about if you want a similar feature all over our stack.

What would change my mind is if there's some kind of totally great thing that needs this feature that I'm not seeing.

[davidfowl]

@rynowak For my education, how many places does MVC give you explicit control after catching an exception besides exception filters?

I'm trying to dig into this comment:

I'm leaving aside right now the fact that if we add this surrounding the action method itself, there are probably 5-6 more places just in MVC we'd also want to add it for consistency

[rynowak]

Each filter type, model binding/formatters, some places in validation, middleware-as-filters. These are all of the places where we catch an exception from user-code and then show it to you after unwind.

[rynowak]

I think once you have something like this, you'd need to consider adding extra log-points that we don't have today everywhere that we provide indirection into user-code - so that means tag helpers, partials, and view components.

[rynowak]

Let's me be clear though, I'm not objecting to it because I think this will turn into the WebAPI global error logging feature. I think it's a bad tradeoff for us to make because of the complexity involved in implementing it and niche nature of the scenario.

[davidfowl]

Maybe a better alternative is to let the user write a filter that catches the action invocation errors themselves.

[rynowak]

For instance if we had a mode where we didn't try/catch inside of filters for you - you write a try/catch if you want one.. That would be both simpler than what we have and satisfy this need.

I don't understand how/when we could get there, but that's a solution I think everyone would be happy with (except people with existing code). If you changed the design of filters to be more middleware-like, then you could have something like this, and provide base-classes that try their best to support the old behaviour.

[cwe1ss]

Yes, this is an extension of what I've written in https://github.com/aspnet/Logging/issues/677. I've been talking about the general problem that C# 6 exception filters seem to not work in asynchronous scenarios. If MVC (or any other component that runs before your exception filter) catches the exception, it obviously also breaks the usage.

I think it is a pretty big deal that logging scopes can not be added to error logs and I think it makes them almost useless. It's just not reasonable to write custom try...catch statements within every scope block.