Console app using Console logger will not write final messages. Easy repro

.net 6 console app on Windows using LoggerFactory - Final messages do not appear on the console. loggerFactory.Dispose() doesn't help. Ilogger does not have a Dispose() method.

Here's a repro. About 20 to 70 of the loop messages appear. After that, nothing.

using var loggerFactory = LoggerFactory.Create(builder =>
{
    builder
        .AddFilter("Microsoft", LogLevel.Warning)
        .AddFilter("System", LogLevel.Warning)
        .AddFilter("MyTestApp.Program", LogLevel.Debug)
        .AddConsole();
});
ILogger logger = loggerFactory.CreateLogger<Program>();
try
{ 
    logger.LogInformation("Starting");
    for (var i=0; i < 100; i++)
    {
        logger.LogInformation($"This is a nice long message for {i}.");
    }
    throw new Exception("boom");
}
catch (Exception e)
{
    logger.LogInformation(e.ToString());
}
finally
{
    loggerFactory.Dispose();
}

It's due to the way Microsoft.Extensions.Logging.Console\src\ConsoleLoggerProcessor.cs was refactored in this commit (Associated PR).

Calling logger.Log doesn't have to immediately flush the message. If it did, the call could possibly take a long time and block longer than desired. The logger passes the message to all the internal ILoggers created from your ILoggerProviders and do what they will with those messages. Configuring LoggerFactory with builder.AddConsole(); adds ConsoleLoggerProvider : ILoggerProvider in your situation.

Upon creating an ILoggerFactory, all of your configured providers are instantiated and this is when ConsoleLoggerProvider constructs a new class called ConsoleLoggerProcessor. It's responsible for writing messages to Console.Out from a background thread it creates to process the console logger message queue. Loggers push messages to this queue so they can return to the caller quickly and not block for file IO.

When ILoggerFactory is disposed, it will dispose of all created ILoggerProviders which results in the disposal of ConsoleLoggerProcesser. Disposing that class calls Thread.Join on the message queue processing thread linked above.

Previously, ConsoleLoggerProcessor's queue was implemented with BlockingCollection<T>. Here's an extremely simplified view:

public class ConsoleLoggerProcessor : IDisposable
{
    private readonly Thread _outputThread;
    private readonly BlockingCollection<string> _messageQueue = new();

    public ConsoleLoggerProcessor()
    {
        _outputThread = new Thread(ProcessLogQueue) { IsBackground = true };
        _outputThread.Start();
    }

    public void EnqueueMessage(string message)
    { /* snip */ }

    private void ProcessLogQueue()
    {
        foreach (var message in _messageQueue.GetConsumingEnumerable())
        {
            Console.WriteLine(message);
        }
    }

    public void Dispose()
    {
        _messageQueue.CompleteAdding();
        _outputThread.Join(millisecondsTimeout: 1500);
    }
}

Upon disposal, the BlockingCollection is completed which prevents more adding, but _messageQueue.GetConsumingEnumerable() does not yield break; until both conditions are true

• Is adding complete?
• Is the queue empty?

This means that _outputThread will not terminate until either ProcessLogQueue returns or the 1500 millisecond timeout hits.

Compare this to the new implementation using Queue<T>. Again extremely simplified to get the point across.

public class ConsoleLoggerProcessor : IDisposable
{
    private readonly Thread _outputThread;
    private readonly Queue<string> _messageQueue = new();
    private bool _isAddingCompleted;

    public ConsoleLoggerProcessor()
    {
        _outputThread = new Thread(ProcessLogQueue) { IsBackground = true };
        _outputThread.Start();
    }

    public void EnqueueMessage(string message)
    { /* snip */ }

    private void ProcessLogQueue()
    {
        while (_isAddingCompleted)
        {
            if (_messageQueue.Count > 0)
            {
                Console.WriteLine(_messageQueue.Dequeue());
            }
        }
    }

    public void Dispose()
    {
        _isAddingCompleted = true;
        _outputThread.Join(millisecondsTimeout: 1500);
    }
}

When this implementation is disposed, the flag _isAddingCompleted is set to true and the tight loop in ProcessLogQueue essentially terminates immediately. In the real implementation, there are some synchronization barriers so ProcessLogQueue doesn't pin a core at 100%.

So it boils down to this:

The previous logger had up to 1.5 seconds to flush what is left in the queue. Blocking your application from exiting for up to 1.5 seconds because Thread.Join blocks the calling thread (the main thread) until it terminates.

The current implementation doesn't wait for messages to be flushed. It exits immediately.