Nlog: Improve shutdown logic when NLog is registered on an IHostBuilder

[alexvy86]

I'm using NLog in a .NET Core app which uses the generic host, inside a linux Docker container. As soon as the container receives a SIGTERM signal, NLog starts shutting down, even before the .NET Core host has done so, and that's causing some messages that I log during the "on stopping" lifetime hooks of the host, to never be logged through NLog (even though they do get to other logger providers if there are any).

This is related to #3012 . I understand the motivation mentioned there for NLog to subscribe to the ProcessExit event (simplifying the default configuration for most users), particularly for a console app with no concept of a host or a lifetime. But when using the .NET Core generic host (or the web host, for that matter), I think it would be a reasonable expectation to wait for the host to stop, before shutting down the NLog logger.

One option would be to change NLog's shutdown logic only when registering it on an IHostBuilder (see snippet below), so it "listens" to IApplicationLifetime's ApplicationStopped "event" instead of ProcessExit.

var hostBuilder = new HostBuilder()
    .ConfigureLogging((hostingContext, logging) => {
        logging.AddConfiguration(hostingContext.Configuration.GetSection("Logging"));
    })
    .UseNLog()
    .ConfigureServices(services => {
        services.AddHostedService<MyHostedService>();
    });

When registering directly on an ILoggingBuilder there is no guarantee that there's an application lifetime, so I can see how it could be more complicated in that scenario (which comes back to the suggestion in #3012 about making it possible to disable the automatic shutdown logic altogether).

Just for reference, since I already prepared it, here's a gif showing the different behavior when running directly on a Windows host (the messages from my hosted service's StopAsync method get logged correctly by NLog before the logger is shut down), and when running inside a linux Docker container (the NLog logger shuts down before my hosted service's StopAsync method runs, so its messages are only logged by the non-NLog console logger).

[welcome[bot]]

Hi! Thanks for opening your first issue here! Please make sure to follow the issue template - so we could help you better!

[304NotModified]

Hi,

At least we could add an option to disable it.

But It would be really nice if we could fix this issue, e.g. by using the IHostBuilder. I didn't have looked into that. I think it should work, as we could retrieve a IHostBuilder instance at the start of NLog?

[alexvy86]

Not sure that approach would work, the HostBuilder instance is created by the user, not provided by the DI container. I was thinking more along the lines of, when calling .UseNLog(), somehow getting to the IApplicationLifetime that corresponds to the host builder and wiring the NLog shutdown logic to it. I haven't checked where that logic is called right now (if it's on a static constructor somewhere, it would probably need to be refactored), but I'll try to spend some time playing with this idea in the coming days, hopefully even get a PR going.

[304NotModified]

Not sure that approach would work, the HostBuilder instance is created by the user, not provided by the DI container

Ah! Missed that part

but I'll try to spend some time playing with this idea in the coming days, hopefully even get a PR going.

That would be great!

[304NotModified]

PS you could by-pass the event with the following trick:

1. Implement NLog.Internal.Fakeables.IAppDomain, don't delegate ProcessExit events to the real appdomain (maybe also the same for DomainUnload) - you could use AppDomainWrapper or it's logic
2. Set LogFactory.CurrentAppDomain

PS: limited support here, we like to drop the public of IAppDomain / AppDomainWrapper (NLog 5 or 6)

[alexvy86]

Thanks for the tip, I'll explore that option too in the meantime.

[alexvy86]

@304NotModified I started playing with ideas to achieve this but I'd like to discuss with you first, since I'm not 100% convinced about either of the approaches that I could easily get to work, and they are only preliminary work before we can actually improve the behavior when registering NLog on IHostBuilder.

Context: I see that the events are currently hooked up in LogFactory's static constructor and when setting LogFactory's static CurrentAppDomain property.

Before hooking up NLog's shutdown logic to the IHost's lifetime, we need a way to either remove the handlers on AppDomain's events after they get registered, or to not register them in the first place. I'm just trying to decide between those 2 options first, since I expect hooking them up to the IHost lifetime will be more straightforward.

---

Idea 1: new API on LogFactory to remove the event handlers from AppDomain

I added a public method to LogFactory that simply does UnregisterEvents(currentAppDomain); (just like this). If I call that method at the beginning of my program, NLog doesn't shut down before the IHost anymore.

I have 2 concerns with this simple idea:

