Logging to File Does not Work from AppDomain UnhandledException Event Handler

[elzik]

Description I have .NET 7 BackgroundService which is hosted using a Microsoft.Extensions.Hosting.Host. The BackgroundService takes a dependency on Serilog.Sinks.File as well as Serilog.Sinks.Console.

Generally logging to both the console and the file works except for a single scenario where logging to the console takes place as expected but no logging takes place to the file. The failing scenario is inside an event handler for the AppDomain.CurrentDomain.UnhandledException In this event handler, logging works as usual to the console sink but silently fails for the file sink.

Reproduction My BackgroundService class looks like this:

public class FmSyncWorker : BackgroundService
{
    private readonly ILogger<FmSyncWorker> _logger;

    public FmSyncWorker(ILogger<FmSyncWorker> logger)
    {
        AppDomain.CurrentDomain.UnhandledException += OnUnhandledException;

        _logger = logger ?? throw new ArgumentNullException(nameof(logger));
    }

    protected override async Task ExecuteAsync(CancellationToken stoppingToken)
    {
        _logger.LogInformation("I can log here to console and file.");

        throw new InvalidOperationException("This is an unhanlded unexception which should lead to a message " +
            "on the console and the file log.");

        await Task.Yield();
    }

    private void OnUnhandledException(object sender, UnhandledExceptionEventArgs e)
    {
        _logger.LogInformation("I can log here only to console. File logging does not work.");
    }
}

The service is hosted from Program.cs like so:

using Elzik.FmSync.Worker;
using Serilog;

var host = Host.CreateDefaultBuilder(args)
    .ConfigureAppConfiguration((_, config) =>
        {
            config.AddJsonFile("appSettings.json", false);
        })
    .UseSerilog((context, config) => config.ReadFrom.Configuration(context.Configuration))
    .ConfigureServices((hostContext, services) =>
        {
            services.AddHostedService<FmSyncWorker>();
        })
    .Build();

Serilog.Debugging.SelfLog.Enable(Console.Error);

host.Run();

And configured with:

{
  "Serilog": {
    "Using": [ "Serilog.Sinks.Console", "Serilog.Sinks.File" ],
    "MinimumLevel": {
      "Default": "Information"
    },
    "WriteTo": [
      { "Name": "Console" },
      {
        "Name": "File",
        "Args": {
          "path": "serilog-issue.log",
          "rollingInterval": "Day",
          "retainedFileCountLimit": "7"
        }
      }
    ]
  }
}

To make things easier to reproduce I have distilled my problem down to the minimum code necessary. You should be able to clone and checkout this branch and run the solution.

After running the solution you will see a message logged both by the console and file sinks in the happy path code. However, you will then see that an unhandled exception is thrown which is then handled by the OnUnhandledException handler. In this event handler, we expect again the logging to be performed by both the console sink and the file sink (as we saw before in the happy path) but the outcome is that it is performed by only the console sink.

Expected behavior With both console and file sinks configured, logging should be performed to both on all occasions, even when the logging is performed from a AppDomain.CurrentDomain.UnhandledException handler.

Relevant package, tooling and runtime versions

• Serilog.Sinks.File 5.0.0 with
• .NET 7 targeting Windows
• Serilog 3.1.1
• Serilog.Extensions.Hosting 8.0.0
• Serilog.Settings.Configuration 8.0.0
• Serilog.Sinks.Console 5.0.1

[elzik]

I have updated the code above to add Serilog self-logging and also pushed the same change to the repo linked. Self logging shows why the log is not being written to:

Caught exception while emitting to sink Serilog.Sinks.File.RollingFileSink: System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'The log file has been disposed.'.
   at Serilog.Sinks.File.RollingFileSink.Emit(LogEvent logEvent)
   at Serilog.Core.Sinks.SafeAggregateSink.Emit(LogEvent logEvent)

But this still leaves the question of whether this is expected behaviour or if the log file being disposed at this point is a bug?

[nblumhardt]

Hi @elzik -

By the time your unhandled exception callback is firing, the host has already unloaded itself and disposed the service container (including the logger).

You may still observe some interesting exceptions using the unhandled exception handler and file sink, but not ones thrown from ExecuteAsync() - you'll need a try/catch block in there.

HTH

[elzik]

I do wonder why the Console logger still works despite the host being unloaded and the service container being disposed of. But I also understand the two sinks are significantly different. Thanks for your reply, I'll have to go for a Try-Catch block.