Writing to the same file from multiple processes may not function when archiving with concurrentWrites="true" and keepFileOpen="true" #1887

Closed
BertrandAreal opened this Issue Jan 5, 2017 · 6 comments

Projects

None yet

3 participants

@BertrandAreal
BertrandAreal commented Jan 5, 2017 edited

Type: Bug
NLog version: 4.4.1
Platform: .Net 4.5, Windows 8.1

Current NLog config

 <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" internalLogFile="C:\logs\log.txt" internalLogLevel="Trace">
    <targets>
      <target name="file"
              xsi:type="File"
              layout="${longdate} (${threadid}) ${level} [${logger}] ${message}"
              fileName="c:\logPath\logfile.log"
              archiveFileName="c:\logPath\logfile{##}.log"
              archiveAboveSize="12000"
              maxArchiveFiles="300"
              concurrentWrites="true"
              keepFileOpen="true"
              encoding="iso-8859-2" />
      <target name="Console" type="console" />
    </targets>
    <rules>
      <logger name="*" minlevel="Debug" writeTo="file" />
    </rules>
  </nlog>

Current result :
Nlog generates multiples archives with the requested size but sometimes an archive contains only few lines of logs from only one process.

Expected result:
I expect that all archives will contain logs from all the running processes and will have the size defined into the Nlog configuration.

Internal logs :
internalLog.txt

Tested in version 4.4.1 and 4.4.0

Repeatability:
This bug occures only somethimes (50% on my computer with the given test) but you can increase the rate of appearance by increasing the number of processes and number of written lines.

Test used to reproduice the bug :

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Linq;
using System.Reflection;
using System.Text;
using System.Threading;
using System.Threading.Tasks;
using NLog;

namespace TestNlog
{
    static class Program
    {
        private static readonly ILogger Logger = LogManager.GetCurrentClassLogger();
        static void Main(string[] args)
        {
            string processName;
            if (args.Length == 0)
            {
                processName = "0";
                for (int i = 1; i < 2; ++i)
                {
                    Process.Start(Assembly.GetEntryAssembly().Location, i.ToString());
                }
            }
            else
            {
                processName = args[0];
            }

            bool running = true;
            Console.CancelKeyPress += (sender, eventArgs) => running = false; // shutdown on Control-C
            int j = 0;
            while (running)
            {
                Logger.Debug("{0} - Happily Running Still {1}", processName, j);
                j++;
                Thread.Sleep(10);
            }
        }
    }
}
@snakefoot
Contributor
snakefoot commented Jan 5, 2017 edited

Think the archive mutex was broken with the introduction of WindowsMultiProcessFileAppender and with #1809. I have tried to repair it again with #1888 (Added tests with #1889)

@BertrandAreal
BertrandAreal commented Jan 9, 2017 edited
@304NotModified
Member
304NotModified commented Jan 9, 2017 edited

@snakefoot FYI

The errors from the internal log:

2 times: (Impossible de trouver le fichier => Unable to find file)

2017-01-09 09:27:20.1372 Warn Failed to archive file 'c:\logPath\logfile.log'. Exception: System.IO.FileNotFoundException: Impossible de trouver le fichier 'c:\logPath\logfile.log'.
Nom de fichier : 'c:\logPath\logfile.log'
   à System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
   à System.IO.File.InternalMove(String sourceFileName, String destFileName, Boolean checkHost)
   à NLog.Targets.FileTarget.ArchiveFile(String fileName, String archiveFileName)
   à NLog.Targets.FileTarget.ArchiveBySequence(String fileName, String pattern)
   à NLog.Targets.FileTarget.DoAutoArchive(String fileName, LogEventInfo eventInfo)
   à NLog.Targets.FileTarget.TryArchiveFile(String fileName, LogEventInfo ev, Int32 upcomingWrit

49 times:

The process can not access the 'c:\logPath\logfile.log' file because it is being used by another process.

2017-01-09 09:27:16.5126 Warn Failed to archive file 'c:\logPath\logfile.log'. Exception: System.IO.IOException: Le processus ne peut pas accéder au fichier 'c:\logPath\logfile.log', car il est en cours d'utilisation par un autre processus.
   à System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
   à System.IO.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean useRights, FileShare share, Int32 bufferSize, FileOptions options, SECURITY_ATTRIBUTES secAttrs, String msgPath, Boolean bFromProxy, Boolean useLongPath, Boolean checkHost)
   à System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share)
   à NLog.Targets.FileTarget.ArchiveFile(String fileName, String archiveFileName)
   à NLog.Targets.FileTarget.ArchiveBySequence(String fileName, String pattern)
   à NLog.Targets.FileTarget.DoAutoArchive(String fileName, LogEventInfo eventInfo)
   à NLog.Targets.FileTarget.TryArchiveFile(String fileName, LogEventInfo ev, Int32 upcomingWriteSize)
@snakefoot
Contributor
snakefoot commented Jan 9, 2017 edited

@304NotModified Both are issues caused by the archive mutex not working its magic for the WindowsMultiProcessFileAppender. Both processes attempts to perform the archive operation. Fixed with #1888.

@304NotModified
Member

Thanks! Will merge soon

@304NotModified 304NotModified added this to the 4.4.2 milestone Jan 11, 2017
@304NotModified
Member

fixed by #1888

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment