Log error when action execution throws

[pranavkm]

Based on https://github.com/aspnet/AspNetCore/issues/3712. When no exception filter is configured, the log for action execution that throws looks like so:

018-10-24 09:42:46.896 +00:00 [Information] Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker: Route matched with {action = "Index", controller = "Home"}. Executing action Lighthouse.Web.Controllers.HomeController.Index (Lighthouse.Web)
2018-10-24 09:42:46.896 +00:00 [Debug] Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker: Execution plan of authorization filters (in the following order): None
2018-10-24 09:42:46.896 +00:00 [Debug] Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker: Execution plan of resource filters (in the following order): Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter
2018-10-24 09:42:46.896 +00:00 [Debug] Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker: Execution plan of action filters (in the following order): Microsoft.AspNetCore.Mvc.Internal.ControllerActionFilter (Order: -2147483648), Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter
2018-10-24 09:42:46.896 +00:00 [Debug] Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker: Execution plan of exception filters (in the following order): None
2018-10-24 09:42:46.896 +00:00 [Debug] Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker: Execution plan of result filters (in the following order): Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter
2018-10-24 09:42:46.896 +00:00 [Trace] Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker: Resource Filter: Before executing OnResourceExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.
2018-10-24 09:42:46.896 +00:00 [Trace] Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker: Resource Filter: After executing OnResourceExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.
2018-10-24 09:42:46.897 +00:00 [Trace] Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker: Resource Filter: Before executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.
2018-10-24 09:42:46.897 +00:00 [Trace] Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker: Resource Filter: After executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.
2018-10-24 09:42:46.897 +00:00 [Information] Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker: Executed action Lighthouse.Web.Controllers.HomeController.Index (Lighthouse.Web) in 1.304ms

This makes it seem like everything the action completed successfully. We could add a log to InvokeNextResourceFilter and InvokeNextExceptionFilterAsync if we catch an exception. Another alternative might be to print an "Executed action failed" message for failure cases

[rynowak]

Doesn't Kestrel or Hosting log unhandled exceptions? We designed logging such that you should only log exceptions if you catch without rethrowing. The top level handler should log. Otherwise you end up with world-ending spam every time an exception happens.

[poke]

And in addition, the request should not be responded with a 200 status code. So I actually think that there is something else going on in the original OP’s project. Maybe there is an exception handler that swallows the exception after all.

[phatcher]

@poke I don't think I'm trapping the exceptions, also nothing is reported in Application Insights.

I'm going to see if I can reproduce this in a sample project

[poke]

@phatcher That would help a lot, thanks!

[pranavkm]

I was thinking more along the lines of changing

2018-10-24 09:42:46.897 +00:00 [Information] Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker: Executed action Lighthouse.Web.Controllers.HomeController.Index (Lighthouse.Web) in 1.304ms

to say

2018-10-24 09:42:46.897 +00:00 [Information] Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker: Executed action Lighthouse.Web.Controllers.HomeController.Index (Lighthouse.Web) with errors in 1.304ms

when the action fails. Right now it seems like the action successfully completed which might be misleading

[rynowak]

I think it's fine to change the log to mentioned that it failed. I still am curious how we ended up in a situation where an exception occurred and it's not obvious somewhere in the log.

Did the exception get swallowed?

[poke]

I just tested this explicitly, attempting to reproduce OP’s exact situation: I have a controller that takes a dependency and that dependency randomly throws an exception in its constructor. So the controller cannot get its dependencies resolved and the controller instantiation itself fails. I also explicitly removed any exception handling from the Startup to let the framework do its default job.

The code basically looks like this; the dependency is registered as transient:

public class TestController : Controller
{
    private readonly IDependency _dependency;
    public TestController(IDependency dependency) => _dependency = dependency;
    public IActionResult Test() => Content(_dependency.GetStuff());
}
public interface IDependency
{
    string GetStuff();
}
public class Dependency : IDependency
{
    private static Random random = new Random();
    public Dependency()
    {
        if (random.Next(2) == 1)
            throw new Exception("failure!");
    }
    public string GetStuff() => "foo";
}

