How Thread-Safe is NLog?
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");
}
}
}
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();
...