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.

Solution 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");
    }
  }
}

Solution 2

I don't know NLog, but from what I can see from the pieces above and the API docs(http://nlog-project.org/help/), there is only one static configuration. So if you want to use this method to add rules to the config only when the logger is created (each from a different thread), you're editing the same configuration object. As far as I can see in the NLog docs, there is no way to use a separate configuration for each logger, so that is why you need all the rules.

The best way to add the rules would be to add the rules before you start the async workers, but I'm going to assume that that is not what you want.

It would also be possible to just use one logger for all the workers. But I'm going to assume that you need every worker in a separate file.

If each thread is creating their own logger and adding their own rules to the configuration, you'll have to put a lock around it. Note that even with you synchronizing your code, there is still a chance that some other code is enumerating over the rules while you are changing them. As you show, NLog does not do locking around these bits of code. So I presume any thread-safe claims are for the actual log-writing methods only.

I'm not sure what your existing lock does, but I don't think it is not doing what you intended. So, change

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

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

return logger;

to

...
lock(privateConfigLock){
    LogManager.Configuration.LoggingRules.Add(Rule);                

    logger = LogManager.GetLogger(loggerID);
}
return logger;

Note that it is considered a best practice to only lock objects that you 'own', i.e. that are private to your class. This prevents that some class in some other code (that does not adhere to the best practice) locks on the same code that may create a deadlock. So we should define privateConfigLock as private to your class. We should also make it static, so that every thread sees the same object reference, like so:

public class Logging{
    // object used to synchronize the addition of config rules and logger creation
    private static readonly object privateConfigLock = new object();
...

Solution 3

This is an older question, but as current owner of NLog I have the following insights:

• Creating a logger is thread-safe
• Writing log messages is thread-safe
• Usage of the context classes and renderers are (GDC, MDC etc) thread-safe
• Adding new targets + rules at runtime is thread-safe (When using LoggingConfiguration.AddRule + ReconfigExistingLoggers)
• Performing Reload of LoggingConfiguration will cause LogEvents from active loggers to be dropped until reload has completed.
• Changing values of existing rules and targets at run-time isn't thread-safe!

You should avoid changing the values of existing items at runtime. Instead one should use the context renderers (${event-properties}, ${GDC}, ${MDLC}, etc.)

Comments

[Mehdi LAMRANI]

Excuse me but I may disagree. Read this : albahari.com/threading/part2.aspx#_Locking

[Mehdi LAMRANI]

Besides, Theorectically I do not even have to put locks as Nlog states to be thread-safe

[Buh Buh]

I don't understand. I read that link and it uses static readonly object _locker = new object(); too. What do you disagree about?

[Andy]

@Mika: Did you write that? If you did, please remove the parts where it says it's ok to lock on this or a Type instance. That's an awful choice to lock on, as you don't know that the calling code hasn't locked on those things either, and you'll create deadlocks. You should NEVER lock on any instance visible outside of the class doing the locking.

[Mehdi LAMRANI]

My Bad My Bad sorry a lot. I did not understand the purpose of Buh Buh's post. I Apologize I got it totally wrong in the first place. I'll fix that later.

[Mehdi LAMRANI]

PERFECT Answer. Thanks a lot. Especially for taking time to read the NLog API as you did not know NLog. Very kind of you. I'll mark this as an answer if it works well when I give it a shot tomorrow morning.

[Mehdi LAMRANI]

@wageoghe : My Friend, your post goes far beyon what I could dream of. It was exactly what I was looking for But I discovered NLog just a few days ago and had to implement log management very quickly. I looked for a way to do that but I did not find it easily so I kept doing it the basic dirty way. I'll take serious time tomorrow morning to give this a decent shot and see how it turns out. If you know any way to give you more votes or offer you points or whatever let me know, because I am about to be very grateful to you.

[wageoghe]

@Mika Jacobi - Glad to help! I just hope it works for you. I haven't tried it myself, so I don't know for sure that it will do exactly what you want. You might find some of the NLog tips here useful as well: stackoverflow.com/questions/4091606/…

[Mehdi LAMRANI]

I followed your instructions. The dynamic ID trick works but I can't get more than One logger writing (i.e, the one corresponding to the first thread that is created). Others that follow do not result in writing into a log file). Logger should not be static I think, but even removing the static reference didn't do... (By the way I've edited your post to bring minor corrections as it did not compile as is.)

[wageoghe]

@Mika Jacobi - See my latest edit and see if it helps you. I demonstrate that it is possible to create one log file for each execution of the delegate function, with the file named based on a value stored in the MappedDiagnosticContext (MDC).

[Mehdi LAMRANI]

@wageoghe : There is a limitation to your sample code. It took me time to identify it with precision : If your main logger happens to write between the MDC Set and MDC remove of tasks, logs get mixed up (i.e If your tasks take time to run, and your main thread logs stuff, these logs are written into the lastly created log file.) Example code : innerLogger.Info("Enter delegate. i = {0}", ii); logger.Info("PIKABOO"); innerLogger.Info("Hello! from delegate. i = {0}", ii);

[wageoghe]

@Mika Jacobi - Have you tried my second sample where there is a logger for the class and a separate logger for each execution of the delegate? You can configure the fileName pattern like this: fileName="${logger}.log" and each logger should then write its own log file. In your example "PIKABOO" would be written to the main logger's file.

[Mehdi LAMRANI]

@wageoghe: Your last comment was hidden, I was crying hot tears to fix this. fileName="${logger}.log worked like a charm I was just going NUTS with the MDC! I didnt succeed in understanding what was exactly the problem with "ID"s sync (makes me frustrated because a sample project based on your 2nd example does not show this weird log interlacing phenomenon). Oh well. Anyway, As long as the I give the logger the name of my ID this trick circumvents the MCD sync problem. So, once again, please accept my deep and sincere gratitude for your precious help. I really do appreciate and THANKS a lot

[Mehdi LAMRANI]

@wageoghe:I'll take time to explore NLog Documentation more deeply as it sounds really versatile, powerful, and full of possibilities/options, beyond basic use-cases (though there are not much advanced code samples/a bit complex use cases out there, mostly getting started examples). Your proposition is really useful and clean as it saved a bunch of code calls to the whole config stuff on and on, and it basically solved my first concurrency problem, as I do not have to declare as much Targets as Threads. SO i'll mark this as an answer. Cheers !

[Mehdi LAMRANI]

Thanx, the right usage of lock worked pretty well. Your proposition is the right answer from the general .Net point of view. However, @wageoghe's proposition seems to be more NLog-compliant as I do not have to declare one target per logger anymore, by using a "wildcard" instead, which solves the concurrency problem I had in the start. Thanks for your help.

[xr280xr]

We commonly declare a static logger at the top of our classes for use throughout the class and this approach has been used in some web apps. Is using a static Logger across many threads to write logs safe?

[Julian]

Yes it is. It's even the recommended approach :). See github.com/nlog/nlog/wiki/…

[uriDium]

@Julian sorry to piggyback off this issue. We have a requirement where we do have hundreds of loggers at runtime. (We can't use config because the logger are dynamic). Also we need to be able to change a logger at runtime's loglevel. The logs we create can be extremely verbose so we leave them on info. If something is going wrong we want to be able to change a logger to DEBUG dynamically so we can troubleshoot and then back to INFO. What is the suggested way of doing this?

[Julian]

Please create a new question StackOverflow :) I Could answer that, but not in a comment