0

I have a C# project using a Logger.

To improve performance, this Logger will add the log info to a waiting queue, and another thread will handle it, including writing it to the Console and the log file.

Unfortunately, it has a big problem: if the process is terminating so fast that the logger isn't fast enough to keep up and handle the rest of log infos in the queue, THEY WILL BE PERMANENTLY LOST.

More clearly, this is the main code of my logging handle thread:

public static void Info(string content, string? sender = null)
    => qlog.Enqueue(new LogDetail(content, LogLevel.Information, sender));

...

private static ConcurrentQueue<LogDetail> qlog = new();
public static int RefreshLogTicks { get; set; }

private static async Task BackgroundUpdate()
{
    if (!qlog.TryDequeue(out LogDetail _log))
    {
         await Task.Delay(RefreshLogTicks);
         await Task.Run(BackgroundUpdate);
         return;
    }

    List<string> logs = new(qlog.Count + 1);
    logs.Add(WriteLog(_log));
    while (qlog.TryDequeue(out LogDetail log))
    {
         logs.Add(WriteLog(log));
    }
    ConsoleWrapper.WriteLine(logs);  

    await Task.Delay(RefreshLogTicks);
    await Task.Run(BackgroundUpdate);
}

(If needed, the full code is open source on GitHub)

Then if I execute code like this:

Console.WriteLine("Hello, ");
Log.Info("Logger!", "Hello");
Console.WriteLine("World!");
Environment.Exit(0);

Then I get an output as this: (at least on my sloooow laptop with a 2-core CPU)

Hello,
World!

If I apply a simple change:

Console.WriteLine("Hello, ");
Log.Info("Logger!", "Hello");
Console.WriteLine("World!");
Console.ReadLine();
Environment.Exit(0);

Then the logger output will recover:

Hello,
World!
21:28:17 <Info:Hello> Logger!

So, I wonder if there's a way to guarantee that the process will terminate only when the queue is Empty? Or to make the process wait until the handle process ended?

(I know that I can't stop the exit process if someone kills it, so "end" below refers to a normal exit, e.g. Environment.Exit() or Application.Exit().)

Notice that I aren't expecting an implement like providing a method Stop() and demand invoking it before closing because I don't think the code users will always correctly invoke it - and as it is mentioned above, if an extra invoke is needed, Console.ReadLine() seems far more simple.

If it's impossible, please tell me as well. Thanks a lot!

Theodor Zoulias
  • 34,835
  • 7
  • 69
  • 104
Yyh
  • 103
  • 7
  • This might help you find a solution: https://stackoverflow.com/questions/62245866/why-the-console-exits-even-after-using-await – MrApnea Mar 30 '23 at 15:20
  • Are you really recursively calling `BackgroundUpdate()`? How does it initially start? The point would be to tell your foreground thread that a background task is still doing work. – CodeCaster Mar 30 '23 at 15:24
  • Currently, it's started by Task.Run() in the static initializer. But I demand to make a process like flush and close operate automatically - though probably unnecessary, that's what all the question about. – Yyh Mar 30 '23 at 15:29

3 Answers3

3

Personally I'd look at a Channel<T> here; this offers a similar API to a ConcurrentQueue<T>, but:

  • with full async support
  • bounded or unbounded, with options for what to do when a bounded channel is full
  • the ability to signal when you're done writing, so that a reader can detect "there will never be anything more"

Example below; note: if you remove the await log.Completed; line, it will show the symptom that you're trying to avoid:

using System;
using System.Collections.Generic;
using System.Threading;
using System.Threading.Channels;
using System.Threading.Tasks;

var log = new MyLogger();
for (int i = 0; i < 100; i++)
    await log.WriteAsync($"msg {i}");
log.Complete(); // tell it we're done writing
await log.Completed; // wait for it to drain
Console.WriteLine("exit");

sealed class MyLogger
{
    static readonly BoundedChannelOptions s_Options = new BoundedChannelOptions(capacity: 128)
    {
        SingleReader = true, // the only reader is WriteAllAsync
        SingleWriter = false, // we don't know about writers
    };
    private readonly Channel<string> qlog = Channel.CreateBounded<string>(s_Options);

    public MyLogger() => Completed = WriteAllAsync();

    public void Complete() => qlog.Writer.Complete();
    public ValueTask WriteAsync(string message, CancellationToken cancellation = default)
        => qlog.Writer.WriteAsync(message, cancellation);

    public Task Completed { get; }

    private async Task WriteAllAsync()
    {
        while (await qlog.Reader.WaitToReadAsync())
        {
            while (qlog.Reader.TryRead(out var item))
            {
                Console.WriteLine("logger: " + item);
            }
        }
    }
}
Marc Gravell
  • 1,026,079
  • 266
  • 2,566
  • 2,900
  • Appreciate a lot! But sadly, my logger implement handles all invokes background - without any waiting - for high efficiency. But if looking in this aspect, it's obvious that the demand in my question is most probably impossible, because it needs to wait for something without waiting. – Yyh Mar 30 '23 at 16:05
  • Actually, what inspired me is a method of preventing forms from closing - but after a quick search I learned that possibly it does not exist. Maybe I will use `Channel` to build a separate logger implement for the needed program. – Yyh Mar 30 '23 at 16:06
  • @Yyh "because it needs to wait for something without waiting" - um, yeah, that'll be a challenge – Marc Gravell Mar 30 '23 at 16:11
0

To do that you could use a ManualResetEventSlim. It's also a good idea to decline new logs when you're waiting for cancellation. For example:

private volatile bool _cancellationRequested;

public ManualResetEventSlim LogInProgressEvent { get; } = new ManualResetEventSlim();

public void CancelLogging() => _cancellationRequested = true;

public void LogSmth(string message)
{
     if (_cancellationRequested) return;
     qlog.Enqueue(message);
}

private static async Task BackgroundUpdate()
{
    // your code here
    if (_cancellationRequested && qlog.IsEmpty()) LogInProgressEvent.Set();
}

And then in your main method just call YourLogger.LogInProgressEvent.Wait() to wait of LogInProgressEvent setting as signaled

0

Personally, I think the key of my question is how to prevent the unflushed logs from being lost, or it's to say, how to execute a clean-up process when the program is terminating.

What solved my problem is the AppDomain.ProcessExit Event:

The EventHandler for this event can perform termination activities, such as closing files, releasing storage and so on, before the process ends.

Take my code for an example.

public static void Initialize()
{
    // ...
    AppDomain.CurrentDomain.ProcessExit += ClearUpLogQueue;
}

I registered an handler for this event, which flushs the unwritten content and dispose log files.

Then run a test:

// Sudden terminate test
Log.Info($"The clearup succeed!");
Environment.Exit(0);

By this fix, the last log message is successfully flushed.

22:52:10 <Info> The clearup succeed!

Notice that it won't work when Environment.FailFast is invoked (actually expected):

Log.Info($"The clearup succeed!");
Environment.FailFast("test message, not error");
Process terminated. test message, not error
   at System.Environment.FailFast(System.String)
   at Program.<Main>$(System.String[])
Yyh
  • 103
  • 7