Prevent Microsoft Logging from log when Unhandled exception thrown

Question

I have ASP.NET Core 3.0 website.
I installed NLog on the project, here is the configuration

public static void Main(string[] args)
{
    var logger = NLogBuilder.ConfigureNLog("nlog.config").GetCurrentClassLogger();
    BuildWebHost(args).Run();
}

public static IWebHost BuildWebHost(string[] args)
{
    return WebHost.CreateDefaultBuilder(args)
        .ConfigureLogging(logging =>
        {
            logging.ClearProviders();
            logging.SetMinimumLevel(Microsoft.Extensions.Logging.LogLevel.Trace);
        })
        .UseNLog()
        .UseStartup<Startup>()
        .UseUrls("http://*:8080")
        .Build();
}



public class Startup
{
    // some constructors

    public void ConfigureServices(IServiceCollection services)
    {
        var serviceProvider = services.BuildServiceProvider();
        var logger = serviceProvider.GetService<ILogger<object>>();
        services.AddSingleton<ILogger>(logger);
    }
}

nlog.config file is

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      autoReload="false"
      throwExceptions="true"
      internalLogLevel="Off">

  <extensions>
    <add assembly="NLog.Web.AspNetCore"/>
  </extensions>

  <variable name="sperator" value="-----------------------------------" />

  <targets>
    <target name="allfile"
            xsi:type="File"
            fileName="${basedir}/Logs/${date:format=yyyy-MM-dd}.log"
            archiveEvery="Day"
            archiveFileName="${basedir}/Logs/Log${shortdate}-{#}.log"
            archiveNumbering="Sequence"
            layout="eventId : ${event-properties:item=EventId_Name}${newline}${message} ${newline} ${sperator} ${newline}" />

  </targets>

  <!-- rules to map from logger name to target -->
  <rules>
    <logger name="*" minlevel="Trace" writeTo="allfile" />
  </rules>
</nlog>

appsettings.config

"Logging": {
    "LogLevel": {
      "Default": "Trace",
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Information"
    }
  },

Last thing I have a middleware to handle all the exceptions thrown from everywhere in the application

public class ExceptionMiddleware
{
    private readonly RequestDelegate _next;
    private readonly ILogger _logger;

    public ExceptionMiddleware(RequestDelegate next, ILogger logger)
    {
        _next = next;
        _logger = logger;
    }

    public async Task Invoke(HttpContext context)
    {
        context.Response.Clear();
        context.Response.ContentType = "application/json";

        var contextFeature = context.Features.Get<IExceptionHandlerFeature>();
        if (contextFeature == null)
            return;

        string jsonResult = "";

        context.Response.StatusCode = (int)HttpStatusCode.InternalServerError;

        EventId eventId = new EventId(0, Guid.NewGuid().ToString());
        _logger.LogError(eventId, message: $"Date : {DateTime.Now.ToString()} \nPath : {context.Request.Path} \nStackTrace: {contextFeature.Error.ToString()}");

        jsonResult = JsonConvert.SerializeObject(new
        {
           ErrorMessage = contextFeature.Error.Message,
           StackTrace = contextFeature.Error.StackTrace
        });

        await context.Response.WriteAsync(jsonResult);
    }
}

The problem is

when I throw an exception I get two logs in the log file (even if I log it only once)
I am convinced now that the first one is done automatically by Asp.NET CORE because the exception is considered as unhandled exceptions (even with the existence of the middleware which handle the exception)

here is the log I got

eventId : UnhandledException
An unhandled exception has occurred while executing the request. 
 ----------------------------------- 

eventId : 88e05695-fc66-4d99-8537-aba8f0fa211b
Date : 1/1/2020 5:09:17 PM 
Path : /api/AppParameter/ThrowException 
StackTrace: System.Exception: this exception has been throw for testing the NLog
   at BT_IQM.Services.WebApi.Controllers.AppParameterController.ThrowException() in C:\Users\BitegPC\Source\Repos\BT_Backend_Architecture\BT_IQM.Services.WebApi\Controllers\AppParameterController.cs:line 80
   at lambda_method(Closure , Object , Object[] )
   at Microsoft.Extensions.Internal.ObjectMethodExecutor.Execute(Object target, Object[] parameters)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.SyncActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()
--- End of stack trace from previous location where exception was thrown ---
   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 BT_IQM.Services.WebApi.Utility.LanguageMiddleware.Invoke(HttpContext context) in C:\Users\BitegPC\Source\Repos\BT_Backend_Architecture\BT_IQM.Services.WebApi\Utility\LanguageMiddlewareExtensions.cs:line 27
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task) 
 ----------------------------------- 

the second log is exactly what I am logging in the middleware, but my problem is in the first log (which I do not want to be presented at all), the second log is enough for me

I think my problem is in the configuration of the Logging (Especially in the appsettings.config file)

Update

here is the extension method which is register the exception middleware

public static class ExceptionMiddlewareExtensions
{
    public static void ConfigureExceptionHandler(this IApplicationBuilder app, ILogger logger)
    {
        app.UseExceptionHandler(appError => appError.UseMiddleware<ExceptionMiddleware>());
    }
}

and here is the whole Configure method

public void Configure(IApplicationBuilder app, IWebHostEnvironment env, ILogger logger
{
    app.ConfigureExceptionHandler(logger);
    app.ConfigureLanguageMiddleware();

    app.UseRouting();
    app.UseAuthentication();
    app.UseAuthorization();

    app.UseEndpoints(endpoints =>
    {
        endpoints.MapControllers();
    });

    app.UseSwagger();
    app.UseSwaggerUI(c =>
    {
        c.SwaggerEndpoint("/swagger/v1/swagger.json", "My API V1");
    });
}

Answer 1

app.UseExceptionHandler(appError => appError.UseMiddleware<ExceptionMiddleware>());

Okay, the problem here is that you are using the ExceptionHandlerMiddleware that ASP.NET Core ships with. This middleware takes care of catching the exception and then handles it in the way you configure it.

The way you are using it is by passing an exception handler application pipeline to it in which you run your own middleware that then produces the result.

Now, if you look at the source of the ExceptionHandlerMiddleware, then you can see that this is how it will eventually catch the exception and invoke its exception handler:

ExceptionDispatchInfo edi;
try
{
    var task = _next(context);
    // …
    return Task.CompletedTask;
}
catch (Exception exception)
{
    edi = ExceptionDispatchInfo.Capture(exception);
}

return HandleException(context, edi);

So it runs the middleware pipeline and just catches any exception and finally runs HandleException if it got so far. And this is the first thing HandleException does:

private async Task HandleException(HttpContext context, ExceptionDispatchInfo edi)
{
    _logger.UnhandledException(edi.SourceException);
    // …

    // much later then:
    await _options.ExceptionHandler(context);

    // …
}

So it logs that it caught an unhandled exception before even looking further at the exception and finally invoking the configured exception handler which will then invoke your custom middleware.

In the end, you won’t be able to prevent this logging, so you have three options now:

1. Filter out the log explicitly through the Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware filter key. This can be done without code changes in the appsettings.json. See the docs on log filtering for details:

   "Logging": {
     "LogLevel": {
       "Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware": "None"
     }
   }
   

2. Remove the log from your middleware and just use the existing log.

3. Do not invoke your middleware as part of the ExceptionHandlerMiddleware but make it a normal middleware that catches exceptions itself and then can do whatever you want.