c# - How Thread-Safe is NLog?

Question

Well,

I have waited for days before deciding to post this issue, as I was not sure how to state this, resutling into a long detailed post. However, I think it is relevant to ask for the community's help at this point.

Basically, I tried to use NLog to configure loggers for hundreds of threads. I thought this would be very straightforward, But I got this exception after few tens of seconds : "InvalidOperationException : Collection was modified; enumeration operation may not execute"

Here is the code.

//Launches threads that initiate loggers
class ThreadManager
{
    //(...)
    for (int i = 0; i<500; i++)
    {
        myWorker wk = new myWorker();
        wk.RunWorkerAsync();
    }

    internal class myWorker : : BackgroundWorker
    {             
       protected override void OnDoWork(DoWorkEventArgs e)
       {              
           // "Logging" is Not static - Just to eliminate this possibility 
           // as an error culprit
           Logging L = new Logging(); 
           //myRandomID is a random 12 characters sequence
           //iLog Method is detailed below
          Logger log = L.iLog(myRandomID);
          base.OnDoWork(e);
       }
    }
}

public class Logging
{   
        //ALL THis METHOD IS VERY BASIC NLOG SETTING - JUST FOR THE RECORD
        public Logger iLog(string loggerID)
        {
        LoggingConfiguration config;
        Logger logger;
        FileTarget FileTarget;            
        LoggingRule Rule; 

        FileTarget = new FileTarget();
        FileTarget.DeleteOldFileOnStartup = false;
        FileTarget.FileName =  "X:" + loggerID + ".log";

        AsyncTargetWrapper asyncWrapper = new AsyncTargetWrapper();
        asyncWrapper.QueueLimit = 5000;
        asyncWrapper.OverflowAction = AsyncTargetWrapperOverflowAction.Discard;
        asyncWrapper.WrappedTarget = FileTarget;

        //config = new LoggingConfiguration(); //Tried to Fool NLog by this trick - bad idea as the LogManager need to keep track of all config content (which seems to cause my problem;               
        config = LogManager.Configuration;                
        config.AddTarget("File", asyncWrapper);                
        Rule = new LoggingRule(loggerID, LogLevel.Info, FileTarget);

        lock (LogManager.Configuration.LoggingRules)
            config.LoggingRules.Add(Rule);                

        LogManager.Configuration = config;
        logger = LogManager.GetLogger(loggerID);

        return logger;
    }
}   

So I did my job an rather than just posting my question here and having a family-quality-time, I spent the week-end digging on that (Lucky Boy ! ) I downloaded the latest stable release of NLOG 2.0 and included it in my project. I was able to trace the exact place where it blowed :

in LogFactory.cs :

    internal void GetTargetsByLevelForLogger(string name, IList<LoggingRule> rules, TargetWithFilterChain[] targetsByLevel, TargetWithFilterChain[] lastTargetsByLevel)
    {
        //lock (rules)//<--Adding this does not fix it
            foreach (LoggingRule rule in rules)//<-- BLOWS HERE
            {
            }
     }

in LoggingConfiguration.cs :

internal void FlushAllTargets(AsyncContinuation asyncContinuation)
    {            
        var uniqueTargets = new List<Target>();
        //lock (LoggingRules)//<--Adding this does not fix it
        foreach (var rule in this.LoggingRules)//<-- BLOWS HERE
        {
        }
     }

The problem according to me
So, based on my understanding, what happens is that the LogManager gets mixed up as there are calls to config.LoggingRules.Add(Rule) from different threads while GetTargetsByLevelForLogger and FlushAllTargets are being called. I tried to screw the foreach and replace it by a for loop but the logger turned rogue (skipping many log files creation)

SOoooo FINALLY
It is written everywhere that NLOG is thread-safe, but I've come through a few posts that dig things further and claim that this depends on the utilization scenario. What about my case ? I have to create thousands of loggers (not all at the same time, but still at a very high pace).

The workaround I have found is to create all loggers in the SAME MASTER THREAD; this is REALLY unconvenient, as I create all my app loggers at the start of the app (sort of a Logger Pool). And though it works sweet, it is just NOT an acceptable design.

So you know it all Folks. Please help a coder see his family again.

Answer 1

I don't really have an answer to your problem, but I do have some observations and some questions:

According to your code, it looks like you want to create a logger per thread and you want to have that logger log to a file named for some passed-in id value. So, the logger whose id is "abc" would log to "x:abc.log", "def" would log to "x:def.log", and so on. I suspect that you can do this via NLog configuration rather than programmatically. I don't know if it would work any better, or if NLog would have the same issue as you are having.

My first impression is that you are doing a lot of work: creating a file target per thread, creating a new rule per thread, getting a new logger instance, etc, that you might not need to do to accomplish what it appears that you want to accomplish.

I know that NLog allows the output file to be named dynamically, based on at least some of the NLog LayoutRenderers. For example, I know that this works:

fileName="${level}.log"

and will give you filenames like this:

Trace.log
Debug.log
Info.log
Warn.log
Error.log
Fatal.log

So, for example, it seems that you could use a pattern like this to create output file(s) based on thread id:

fileName="${threadid}.log"

And if you ended up having threads 101 and 102, then you would have two log files: 101.log and 102.log.

In your case, you want to name the file based on your own id. You could store the id in the MappedDiagnosticContext (which is a dictionary that allows you to store thread-local name-value pairs) and then reference that in your pattern.

Your pattern for your filename would look something like this:

fileName="${mdc:myid}.log"

So, in your code you might do this:

         public class ThreadManager
         {
           //Get one logger per type.
           private static readonly Logger logger = LogManager.GetCurrentClassLogger();

           protected override void OnDoWork(DoWorkEventArgs e)
           {
             // Set the desired id into the thread context
             NLog.MappedDiagnosticsContext.Set("myid", myRandomID);

             logger.Info("Hello from thread {0}, myid {1}", Thread.CurrentThread.ManagedThreadId, myRandomID);
             base.OnDoWork(e);  

             //Clear out the random id when the thread work is finished.
             NLog.MappedDiagnosticsContext.Remove("myid");
           }
         }

Something like this should allow your ThreadManager class to have a single logger named "ThreadManager". Each time it logs a message, it will log the formatted string in the Info call. If the logger is configured to log to the File target (in the config file make a rule that sends "*.ThreadManager" to a File target whose filename layout is something like this:

fileName="${basedir}/${mdc:myid}.log"

At the time a message is logged, NLog will determine what the filename should be, based on the value of the fileName layout (i.e. it applies the formatting tokens at log time). If the file exists, then the message is written to it. If the file does not exist yet, the file is created and the message is logged to it.

If each thread has a random id like "aaaaaaaaaaaa", "aaaaaaaaaaab", "aaaaaaaaaaac", then you should get log files like this:

aaaaaaaaaaaa.log
aaaaaaaaaaab.log
aaaaaaaaaaac.log

And so on.

If you can do it this way, then your life should be simpler as you do not have to all of that programmatic configuration of NLog (creating rules and file targets). And you can let NLog worry about creating the output file names.

I don't know for sure that this will work any better than what you were doing. Or, even if it does, you might really need to what you are doing in your bigger picture. It should be easy enough to test to see that it even works (i.e. that you can name your output file based a value in the MappedDiagnosticContext). If it works for that, then you can try it for your case where you are creating thousands of threads.

UPDATE:

Here is some sample code:

Using this program:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;

using NLog;
using System.Threading;
using System.Threading.Tasks;

namespace NLogMultiFileTest
{
  class Program
  {
    public static Logger logger = LogManager.GetCurrentClassLogger();

    static void Main(string[] args)
    {

      int totalThreads = 50;
      TaskCreationOptions tco = TaskCreationOptions.None;
      Task task = null;

      logger.Info("Enter Main");

      Task[] allTasks = new Task[totalThreads];
      for (int i = 0; i < totalThreads; i++)
      {
        int ii = i;
        task = Task.Factory.StartNew(() =>
        {
          MDC.Set("id", "_" + ii.ToString() + "_");
          logger.Info("Enter delegate.  i = {0}", ii);
          logger.Info("Hello! from delegate.  i = {0}", ii);
          logger.Info("Exit delegate.  i = {0}", ii);
          MDC.Remove("id");
        });

        allTasks[i] = task;
      }

      logger.Info("Wait on tasks");

      Task.WaitAll(allTasks);

      logger.Info("Tasks finished");

      logger.Info("Exit Main");
    }
  }
}

And this NLog.config file:

<?xml version="1.0" encoding="utf-8" ?>
<!-- 
  This file needs to be put in the application directory. Make sure to set 
  'Copy to Output Directory' option in Visual Studio.
  -->
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">

    <targets>
        <target name="file" xsi:type="File" layout="${longdate} | ${processid} | ${threadid} | ${logger} | ${level} | id=${mdc:id} | ${message}" fileName="${basedir}/log_${mdc:item=id}.txt" />
    </targets>

    <rules>
        <logger name="*" minlevel="Debug" writeTo="file" />
    </rules>
</nlog>

I am able to get one log file for each execution of the delegate. The log file is named for the "id" stored in the MDC (MappedDiagnosticContext).

So, when I run the sample program, I get 50 log files, each of which has three lines in it "Enter...", "Hello...", "Exit...". Each file is named log__X_.txt where X is the value of the captured counter (ii), so I have log_0.txt, log_1.txt, log_1.txt, etc, log_49.txt. Each log file contains only those log messages pertaining to one execution of the delegate.

Is this similar to what you want to do? My sample program uses Tasks rather than threads because I had already written it some time ago. I think that the technique should adapt to what you are doing easily enough.

You could also do it this way (getting a new logger for each excecution of the delegate), using the same NLog.config file:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;

using NLog;
using System.Threading;
using System.Threading.Tasks;

namespace NLogMultiFileTest
{
  class Program
  {
    public static Logger logger = LogManager.GetCurrentClassLogger();

    static void Main(string[] args)
    {

      int totalThreads = 50;
      TaskCreationOptions tco = TaskCreationOptions.None;
      Task task = null;

      logger.Info("Enter Main");

      Task[] allTasks = new Task[totalThreads];
      for (int i = 0; i < totalThreads; i++)
      {
        int ii = i;
        task = Task.Factory.StartNew(() =>
        {
          Logger innerLogger = LogManager.GetLogger(ii.ToString());
          MDC.Set("id", "_" + ii.ToString() + "_");
          innerLogger.Info("Enter delegate.  i = {0}", ii);
          innerLogger.Info("Hello! from delegate.  i = {0}", ii);
          innerLogger.Info("Exit delegate.  i = {0}", ii);
          MDC.Remove("id");
        });

        allTasks[i] = task;
      }

      logger.Info("Wait on tasks");

      Task.WaitAll(allTasks);

      logger.Info("Tasks finished");

      logger.Info("Exit Main");
    }
  }
}