• The new method would need to set some internal state to prevent the event handlers from being registered against the AppDomain again, in case someone explicitly sets LogFactory.CurrentAppDomain after calling the new method.
• The fact that the events are still getting registered. It we wanted to let users choose if they want them or not, an approach that didn't register them at all sounds better than "oh we can't avoid registering them, so make this other call to remove them if you don't want them".

---

Idea 2: new static class to prevent registering events in LogFactory's static constructor

I created a new static class LogSettings with a static RegisterShutdownEvents bool property that defaults to true to maintain the current behavior. LogFactory's static constructor now only registers the event handlers if the new setting is true, and similarly for the calls to UnregisterEvents and RegisterEvents on the setter for LogFactory.CurrentAppDomain. In my program, I do LogSettings.RegisterShutdownEvents = false at the very start, and again NLog doesn't shut down before the IHost.

Concerns in this case:

• Another static class just to control the behavior of LogFactory's static constructor... feels like it shouldn't be necessary. Especially since all "high level" configuration usually happens through LogManager, but in this case that doesn't work because as soon as we try to access a static property there, LogFactory's static constructor will be called.
• Making it more robust so once NLog is "running", these options cannot be set anymore.

---

Idea 3: moving away from static constructors

I feel that moving stuff out of static constructors (into static methods that we can control when to call) is a better approach overall, but it's certainly trickier. It brings questions like who is responsible for calling the initialization method for LogFactory, the user or the library? If the library, at what point? If the user, that's a breaking change.

---

Idea 1 is the easiest and quickest to implement, but I wanted to see if you have any thoughts.

[lobster2012-user]

Hi! @alexvy86
My version

I think the logic for handling domain unloading needs to be completely removed from the factory.

public static bool AutoRegister {get;set;} => true
LogFactory(/*bool autoregister*/)
{
    if(AutoRegister)
   {
        NLogManager/*.DisposableManager.*/Register((IDisposable)this) // or factory for factory
   }
}
//Dispose => dm.Remove(this) // Not necessary

NLogManager/*.DisposableManager*/.UnregisterShutdownEvents()
NLogManager/*.DisposableManager*/.RegisterShutdownEvents()

[304NotModified]

Thanks for all the input! :tada:

I think 3 is the best, NLog is responsible for calling init, and it should be called before/after/around (not sure yet) when applying the config the first time.

For the short term, I think 1 and 2 are also OK

[blemasle]

Just hit this page after schratching my head around that behaviour for quite a bit of time.
Any advice on how to circumvent the problem while we gently wait for a fix ? 😃

Current suggestions cannot work without altering NLog source code...

[snakefoot]

@blemasle Sounds like a duplicate of https://github.com/NLog/NLog.Extensions.Logging/issues/313

Resolved with https://github.com/NLog/NLog.Extensions.Logging/pull/314 (NLog.Extension.Logging ver. 1.5.2)

You can configure NLog with appsettings.json:

{
    "Logging": {
        "NLog": {
            "ShutdownOnDispose": true
        }
    }
}

[blemasle]

Nice catch @snakefoot . Thanks !

[blemasle]

I must have missed something somewhere, but from what I can see, even when Dispose is called (and you either have to do it by hand or use another DI framework like Lamar for that to happen), logging with NLog is disabled at the time IHostedService.StopAsync is called :

Full repro :

<PackageReference Include="Lamar" Version="3.0.5" />
<PackageReference Include="Lamar.Microsoft.DependencyInjection" Version="3.1.2" />
<PackageReference Include="Microsoft.Extensions.Hosting" Version="2.2.0" />
<PackageReference Include="Microsoft.Extensions.Logging" Version="2.2.0" />
<PackageReference Include="Microsoft.Extensions.Logging.Console" Version="2.2.0" />
<PackageReference Include="NLog.Config" Version="4.6.7" />
<PackageReference Include="NLog.Extensions.Logging" Version="1.5.3" />

class Program
{
    static async Task<int> Main(string[] args)
    {
        IHost host = new HostBuilder()
            .ConfigureServices(s =>
            {
                s.AddHostedService<HostedService>();
                s.Configure<HostOptions>(options =>
                {
                    options.ShutdownTimeout = TimeSpan.FromSeconds(20);
                });
            })
            .ConfigureLogging((c, l) =>
            {
                l.SetMinimumLevel(LogLevel.Debug);
                l.ClearProviders();
                l.AddNLog(new NLogProviderOptions
                {
                    ShutdownOnDispose = true
                });

            })
            .UseLamar()
            .UseConsoleLifetime()
            .Build();

        await host.RunAsync();
        return 0;
    }
}

