Issue with Serilog's RequestLogging and Rethrow

[ismaelbl]

Continuing the issue described here #104.

I have the configuration below in my Startup class:

options.UseSerilogRequestLogging(options =>
                {
                    options.MessageTemplate = "Estado: {CodigoEstado}";
                    options.GetLevel = (httpContext, elapsed, ex) =>
                    {
                        if (httpContext.Response.StatusCode > 499)
                            return LogEventLevel.Error;
                        return LogEventLevel.Information;
                    };

                    options.EnrichDiagnosticContext = Enrichers.PushSerilogProperties;
                });
                options.UseProblemDetails();
                options.UseCors(x => x
                    .AllowAnyOrigin()
                    .AllowAnyMethod()
                    .AllowAnyHeader());

                options.UseRouting();
                options.UseAuthenticationWithOptions(null);
                options.UseEndpoints(endpoints => { endpoints.MapControllers(); });
                options.UseSwaggerWithOptions(apiVersionDescriptionProvider, Configuration);

                options.UseDefaultFiles();
                options.UseStaticFiles();

Here it's my ProblemDetails configuration. I just want to Rethrow unhandled exceptions that I want to log.

     public static IServiceCollection AddProblemDetails(this IServiceCollection services,
           IWebHostEnvironment environment)
       {
           return services
                  .AddProblemDetails(options =>
                  {

                      options.IncludeExceptionDetails = (context, exception) => environment.IsDevelopment();
                      options.ShouldLogUnhandledException = (context, exception, problemDetails) => false;
                      
                      options.Rethrow<Exception>((ctx, ex) =>
                      {
                          if(ex is not ValidationException &&
                          ex is not ValidationDomainException &&
                          ex is not KeyNotFoundException &&
                          ex is not AuthenticationException &&
                          ex is not InvalidOperationException)
                          {
                              return true;
                          }
                          return false;
                      });

                      options.Map<ValidationException>(ex => new CustomValidationProblemDetails(ex));

                      options.Map<ValidationDomainException>(ex =>
                          new CustomValidationProblemDetails(ex,
                              ex.Failures.ToDictionary(
                                  s => s.Key.ToCamelCase(),
                                  s => s.Value.Select(d => new CustomValidationProblemDetails.Error(d.Code, d.Error)).ToList()
                                  )
                          )
                      );
                      options.Map<Exception>(ex =>
                                     new StatusCodeProblemDetails(StatusCodes.Status500InternalServerError)
                                     {
                                         Title = "Esta aplicación detectou un problema e debe pecharse. Se o erro persiste, póñase en contacto co administrador."
                                     });

                      #endregion            

                  });
       }

If I force and Exception in and endpoint I get the text belog in my log file. It's seems the same problem described in #104 still persists in v6.5.1.

NT|WEBAP|Aplicación|Anónimo|2023-01-23 16:06:18|Estado: 500|System.ArgumentException: patata
   at ClasesSenFume.Api.Controllers.CentrosController.GetAll(CentroFilterViewModel filter) in C:\Users\ismaelbl\Desktop\Proyectos\ClasesSenFume\sw-csf\src\ClasesSenFume.Api\Controllers\CentrosController.cs:line 48
   at lambda_method(Closure , Object )
   at Microsoft.Extensions.Internal.ObjectMethodExecutorAwaitable.Awaiter.GetResult()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.AwaitableObjectResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Hellang.Middleware.ProblemDetails.ProblemDetailsMiddleware.Invoke(HttpContext context)
   at Hellang.Middleware.ProblemDetails.ProblemDetailsMiddleware.HandleException(HttpContext context, ExceptionDispatchInfo edi)
   at Hellang.Middleware.ProblemDetails.ProblemDetailsMiddleware.Invoke(HttpContext context)
   at Serilog.AspNetCore.RequestLoggingMiddleware.Invoke(HttpContext httpContext)