When I run this, an unsuccessful request looks like this in the logs (trace logs enabled):

info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://localhost:5000/Test/Test
trce: Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware[0]
      All hosts are allowed.
dbug: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware[4]
      The request path /Test/Test does not match a supported file type
dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1001]
      1 candidate(s) found for the request path '/Test/Test'
dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1005]
      Endpoint 'Issue8643.Controllers.TestController.Test (Issue8643)' with route pattern 'Test/Test/{id?}' is valid for the request path '/Test/Test'
dbug: Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware[1]
      Request matched endpoint 'Issue8643.Controllers.TestController.Test (Issue8643)'
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'Issue8643.Controllers.TestController.Test (Issue8643)'
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Route matched with {action = "Test", controller = "Test"}. Executing action Issue8643.Controllers.TestController.Test (Issue8643)
dbug: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Execution plan of authorization filters (in the following order): None
dbug: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Execution plan of resource filters (in the following order): Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter
dbug: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Execution plan of action filters (in the following order): Microsoft.AspNetCore.Mvc.Internal.ControllerActionFilter (Order: -2147483648), Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter (Order: -3000)
dbug: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Execution plan of exception filters (in the following order): None
dbug: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Execution plan of result filters (in the following order): Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Resource Filter: Before executing OnResourceExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
      Resource Filter: After executing OnResourceExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.

trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Resource Filter: Before executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
      Resource Filter: After executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action Issue8643.Controllers.TestController.Test (Issue8643) in 1.3013ms
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'Issue8643.Controllers.TestController.Test (Issue8643)'
fail: Microsoft.AspNetCore.Server.Kestrel[13]
      Connection id "0HLHQO6E7UVHN", Request id "0HLHQO6E7UVHN:00000003": An unhandled exception was thrown by the application.
System.Exception: failure!
   at Issue8643.Controllers.Dependency..ctor() in C:\Users\poke\Desktop\Issue8643\Controllers\TestController.cs:line 36
   at System.RuntimeType.CreateInstanceDefaultCtor(Boolean publicOnly, Boolean skipCheckThis, Boolean fillCache, Boolean wrapExceptions)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitCreateInstance(CreateInstanceCallSite createInstanceCallSite, ServiceProviderEngineScope scope)
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(IServiceCallSite callSite, TArgument argument)
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitTransient(TransientCallSite transientCallSite, ServiceProviderEngineScope scope)
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(IServiceCallSite callSite, TArgument argument)
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.DynamicServiceProviderEngine.<>c__DisplayClass1_0.<RealizeService>b__0(ServiceProviderEngineScope scope)
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngine.GetService(Type serviceType, ServiceProviderEngineScope serviceProviderEngineScope)
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngineScope.GetService(Type serviceType)
   at Microsoft.Extensions.DependencyInjection.ActivatorUtilities.GetService(IServiceProvider sp, Type type, Type requiredBy, Boolean isDefaultParameterRequired)
   at lambda_method(Closure , IServiceProvider , Object[] )
   at Microsoft.AspNetCore.Mvc.Controllers.ControllerActivatorProvider.<>c__DisplayClass4_0.<CreateActivator>b__0(ControllerContext controllerContext)
   at Microsoft.AspNetCore.Mvc.Controllers.ControllerFactoryProvider.<>c__DisplayClass5_0.<CreateControllerFactory>g__CreateController|0(ControllerContext controllerContext)
   at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.InvokeInnerFilterAsync()
   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.InvokeNextResourceFilter()
   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.Rethrow(ResourceExecutedContext context)
   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)

   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.InvokeFilterPipelineAsync()
   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.InvokeAsync()
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.Invoke(HttpContext httpContext)
   at Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware.Invoke(HttpContext httpContext)
   at Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)
dbug: Microsoft.AspNetCore.Server.Kestrel[9]
      Connection id "0HLHQO6E7UVHN" completed keep alive response.
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 33.2887ms 500

