BlockingCollection file logging - Thread of a BlockingCollection task automatically aborted

Question

Is BlockingCollection thread safe in every situation ?

I am trying to use a BlockingCollection to implement a log system without taking too much of the Main Thread resources. The idea is that it costs only a BlockingCollection.Add() call for the Main Thread, and one waiting task do the writing job.

The BlockingCollection Class is supposed to take care of the tasks competition with its queue, so that every Add() will bring about a job successively.

Declaring the BlockingCollection object:

private static BlockingCollection<string> queueLogMinimal = new BlockingCollection<string>();

And the other vars:

internal static string AllLogFileName = Path.Combine(Environment.GetFolderPath(Environment.SpecialFolder.Desktop), "Log.log");
private static Object logLocker = new Object();

Initiating the Task which will be always listening, in the constructor :

    public LogManager()
    {
        Task.Factory.StartNew(() =>
        {
            Thread.CurrentThread.Name = "Logger";
            foreach (string message in queueLogMinimal.GetConsumingEnumerable())
            {
                WriteLogMinimal(message);
            }
        });
    }

A minimal function which is called to manage the logging :

    public static void LogMinimal(string message)
    {
        queueLogMinimal.Add(message);
    }

A lock has been necessary, to ensure the Main Thread is not changing the file configuration while the Logger Thread is writing.

The function called by the Task at each BlockingCollection dequeue :

    public static void WriteLogMinimal(string message)
    {
        lock (logLocker)
        {
            try
            {
                File.AppendAllText(AllLogFileName, DateTime.Now.ToString() + " - " +message +Environment.NewLine);
            }
            catch (Exception e)
            {
                Debug.WriteLine("EXCEPTION while loging the message : ");
            }
        }
    }

The thing is that when testing the functioning of that system by doing logs in a row. If I test, let's say 40 logs in a row:

[TestClass]
public class UnitTest
{
    [TestMethod]
    public void TestLogs()
    {
        LogManager lm = new LogManager();
        int a = 0;
        LogManager.LogMinimal(a++.ToString());
        LogManager.LogMinimal(a++.ToString());
        LogManager.LogMinimal(a++.ToString());
        LogManager.LogMinimal(a++.ToString());
    }
}

After 10 to 30 logs, it stops logging because that happens in LaunchLogTask(), in the foreach browsing the BlockingCollection elements with GetConsumingEnumerable() :

Thread was being aborted.

StackTrace :

at System.Threading.Monitor.ObjWait(Boolean exitContext, Int32 millisecondsTimeout, Object obj)\r\n
at System.Threading.Monitor.Wait(Object obj, Int32 millisecondsTimeout, Boolean exitContext)\r\n
at System.Threading.SemaphoreSlim.WaitUntilCountOrTimeout(Int32 millisecondsTimeout, UInt32 startTime, CancellationToken cancellationToken)\r\n at System.Threading.SemaphoreSlim.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)\r\n
at System.Collections.Concurrent.BlockingCollection`1.TryTakeWithNoTimeValidation(T& item, Int32 millisecondsTimeout, CancellationToken cancellationToken, CancellationTokenSource combinedTokenSource)\r\n
at System.Collections.Concurrent.BlockingCollection`1.d__68.MoveNext()\r\n
at RenaultTrucks.Common.Managers.LogManager.<>c.<.ctor>b__14_1() in C:\Source\Diagnostica\GLB-DIAGNOSTICA\NewDiagnostica\Source\Common\Managers\LogManager.cs:line 61" string

And if I test it less intensively while addingsleep time :

[TestClass]
public class UnitTest
{
    [TestMethod]
    public void TestLogs()
    {
        LogManager lm = new LogManager();
        int a = 0;
        LogManager.LogMinimal(a++.ToString());
        System.Threading.Thread.Sleep(100);
        LogManager.LogMinimal(a++.ToString());
        System.Threading.Thread.Sleep(100);
        LogManager.LogMinimal(a++.ToString());
        System.Threading.Thread.Sleep(100);
        LogManager.LogMinimal(a++.ToString());
    }
}

It logs everything! (without thread abortion).

Is it possible that the queue is managed differently according to the queuing pace, or that that pace can be "too quick" ?

Answer 1

Problem here is you are not waiting for all log messages to become processed before exiting your unit test.

Task.Factory.StartNew (which usage is discouraged by the way) runs your code on background thread pool thread. When your process is about to exit - all background threads are aborted, that's the exception you observe.

First, it's not good to use thread pool threads for such long running operations. Better start new background thread for that, and save in a variable, since we will need it later:

private readonly Thread _consumerThread;
public LogManager() {
    new Thread(() => {
        Thread.CurrentThread.Name = "Logger";
        try {
            foreach (string message in queueLogMinimal.GetConsumingEnumerable()) {
                try {
                    LogMinimal(message);
                }
                catch (Exception ex) {
                    // do something, otherwise one failure to write a log
                    // will bring down your whole logging
                }
            }
        }
        catch (Exception ex) {
            // do something, don't let exceptions go unnoticed
        }
    }) {
        IsBackground = true
    }.Start();
}

Now, before exiting your process, you need to let all pending messages to be processed. Reasonable thing is to implement IDisposable, but that's not necessary, you just need some method which you call on logger to notify it should stop.

public void Dispose() {
    // first notify that no messages are expected any more
    // this will allow GetConsumerEnumerable to finish
    this.queueLogMinimal.CompleteAdding();
    // now wait for thread to finish with reasonable timeout
    // don't do this without timeout to prevent potential deadlocks
    bool finishedGracefully = _consumerThread.Join(TimeSpan.FromSeconds(5));
    if (!finishedGracefully) {
        // thread did not finish during timeout,
        // do something like throwing exception
    }
}

Now tell your logger to stop before exiting:

[TestMethod]
public void TestLogs()
{
    LogManager lm = new LogManager();
    int a = 0;
    lm.LogMinimal(a++.ToString());
    // ...
    lm.Dispose();
}

Final note: don't implement logger yourself, just use existing solutions which already did all that for you, such as log4net.

Answer 2

I think the picture is little different here than what you think it is.

Basically your threads are not waiting to logging, notice the thread count it will keep increasing in your case.

Reason: Task.Factory.StartNew

This is making all your new thread to process the blockingcollection.GetConsumingEnumerables..

Your case of not logging is thread exhaustion. Please verify.

As suggested don't use StartNew, instead use thread class and run it.

thanks for reading