Consider running user-provided exception handler even when response has started

[analogrelay]

Created from https://github.com/aspnet/AspNetCore/issues/12301

If the response has already started, the Exception Handler middleware exits early and doesn't write a response. This makes total sense. However, it also doesn't call the user-provided handler (if any) and it doesn't signal the diagnostic source. This makes diagnosing issues more difficult. We should consider refactoring this.

[Tratcher]

The user provided handler is also intended to generate a response, so running that seems problematic. Signaling the diagnostic source makes sense though.

[analogrelay]

The user provided handler is also intended to generate a response

I don't know that I'd agree. The handler is a RequestDelegate yes, but that's not inappropriate here. There's nothing that expects the handler to generate a response here. It's just giving it the full context (the request) and the opportunity to generate responses as necessary. The handler can just as easily check if the response has started. Or it could collect all the data it wants, send it to some error reporting service and then let the response proceed as it would have before. Plus, this would allow the user control over what response gets generated if an exception occurs mid-stream.

I would agree that this could be a behavior break though since the handler may not have been expecting to run when the response has already started. We can talk further about how we want to do that (or if we want to call the handler at all). Signalling the diagnostic source definitely seems like a no-brainer here :).

[TehWardy]

@anurse Is that something I as a consumer of the framework can hook in to and have a block of code provide a response to the request with?

No matter what we need to be able to provide some sort of response that explains either that the request was somehow not valid or that the server was unable to handle it for what ever reason.

[Tratcher]

No matter what we need to be able to provide some sort of response that explains either that the request was somehow not valid or that the server was unable to handle it for what ever reason.

If the response has already started it's not possible for you to provide a different response. You'd be writing in the middle of the existing response and corrupting the HTML, JSON, etc.. If you want to be able to replace a response then you have to fully buffer it to prevent it from being sent to the client. This adds a lot of overhead so we don't do it by default.

[analogrelay]

Yeah, I agree with @Tratcher here. This middleware is not designed to allow you to produce an error response after the main response has already started. If you want to be able to do that, you'd need to build a new middleware that buffers the response in memory and then dumps that buffer only if there is no error executing the rest of the pipeline.

What we are discussing here (and still not at all committed to) is the idea of allowing you to run code in the handler even after the response has started. You still would not be able to write a new response or affect the status code if the response has already started, but you could send the error to a diagnostic system of some kind (for example).

[TehWardy]

Yeh that's not unreasonable at all @Tratcher . I found a scenario where I could setup an OData controller (I know OData is not core aspnet but bear with me) ... in the business logic for the action I could construct an entity and not populate it correctly so the entity was not valid.

EF for example would fail to put it in to the DB with a SQL exception. The OData framework seems to validate properties as it serializes them resulting in the response failing during serialization so the response is literally a half backed blob of JSON.

The key issue I had there of course is that the framework just stopped processing at that point. Being able to hook on to any part of the request lifecycle as a global catch all and at least log the true exception information is key to helping devs treat the framework right.

I do also accept that some scenarios are just simply not resolvable (like my OData one) in the ideal manner.

@anurse It sounds like you're proposal is much like what I would expect with some basic ability. So a "pseudo code" concept (with little detail of course) of what I think the framework should do as core behaviour ...

MiddlewareObject stack;
try
{
     stack = BuildMiddlewareStack();
     stack.ExecuteOn(request);
}
catch(Exception ex)
{
      CallDefaultHandler(ex);
      if(defined) { CallUserHandler(ex); }
}
finally
{
     Cleanup(stack, request);
}

... I'm sure it's way more complex than that but this at the root level ensures that "worst case" the user still gets notified when the framework simply can't handle our garbage ;)

[Tratcher]

and at least log the true exception information

The framework should already be logging the exception at the middleware or server level, even if it can't produce a response.

[TehWardy]

The bulk of logging that has any value seems to be dropped in to the VS console ... is that what you mean by the "middleware or server level"?

I'm thinking take that VS console stuff too and be able to handle that with the global exception handler.

I'm already doing this ...

app.UseExceptionHandler(errorApp =>
{
    errorApp.Run(async context =>
    {
        var ex = context.Features.Get<IExceptionHandlerPathFeature>();
        log.Error(ex.Error.Message + "\n" + ex.Error.StackTrace);
          // code clipped out here for berevity
        var innerEx = ex.Error.InnerException;
        while (innerEx != null)
        {
            log.Error(ex.Error.Message + "\n" + ex.Error.StackTrace);
            innerEx = innerEx.InnerException;
        }
    });
});

... but I've hit scenarios where the output window in VS has information that would really help and doesn't get passed to this handler. It would be really cool if this middleware also got all the info passed to the VS console window ... maybe if that is the case though put some flag / logging level info in the errorApp object as it might produce a lot of noise for some scenarios that people wouldn't want.

I think @anurse was talking to me about this in another ticket actually. ah yeh, it's #12301 linked above. That would probably solve both of these tickets at least in part.

[analogrelay]

The bulk of logging that has any value seems to be dropped in to the VS console ... is that what you mean by the "middleware or server level"?

It's logged to the ASP.NET Core logging system. You can plug in a number of outputs, including custom ones.

[analogrelay]

See https://docs.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-3.0 for more details on logging.

[TehWardy]

I use Log4Net as my logging framework (legacy reasons basically) ... This looks really good though ... I ma have to migrate to it and see if it's any better (anything that reduces further external dependencies can't be that bad right).

[analogrelay]

The advantage to integrating with the built-in framework is that the entire ASP.NET Core framework logs to that system, at a variety of detail levels. There are third-party providers than integrate our system with other logging frameworks, more detail on that in the docs. I don't see log4net in that list, but a quick google search for log4net microsoft.extensions (The logging framework is in the Microsoft.Extensions.Logging namespace) does yield some results (though I don't know how well those integrations work). You can always integrate the two systems and then continue to log directly to log4net in your app, while also having ILogger messages go through to log4net.

[TehWardy]

As per this issue ... https://github.com/OData/WebApi/issues/1858

... Is there any way I can "turn off" result validation during the response serialization in OData controller response handling?

This is where it all began and I feel like the problem has moved in to an issue of logging when it's really an issue of response generation (the framework is forcing an exception that need not be one in the situation I have.

Sorry to drag an OData issue over here but I think the visibility of my issue is being lost somewhat and buried in a logging technicality (which is in all fairness not that important).