Add SynchronousWrite option for immediate log persistence

[icnocop]

Introduce SynchronousWrite setting to file logger configuration, allowing log entries to be written directly to file on the calling thread and bypassing the background queue. This ensures logs are persisted before ILogger.Log returns, useful for crash diagnostics. Updated processor, settings, and documentation. Added unit tests for both global and per-file SynchronousWrite behavior.

[adams85]

First of all, thanks for the contribution.

However, at a first glance, I'm not convinced that this a good idea: such a block-waiting operation mode is a big performance killer.

Could you tell me more about your application that would require this? With what kind of crashes would this help?

Please note that even though the current implementation uses background queues, it makes sure that the queues are written to disk when the logger gets disposed. So, if your application handles shutdown correctly, you shouldn't really end up with missing logs. (There is a completion timeout though, which is set to 1.5 sec by default. However, this can be increased as needed.)

AFAICS, the only cases where you can actually lose some logs are non-catchable exceptions like StackOverflowException, which bring down the process, or hardware failures. But in those cases not even block-waiting can ensure that the latest log entries are written (apart from single-threaded applications).

The other benefit of the proposed mode I can imagine is that it would enable applying backpressure in an application that produces a huge amount of logs. Is this maybe what you want to achieve?

[icnocop]

However, at a first glance, I'm not convinced that this a good idea: such a block-waiting operation mode is a big performance killer.

Right, it's not a good idea to enable this by default in production. This setting is disabled by default.

Could you tell me more about your application that would require this? With what kind of crashes would this help?

Any exception that is not caught and cause the application to crash, or worse, causes a BSOD, when calling low-level Win32 APIs which perform hardware I/O for example. When a BSOD occurs for example, the latest log messages are not flushed to disk and so it makes it harder to troubleshoot the issue without the latest log messages.

So, if your application handles shutdown correctly, you shouldn't really end up with missing logs.

This feature is specifically for when the application doesn't gracefully shutdown, as a result of a BSOD for example.

There is a completion timeout though, which is set to 1.5 sec by default. However, this can be increased as needed.

This internal value doesn't seem like it satisfies the requirements. For example, I can't set it in appsettings.json, and I'm not sure a timeout value would achieve the desired results.

AFAICS, the only cases where you can actually lose some logs are non-catchable exceptions like StackOverflowException, which bring down the process, or hardware failures. But in those cases not even block-waiting can ensure that the latest log entries are written (apart from single-threaded applications).

When SynchronousWrite is enabled, log messages are written to disk immediately, and persist after a BSOD for example.
The assumption is that the message sent to the logger is on the same thread that causes the BSOD.

The other benefit of the proposed mode I can imagine is that it would enable applying backpressure in an application that produces a huge amount of logs. Is this maybe what you want to achieve?

No. The logs don't have to be huge. The log messages can be filtered by their category.
The idea is to not have to wait for the queue to write the log messages to disk and to write them immediately.
In most cases, I would imagine enabling SynchronousWrite would only be done temporarily to diagnose and troubleshoot issues like a hard crash or BSOD.

I could imagine another case where enabling SynchronousWrite may also be able to help troubleshoot multi-threaded issues in an application since there is a lock around writing messages to the log file.

Thank you for your consideration.

[adams85]

This internal value doesn't seem like it satisfies the requirements. For example, I can't set it in appsettings.json, and I'm not sure a timeout value would achieve the desired results.

Another option is to set it to Timeout.InfiniteTimeSpan and let your application handle shutdown timeout. E.g. generic host has this built-in.

When SynchronousWrite is enabled, log messages are written to disk immediately, and persist after a BSOD for example.

You mean "...persist before a BSOD for example", right? I'd be surprised if anything was persisted after you got a BSOD.

---

This feature is specifically for when the application doesn't gracefully shutdown, as a result of a BSOD for example.

Okay, I think now I understand what you are onto. This would be a kind of temporary diagnostic mode that could help you track down nasty crashes that brings down the process or even the OS.

After all, I see some value in this. However, the implementation would need some more work. E.g.:

When a BSOD occurs for example, the latest log messages are not flushed to disk and so it makes it harder to troubleshoot the issue without the latest log messages.

A further problem that there may be OS-level buffering. So in this mode we probably want to write through such buffers, e.g., using Flush(true)).

I could imagine another case where enabling SynchronousWrite may also be able to help troubleshoot multi-threaded issues in an application since there is a lock around writing messages to the log file.

However, as you're surely aware, locks result in queuing too. It's just a blocking queue, not an asynchronous one.

So, if possible, I'd prefer to implement this on top of the queues (channels) we already have in place.

A pattern like this might work:

var channel = Channel.CreateBounded<ChannelItem<int>>(new BoundedChannelOptions(10)
{
	FullMode = BoundedChannelFullMode.Wait,
});

// Start consumer
Task.Run(() => ProcessItemsAsync());

// Produce items
for (var i = 0; ; i++)
{
	WriteAndWaitForProcessing(i).ConfigureAwait(false).GetAwaiter().GetResult(); // sync-over-async ??
}

async Task WriteAndWaitForProcessing(int data, CancellationToken ct = default)
{
	var item = new ChannelItem<int>(data);
	await channel.Writer.WriteAsync(item, ct).ConfigureAwait(false);

	// Wait for processing to complete
	await item.ProcessingCompleted.Task.ConfigureAwait(false);
}

async Task ProcessItemsAsync(CancellationToken ct = default)
{
	await foreach (var item in channel.Reader.ReadAllAsync(ct))
	{
		try
		{
			// Simulate work
			await Task.Delay(100); 
			Console.WriteLine($"Processed: {item.Data}");

			// Signal completion
			item.ProcessingCompleted.TrySetResult();
		}
		catch (Exception ex)
		{
			item.ProcessingCompleted.TrySetException(ex);
		}
	}
}

public class ChannelItem<T>(T data)
{
	public T Data { get; } = data; 
	
	public TaskCompletionSource ProcessingCompleted { get; } = new(TaskCreationOptions.RunContinuationsAsynchronously);
}

However, I'm not very comfortable with blocking over asynchronous code. That's a recipe for disaster.

BTW, your proposed implementation has the same problem: https://github.com/adams85/filelogger/pull/38/changes#diff-c8fcc66b270a7480057aa3ef1653e60d2c45571d64adee00e307f9f7fcde9354R395-R398

Another option would be to implement a fully synchronous code path. But that would require a lot of code duplication.

I need to give this some more thought and weigh up the pros and cons. In the meantime, I'd love to hear your opinion too.