I only added two newlines to that where the filter pipeline starts going in reverse (where you would usually see the action being executed). As you can see, the exception is properly caught by the framework and the error is properly logged and produces a 500 status code. The stack trace is also correct and shows where the exception originated (TestController.cs:line 36 is where the throw inside the Dependency is).

Just for comparison, this is a successful request; I inserted a space first where the two requests diverge (on the ControllerActionFilter) and another where the two spaces were above:

info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://localhost:5000/Test/Test
trce: Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware[0]
      All hosts are allowed.
dbug: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware[4]
      The request path /Test/Test does not match a supported file type
dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1001]
      1 candidate(s) found for the request path '/Test/Test'
dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1005]
      Endpoint 'Issue8643.Controllers.TestController.Test (Issue8643)' with route pattern 'Test/Test/{id?}' is valid for the request path '/Test/Test'
dbug: Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware[1]
      Request matched endpoint 'Issue8643.Controllers.TestController.Test (Issue8643)'
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'Issue8643.Controllers.TestController.Test (Issue8643)'
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Route matched with {action = "Test", controller = "Test"}. Executing action Issue8643.Controllers.TestController.Test (Issue8643)
dbug: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Execution plan of authorization filters (in the following order): None
dbug: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Execution plan of resource filters (in the following order): Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter
dbug: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Execution plan of action filters (in the following order): Microsoft.AspNetCore.Mvc.Internal.ControllerActionFilter (Order: -2147483648), Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter (Order: -3000)
dbug: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Execution plan of exception filters (in the following order): None
dbug: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Execution plan of result filters (in the following order): Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Resource Filter: Before executing OnResourceExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
      Resource Filter: After executing OnResourceExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.

trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Action Filter: Before executing OnActionExecutionAsync on filter Microsoft.AspNetCore.Mvc.Internal.ControllerActionFilter.
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Action Filter: Before executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
      Action Filter: After executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Executing action method Issue8643.Controllers.TestController.Test (Issue8643) - Validation state: Valid
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action method Issue8643.Controllers.TestController.Test (Issue8643), returned result Microsoft.AspNetCore.Mvc.ContentResult in 0.0599ms.
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Action Filter: Before executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
      Action Filter: After executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
      Action Filter: After executing OnActionExecutionAsync on filter Microsoft.AspNetCore.Mvc.Internal.ControllerActionFilter.
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Result Filter: Before executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
      Result Filter: After executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[4]
      Before executing action result Microsoft.AspNetCore.Mvc.ContentResult.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ContentResultExecutor[1]
      Executing ContentResult with HTTP Response ContentType of text/plain; charset=utf-8
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[5]
      After executing action result Microsoft.AspNetCore.Mvc.ContentResult.
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Result Filter: Before executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
      Result Filter: After executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.

trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Resource Filter: Before executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.
trce: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
      Resource Filter: After executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action Issue8643.Controllers.TestController.Test (Issue8643) in 11.742ms
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'Issue8643.Controllers.TestController.Test (Issue8643)'
dbug: Microsoft.AspNetCore.Server.Kestrel[9]
      Connection id "0HLHQO6E7UVHO" completed keep alive response.
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 25.4307ms 200 text/plain; charset=utf-8

So the framework is doing its job correctly. Exceptions are logged and unhandled exceptions cause a 500 status code. Since that is not happening with OP’s project, there must be some middleware that swallows or otherwise handles the exception (without logging it itself).

I do not consider a log entry change to “Executed action […] with errors” very helpful. First, it does not provide any information whatsoever. So you have to rely on those errors being logged out separately anyway (in which case, the “with errors” part is rather obvious). Second, it requires the ResourceInvoker to be able to identify those errors, adding unnecessary complexity to the logging. And third, I don’t even see a clear definition of “with errors”. Is this only a thrown exception? Is this also a non-successful status code? What if there’s middleware afterwards that handles these cases anyway, so that this actually isn’t an error?

[pranavkm]

. So you have to rely on those errors being logged out separately anyway (in which case, the “with errors” part is rather obvious).

Fair enough, that seems like a reasonable argument. Closing this