Logging from multiple processes with nLog missing logs and inconsistent archives

3

I have a process that runs on a windows server from multiple users on multiple sessions (could be as many as 50 concurrent users), I would like to:

  1. Log from all processes to a single log file
  2. limit the size of the logs to 1.5MB (for the purposes of our test)
  3. have acceptable performance from the logger

So I thought I'd give nLog a try:

<?xml version="1.0" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
            xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"    
        internalLogFile="file.txt">
        <targets async="false">
          <target name="regFile" xsi:type="File"
                  layout="${longdate} [${windows-identity}][${processid}]${threadname} ${uppercase:${level}} ${callsite} - ${message}${onexception:${newline}${exception:format=tostring}}" 
                  fileName="${basedir}/logs/test.log" 
                  archiveFileName="${basedir}/logs/test.{#####}.log"
                  archiveAboveSize="102400"
                  archiveNumbering="Rolling"
                  maxArchiveFiles="14"
                  concurrentWrites="true"
                  keepFileOpen="true"               
                  autoFlush="true"                                      
                          />
        </targets>
        <rules>
                <logger name="*" minlevel="Trace" writeTo="regFile" />
        </rules>
</nlog>

I also wrote a small tester:

class Program
    {
        private static Logger m_log = LogManager.GetCurrentClassLogger();

        static void Main(string[] args)
        {
            // Load logger configuration
            var assemblyLocation = Assembly.GetExecutingAssembly().Location;
            var assemblyDirectory = Path.GetDirectoryName(Assembly.GetExecutingAssembly().Location);

            if (assemblyDirectory != null)
            {
                var logConfig = new FileInfo(Path.Combine(assemblyDirectory, "nlogConfig.xml"));
                NLog.LogManager.Configuration = new NLog.Config.XmlLoggingConfiguration(logConfig.FullName, true);
            }
            if (args.Length == 1)
            {
                var sw = Stopwatch.StartNew();
                var size = Int32.Parse(args[0]);
                m_log.Info("Will launch {0} process and wait for them to come back...",size);                               
                var handles = new WaitHandle[size];  
                for (int i = 0; i < size; i++)
                {
                    var p = Process.Start(Assembly.GetExecutingAssembly().Location);
                    var processHandle = OpenProcess(
                            ProcessAccessFlags.Synchronize, false, p.Id);
                    if (processHandle != IntPtr.Zero)
                    handles[i] = new ManualResetEvent(false)
                    {
                        SafeWaitHandle = new SafeWaitHandle(processHandle, false)
                    };
                    m_log.Fatal("Started pid={0}.",p.Id);
                }

                m_log.Info("Created the processes, now wait.");
                WaitHandle.WaitAll(handles);
                sw.Stop();
                Thread.Sleep(100);
                m_log.Info("Done, took {0}.",sw.ElapsedMilliseconds);
            }
            else
            {
                m_log.Info("Running for {0} * {1}",1000,m_log.ToString());
                for (int i = 0; i < 1000; i++)
                {
                    m_log.Error("Hello nlog {0}", i);
                }              
            }           
        }
        #region Native API

        [Flags]
        enum ProcessAccessFlags
        {
            All = 0x001F0FFF,
            Terminate = 0x00000001,
            CreateThread = 0x00000002,
            VMOperation = 0x00000008,
            VMRead = 0x00000010,
            VMWrite = 0x00000020,
            DupHandle = 0x00000040,
            SetInformation = 0x00000200,
            QueryInformation = 0x00000400,
            Synchronize = 0x00100000
        }

        [DllImport("kernel32.dll", SetLastError = true)]
        private static extern IntPtr OpenProcess(ProcessAccessFlags dwDesiredAccess, bool bInheritHandle, int dwProcessId);
        #endregion
    }

Runs great, as long as I don't need to archive... Running my tester as such: "LoggerTester.exe 10" I get

  1. Less then 10,000 ERROR messages (each one should write 1000 "hello nlog in ERROR)
  2. It seems that sometimes 2 loggers rolled the file, so that there are some logs that are smaller the 100kb in the middle.

Maybe I'm asking to much and I must use some kind of Memory logger pattern (with 1 logger to actually manager the files), but I'm really hoping against that.

Couldn't find any reference to this anywhere, so I figured I try my luck here... Thanks.

c#
logging
nlog
asked on Stack Overflow Apr 16, 2014 by user1730969 • edited Apr 16, 2014 by user1730969

2 Answers

0

I think you are going to have trouble logging to a single file from multiple processes. I would suggest trying some other targets:

  1. DatabaseTarget
  2. LogReceiverwebServiceTarget (NLog also has a LogReceiverService implementation to go along with the target).
  3. WebServiceTarget

I have had success using the DatabaseTarget in the past.

I don't have experience with the other targets, but I did implement a LoggingService once. It was very similar to the LogReceiverWebServiceTarget. It was a WCF service that implemented a logging interface. We had a corresponding Target that could be configured to communicate with the logging service endpoint. We also implemented some caching and flushing so that we sent blocks of messages rather than making a service call for every message.

Good luck!

answered on Stack Overflow Apr 16, 2014 by wageoghe
0

NLog have now implemented several improvements to the concurrent archive logic:

This allows better coordination between concurrent processes when doing the archive operation. Of course the coordination/synchronization still has a performance cost.

Instead of having multiple concurrent processes trying rename/move the same static filename, then it is recommended with NLog 4.5 (and newer) to include ${shortdate} in filename. This reduces the chance of getting into a fight on day-roll:

     <target name="regFile" xsi:type="File"
           fileName="${basedir}/logs/test.${shortdate}.log" 
           archiveAboveSize="102400"
           maxArchiveFiles="14"
           concurrentWrites="true"
           keepFileOpen="true" />
answered on Stack Overflow Apr 4, 2020 by Rolf Kristensen • edited Apr 4, 2020 by Rolf Kristensen

User contributions licensed under CC BY-SA 3.0