internal class HostedService : IHostedService
{
    private readonly ILogger<HostedService> _logger;

    public HostedService(ILogger<HostedService> logger)
    {
        _logger = logger;
    }

    public Task StartAsync(CancellationToken cancellationToken)
    {
        _logger.LogDebug("PID: {0}", Process.GetCurrentProcess().Id);
        return Task.CompletedTask;
    }

    public async Task StopAsync(CancellationToken cancellationToken)
    {
        _logger.LogInformation("StopAsync called");
        Console.WriteLine("Debug IsEnabled: " + _logger.IsEnabled(LogLevel.Debug));
        Console.WriteLine("Error IsEnabled: " + _logger.IsEnabled(LogLevel.Error));

        await Task.Delay(5000);
    }
}

2019/09/02 14:16:18.015|DEBUG|Hosting starting |Microsoft.Extensions.Hosting.Internal.Host|EventId_Id=1, EventId=1
2019/09/02 14:16:18.181|INFO|StartAsync Called |GracefulShutdown.HostedService|
2019/09/02 14:16:18.187|DEBUG|PID: 3747 |GracefulShutdown.HostedService|
Application started. Press Ctrl+C to shut down.
Hosting environment: Production
Content root path: /mnt/c/Users/Bertrand/source/repos/GracefulShutdown/bin/Debug/netcoreapp2.2/
2019/09/02 14:16:18.199|DEBUG|Hosting started |Microsoft.Extensions.Hosting.Internal.Host|EventId_Id=2, EventId=2
Debug IsEnabled: False
Error IsEnabled: False
````

That does not happen when sending `SIGTERM` with the default logging provider from Microsoft (just call `l.AddConsole()` instead of `l.AddNLog()`) :

dbug: Microsoft.Extensions.Hosting.Internal.Host[1]
Hosting starting
info: GracefulShutdown.HostedService[0]
StartAsync Called
dbug: GracefulShutdown.HostedService[0]
PID: 3951
Application started. Press Ctrl+C to shut down.
Hosting environment: Production
Content root path: /mnt/c/Users/Bertrand/source/repos/GracefulShutdown/bin/Debug/netcoreapp2.2/
dbug: Microsoft.Extensions.Hosting.Internal.Host[2]
Hosting started
dbug: Microsoft.Extensions.Hosting.Internal.Host[3]
Hosting stopping
info: GracefulShutdown.HostedService[0]
StopAsync called
Debug IsEnabled: True
Error IsEnabled: True
dbug: Microsoft.Extensions.Hosting.Internal.Host[4]
Hosting stopped
```

[snakefoot]

@blemasle Sorry about misleading you. It is still an open issue with NLog automatically reacting to AppDomain Unload. This is to support IIS and other AppDomain-hosting-environments (Ex. Silverlight).

Though I'm curious why there is not a 4th Idea/Suggestion. Make a setting like LogFactory.ThrowConfigExceptions that can be configured from NLog.config. Lets call this setting LogFactory.AutoShutdown. When the setting is assigned to false then it will just unhook the LogFactory from the LoggerShutdown-event. Letting the application-owner take over the task of calling LogFactory.Shutdown() manually when sensible.

Should be simple to implement. Then after having introduced this property then we can fix the UseNLog to configure AutoShutdown = false by default and instead hook into the HostBuilder-lifetime-interface for the shutdown.

[snakefoot]

Created #3578 with an example of my idea no 4. Name of the property can be whatever you like.

[blemasle]

@snakefoot Thanks. I'll keep an eye on it.

[snakefoot]

@304NotModified Resolved with #3578 that will be included in the coming NLog ver. 4.6.8

[snakefoot]

@alexvy86 NLog ver. 4.6.8 has been released:

https://www.nuget.org/packages/NLog

You can now configure NLog not to shutdown on AppDomain-Unload:

NLog.LogManager.AutoShutdown = false;

And instead use:

{
    "Logging": {
        "NLog": {
            "ShutdownOnDispose": true
        }
    }
}