Async Logger. Can I lose/delay log entries?

问题:

I'm implementing my own logging framework. Following is my BaseLogger which receives the log entries and push it to the actual Logger which implements the abstract Log method.

I use the C# TPL for logging in an Async manner. I use Threads instead of TPL. (TPL task doesn't hold a real thread. So if all threads of the application end, tasks will stop as well, which will cause all 'waiting' log entries to be lost.)

public abstract class BaseLogger
{
    // ... Omitted properties constructor .etc. ... //

public virtual void AddLogEntry(LogEntry entry)
{
    if (!AsyncSupported)
    {
        // the underlying logger doesn't support Async.
        // Simply call the log method and return.
        Log(entry);
        return;
    }
    // Logger supports Async.
    LogAsync(entry);
}

private void LogAsync(LogEntry entry)
{
    lock (LogQueueSyncRoot) // Make sure we ave a lock before accessing the queue.
    {
        LogQueue.Enqueue(entry);
    }

    if (LogThread == null || LogThread.ThreadState == ThreadState.Stopped)
    { // either the thread is completed, or this is the first time we're logging to this logger.
        LogTask = new  new Thread(new ThreadStart(() =>
        {
            while (true)
            {
                LogEntry logEntry;
                lock (LogQueueSyncRoot)
                {
                    if (LogQueue.Count > 0)
                    {
                        logEntry = LogQueue.Dequeue();
                    }
                    else
                    {
                        break; 
                        // is it possible for a message to be added,
                        // right after the break and I leanve the lock {} but 
                        // before I exit the loop and task gets 'completed' ??
                    }
                }
                Log(logEntry);
             }
        }));
        LogThread.Start();
    }
}

// Actual logger implimentations will impliment this method.
protected abstract void Log(LogEntry entry);
}

Note that AddLogEntry can be called from multiple threads at the same time.

My question is, is it possible for this implementation to lose log entries ? I'm worried that, is it possible to add a log entry to the queue, right after my thread exists the loop with the break statement and exits the lock block, and which is in the else clause, and the thread is still in the 'Running' state.

I do realize that, because I'm using a queue, even if I miss an entry, the next request to log, will push the missed entry as well. But this is not acceptable, specially if this happens for the last log entry of the application.

Also, please let me know whether and how I can implement the same, but using the new C# 5.0 async and await keywords with a cleaner code. I don't mind requiring .NET 4.5.

Thanks in Advance.

回答1:

I see two race conditions off the top of my head:

1. You can spin up more than one Thread if multiple threads call AddLogEntry. This won't cause lost events but is inefficient.
2. Yes, an event can be queued while the Thread is exiting, and in that case it would be "lost".

Also, there's a serious performance issue here: unless you're logging constantly (thousands of times a second), you're going to be spinning up a new Thread for each log entry. That will get expensive quickly.

Like James, I agree that you should use an established logging library. Logging is not as trivial as it seems, and there are already many solutions.

That said, if you want a nice .NET 4.5-based approach, it's pretty easy:

public abstract class BaseLogger
{
  private readonly ActionBlock<LogEntry> block;

  protected BaseLogger(int maxDegreeOfParallelism = 1)
  {
    block = new ActionBlock<LogEntry>(
        entry =>
        {
          Log(entry);
        },
        new ExecutionDataflowBlockOptions
        {
          MaxDegreeOfParallelism = maxDegreeOfParallelism,
        });
  }

  public virtual void AddLogEntry(LogEntry entry)
  {
    block.Post(entry);
  }

  protected abstract void Log(LogEntry entry);
}

回答2:

While you could likely get this to work, in my experience, I'd recommend, if possible, use an existing logging framework :) For instance, there are various options for async logging/appenders with log4net, such as this async appender wrapper thingy.

Otherwise, IMHO since you're going to be blocking a threadpool thread during your logging operation anyway, I would instead just start a dedicated thread for your logging. You seem to be kind-of going for that approach already, just via Task so that you'd not hold a threadpool thread when nothing is logging. However, the simplification in implementation I think benefits just having the dedicated thread.

Once you have a dedicated logging thread, you then only need have an intermediate ConcurrentQueue. At that point, your log method just adds to the queue and your dedicated logging thread just does that while loop you already have. You can wrap with BlockingCollection if you need blocking/bounded behavior.

By having the dedicated thread as the only thing that writes, it eliminates any possibility of having multiple threads/tasks pulling off queue entries and trying to write log entries at the same time (painful race condition). Since the log method is now just adding to a collection, it doesn't need to be async and you don't need to deal with the TPL at all, making it simpler and easier to reason about (and hopefully in the category of 'obviously correct' or thereabouts :)

This 'dedicated logging thread' approach is what I believe the log4net appender I linked to does as well, FWIW, in case that helps serve as an example.

回答3:

Regarding the loosing waiting messages on app crush because of unhandled exception, I've bound a handler to the event AppDomain.CurrentDomain.DomainUnload. Goes like this:

protected ManualResetEvent flushing = new ManualResetEvent(true);
protected AsyncLogger()  // ctor of logger
{
    AppDomain.CurrentDomain.DomainUnload += CurrentDomain_DomainUnload;
}

protected void CurrentDomain_DomainUnload(object sender, EventArgs e)
{
    if (!IsEmpty)
    {
        flushing.WaitOne();
    }
}

Maybe not too clean, but works.