NT|WEBAP|Aplicación||2023-01-23 16:06:19|Connection id "0HMNTADB12UF5", Request id "0HMNTADB12UF5:00000001": An unhandled exception was thrown by the application.|System.ArgumentException: patata
   at ClasesSenFume.Api.Controllers.CentrosController.GetAll(CentroFilterViewModel filter) in C:\Users\ismaelbl\Desktop\Proyectos\ClasesSenFume\sw-csf\src\ClasesSenFume.Api\Controllers\CentrosController.cs:line 48
   at lambda_method(Closure , Object )
   at Microsoft.Extensions.Internal.ObjectMethodExecutorAwaitable.Awaiter.GetResult()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.AwaitableObjectResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Hellang.Middleware.ProblemDetails.ProblemDetailsMiddleware.Invoke(HttpContext context)
   at Hellang.Middleware.ProblemDetails.ProblemDetailsMiddleware.HandleException(HttpContext context, ExceptionDispatchInfo edi)
   at Hellang.Middleware.ProblemDetails.ProblemDetailsMiddleware.Invoke(HttpContext context)
   at Serilog.AspNetCore.RequestLoggingMiddleware.Invoke(HttpContext httpContext)
   at Microsoft.AspNetCore.Watch.BrowserRefresh.BrowserRefreshMiddleware.InvokeAsync(HttpContext context)
   at Microsoft.AspNetCore.Builder.Extensions.MapWhenMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)

[khellang]

Hi @ismaelbl! 👋🏻

I don't understand what the issue is. You've configured the middleware to rethrow ArgumentException. Why do you think it's an issue when an ArgumentException has been rethrown and logged in the request logging middleware?

[ismaelbl]

Hi @khellang. The problem it seems the same described in #104. The actual logging works fine, but it should just write this part:

NT|WEBAP|Aplicación|Anónimo|2023-01-23 16:06:18|Estado: 500|System.ArgumentException: patata
   at ClasesSenFume.Api.Controllers.CentrosController.GetAll(CentroFilterViewModel filter) in C:\Users\ismaelbl\Desktop\Proyectos\ClasesSenFume\sw-csf\src\ClasesSenFume.Api\Controllers\CentrosController.cs:line 48
   at lambda_method(Closure , Object )
   at Microsoft.Extensions.Internal.ObjectMethodExecutorAwaitable.Awaiter.GetResult()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.AwaitableObjectResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Hellang.Middleware.ProblemDetails.ProblemDetailsMiddleware.Invoke(HttpContext context)
   at Hellang.Middleware.ProblemDetails.ProblemDetailsMiddleware.HandleException(HttpContext context, ExceptionDispatchInfo edi)
   at Hellang.Middleware.ProblemDetails.ProblemDetailsMiddleware.Invoke(HttpContext context)
   at Serilog.AspNetCore.RequestLoggingMiddleware.Invoke(HttpContext httpContext) 

The entry below the first one seems to be produced by the aforementioned issue.

[khellang]

#104 is a completely different issue. The issue was that even though the exception was rethrown, the response ended up being empty.

[ismaelbl]

Ok, I thought it might have to do with the other issue because it's printting the Connection id "0HMNTADB12UF5", Request id "0HMNTADB12UF5:00000001": An unhandled exception was thrown by the application. message.

Sorry if it's not the case, does it occur to you what could be happening? Thanks.

[khellang]

It's hard to say what's happening as the code is incomplete and I don't know what the response looks like. To me, it looks like the request logging and problem details middleware are doing what they're supposed/configured to.

[ismaelbl]

Yes, it actually working as I spected, but for some reason it's printting two times the same exception. In the last one without the intervention of request logging. I will try to dig up more information next week.

[ismaelbl]

Hi, there. In the end the problem was caused by Serilog request logging. I solved it following serilog/serilog-aspnetcore#270. Instead of rethrowing the exception I set it via IDiagnosticContext.

[bartpio]

Good approach. I faced a similar issue and came up with a small library containing trivial middleware that sets exceptions in IDiagnosticContext before ProblemDetails handles them.