Hosted app startup errors cause top-level exception logging to be lost when ShutdownOnDispose is enabled

[GREsau]

Type: Bug

NLog version: 5.0.1
NLog.Extensions.Logging version: 5.0.1

Platform: .NET 6

In this example, we have an IHostedService which throws an exception on startup, which bubbles up out of app.Run(). It should be caught and logged by the top-level exception handler, but nothing is logged because NLog has already been shutdown, presumably due to the IServiceProvider having been disposed.

using NLog;
using NLog.Extensions.Logging;

var logger = LogManager.GetCurrentClassLogger();

try
{
    var builder = Host.CreateDefaultBuilder(args);

    builder.ConfigureLogging(l => l.ClearProviders().AddNLog(new NLogProviderOptions { ShutdownOnDispose = true }));
    builder.ConfigureServices(s => s.AddHostedService<BrokenHostedService>());
    // This exception does get correctly logged when thrown:
    // builder.ConfigureServices(s => throw new Exception("DI config-time error!"));

    var app = builder.Build();

    app.Run();
}
catch (Exception exception)
{
    logger.Error(exception, "Stopped program because of exception");
    Environment.ExitCode = 1;
}
finally
{
    LogManager.Shutdown();
}

class BrokenHostedService : IHostedService
{
    public Task StartAsync(CancellationToken cancellationToken)
    {
        throw new Exception("Hosted service startup error!");
    }

    public Task StopAsync(CancellationToken cancellationToken)
    {
        return Task.CompletedTask;
    }
}

Example nlog.config (not particularly relevant to this bug, but here it is to aid repro):

<?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">
  <targets><target name="console" xsi:type="Console" /></targets>
  <rules><logger name="*" minlevel="Info" writeTo="console" /></rules>
</nlog>

This only occurs when ShutdownOnDispose is set to true - when false, the error is correctly logged. Of course, doing so may also cause different logs to be lost during app shutdown unless we also explicitly disable AutoShutdown.

When an exception is thrown during the IServiceCollection configuration, e.g. by uncommenting the relevant line of code in the above example, it is logged, presumably because the IServiceProvider has not yet been constructed (and so obviously hasn't been disposed).

This problem also occurs using NLog.Web.AspNetCore with the default NLogAspNetCoreOptions, as they now have ShutdownOnDispose enabled by default.

[snakefoot]

What happens if you change to this:

var logger = LogManager.GetCurrentClassLogger();

bool LogError(Exception exception)
{
   logger.Error(exception, "Stopped program because of exception");
   return false;   // Exception Filter should not suppress the Exception
} 

try
{
    logger.Info("Starting program...");

    var builder = Host.CreateDefaultBuilder(args);

    builder.ConfigureLogging(l => l.ClearProviders().AddNLog(new NLogProviderOptions { ShutdownOnDispose = true }));
    builder.ConfigureServices(s => s.AddHostedService<BrokenHostedService>());
    // This exception does get correctly logged when thrown:
    // builder.ConfigureServices(s => throw new Exception("DI config-time error!"));

    var app = builder.Build();

    app.Run();
}
catch (Exception exception) when (LogError(exception))
{
    Environment.ExitCode = 1;
    throw;
}
finally
{
    LogManager.Shutdown();
}

[snakefoot]

The reason for changing to ShutdownOnDispose = true was to ensure to have correct flush and shutdown for normal program-exit (Because the standard assembly-unloading-event / process-exit-event is not working on netcore on linux)

[GREsau]

What happens if you change to this:

In that case, LogError effectively does nothing, since it's still run only after the service provider is disposed. The throw does cause the exception to be The unhandled exception is printed to stdout by the .NET runtime, but that of course doesn't use the nlog-configured loggers.

[snakefoot]

Have you tested ? (since it works for me)

[GREsau]

Yes, when I run it the only output is:

Unhandled exception. System.Exception: Hosted service startup error!
   at BrokenHostedService.StartAsync(CancellationToken cancellationToken) in C:\projects\DotNetTest\Program.cs:line 39
   at Microsoft.Extensions.Hosting.Internal.Host.StartAsync(CancellationToken cancellationToken)
   at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.RunAsync(IHost host, CancellationToken token)
   at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.RunAsync(IHost host, CancellationToken token)
   at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.Run(IHost host)
   at Program.<Main>$(String[] args) in C:\projects\DotNetTest\Program.cs:line 23

Which is from the unhandled exception being logged to console by the .NET runtime, not NLog (note how it doesn't contain our log message "Stopped program because of exception")

[snakefoot]

I get this output:

2022/07/14 21:50:37.324|FATAL|Stopped program because of exception System.Exception: DI config-time error!
   at HostingExample.Program.<>c.<Main>b__0_5(IServiceCollection s) in C:\Users\snakefoot\source\repos\NLog.Extensions.Logging\examples\NetCore2\HostingExample\Program.cs:line 36
   at Microsoft.Extensions.Hosting.HostingHostBuilderExtensions.<>c__DisplayClass7_0.<ConfigureServices>b__0(HostBuilderContext context, IServiceCollection collection)
   at Microsoft.Extensions.Hosting.HostBuilder.CreateServiceProvider()
   at Microsoft.Extensions.Hosting.HostBuilder.Build()
   at Microsoft.Extensions.Hosting.HostingHostBuilderExtensions.RunConsoleAsync(IHostBuilder hostBuilder, CancellationToken cancellationToken)
   at HostingExample.Program.Main() in C:\Users\snakefoot\source\repos\NLog.Extensions.Logging\examples\NetCore2\HostingExample\Program.cs:line 40|HostingExample.Program|

Unhandled exception. System.Exception: DI config-time error!
   at HostingExample.Program.<>c.<Main>b__0_5(IServiceCollection s) in C:\Users\snakefoot\source\repos\NLog.Extensions.Logging\examples\NetCore2\HostingExample\Program.cs:line 36
   at Microsoft.Extensions.Hosting.HostingHostBuilderExtensions.<>c__DisplayClass7_0.<ConfigureServices>b__0(HostBuilderContext context, IServiceCollection collection)
   at Microsoft.Extensions.Hosting.HostBuilder.CreateServiceProvider()
   at Microsoft.Extensions.Hosting.HostBuilder.Build()
   at Microsoft.Extensions.Hosting.HostingHostBuilderExtensions.RunConsoleAsync(IHostBuilder hostBuilder, CancellationToken cancellationToken)
   at HostingExample.Program.Main() in C:\Users\snakefoot\source\repos\NLog.Extensions.Logging\examples\NetCore2\HostingExample\Program.cs:line 40
   at HostingExample.Program.<Main>()

[GREsau]

That's very strange - I definitely don't get that first log when I run it...

[snakefoot]

Have added an extra line to the example program:

logger.Info("Starting program...");

Do you see that output? (Maybe NLog.config is not loaded correctly)

[snakefoot]

Yes I can reproduce it now. I was testing with the exception from:

.ConfigureServices(s => throw new Exception("DI config-time error!"));

But I get your experience when StartAsync is throwing

[snakefoot]

Curious why Microsoft decided to dispose its LoggerFactory, before logging the error.

Espcially since the Microsoft Host has a Logger-object that is used for logging "Starting" / "Stopping" (But not failure)

[snakefoot]

Thank you for bringing this to my attention. NLog.Web.AspNetCore v5.1 have now been released:

https://www.nuget.org/packages/NLog.Web.AspNetCore/5.1.0

It reverts ShutdownOnDispose default value to false.