C# lock issues when writing to log

Question

I have a class that programmatically creates a log using the Nlog framework. I have several processes running and creating their logs at the same time. I added a lock to the constructor of the class, as before the two threads were attempting to create a file at the same time which resulted in some annoying bugs (like only creating one log).

This seems to have solved that problem. However now i have the same issue with writing to the log, and using a lock has not helped. Here is the class.

public class CwiLogger
    {
        private Logger _log;
        private static Object createLogLock = new Object();
        private static Object writeLogLock = new Object();
        public CwiLogger(string logPath, string logName, string className)
        {
            lock (createLogLock)
            {
                var config = new LoggingConfiguration();
                var fileTarget = new FileTarget();
                config.AddTarget("file", fileTarget);
                fileTarget.FileName = Path.Combine(logPath, logName);
                fileTarget.Layout = "${longdate}|${level:uppercase=true}|${logger}|${message}";
                var rule = new LoggingRule("*", LogLevel.Debug, fileTarget);
                config.LoggingRules.Add(rule);

                LogManager.Configuration = config;

                this._log = LogManager.GetLogger(className);
            }
        }

        public void AddToLog(string logText, LogLevel level = null)
        {
            lock (writeLogLock)
            {
                level = level ?? LogLevel.Info;
                this._log.Log(level, logText + "\n");
            }
        }
    }

In my client code i run two threads each running a process that looks like this:

var log = new CwiLogger(@"C:\Users\jma\Documents\ProgrammingJunk\logTest", "Log2.txt", "Log2");
for (int i = 0; i < 100; i++)
{
    log.AddToLog("Log2 " + i);
}

only i use log1 for one and log2 for the other.

in my output. One of the 2 logs always sucessfully counts to 99, while the other gets 4-5 in and then has no other output.

Answer 1

This is because the lock() syntax compiles to Monitor.Enter and Monitor.Leave - Monitor.Enter will put the current thread to sleep if it cannot lock the object, the thread holding the lock and will then awake all waiting threads when it calls Monitor.Leave.

Your problem is that your second thread has to go through the additional time of waking up before it can attempt to lock the object, by which time the thread that just released the lock has already locked it again.

If you expect your routine to lock only for a very short time (too short to want to sleep waiting threads) use a SpinLock instead. This class gets each thread to keep attempting the lock in a loop until it succeeds rather than sleeping. It means it uses more CPU (and thus more battery power on a laptop), which is why the code you lock must run for very small amounts of time.

Answer 2

Maybe something like this:

public class CwiLogger
{
    private static LoggingConfiguration _logConfig = new LoggingConfiguration();
    private static Object createLogLock = new Object();
    private Logger _log;

    public CwiLogger(string logPath, string logName, string className)
    {
            lock (createLogLock)
            {
                var fileTarget = _logConfig.FindTargetByName(logName);
                if (fileTarget == null)
                {
                    var fileTarget = new FileTarget(logName);
                    fileTarget.FileName = Path.Combine(logPath, logName);
                    fileTarget.Layout = "${longdate}|${level:uppercase=true}|${logger}|${message}";
                    _logConfig.AddTarget(fileTarget);
                    var rule = new LoggingRule(className, LogLevel.Debug, fileTarget) { Final = true };
                    _logConfig.LoggingRules.Add(rule);
                    LogManager.Configuration = _logConfig;
                }
            }
        this._log = LogManager.GetLogger(className);
    }

    public void AddToLog(string logText, LogLevel level = null)
    {
        level = level ?? LogLevel.Info;
        this._log.Log(level, logText + "\n");
    }
}

Or maybe steal some ideas from here: https://github.com/NLog/NLog/issues/1998