Type:
NLog version: 4.4.0
Platform: .Net 4.5
Current NLog config (xml or C#, if relevant)
var fileTarget = new FileTarget
{
FileName = Path.Combine(directoryPath, "${logger}_${date:format=yyyyMMdd}.txt"),
Layout = DefaultLayoutFormatter,
NetworkWrites = false,
KeepFileOpen = true,
ConcurrentWrites = true,
Name = name,
MaxArchiveFiles = 10,
ArchiveAboveSize = 1024 * 20, //1024*1024*10 - we reduce the log size before archiving to 20KB to reach the problematic condition quicker, with log size of 10MB the problem reproduces as well
ArchiveFileName = Path.Combine(directoryPath, "${logger}_{#}.txt"),
ArchiveDateFormat = "yyyyMMdd.HHmmss",
ArchiveNumbering = ArchiveNumberingMode.DateAndSequence
};
var fileWrapper = new BufferingTargetWrapper
{
WrappedTarget = fileTarget,
Name = name,
SlidingTimeout = true
};
LogManager.Configuration.AddTarget(name, fileWrapper);
var logFileLoggingRule = new LoggingRule("*", minLevel, fileTarget);
LogManager.Configuration.LoggingRules.Add(logFileLoggingRule);
Bug description:
We have a "host" application that spins up multiple child "runner" applications.
The "host" application can write to it's own single "host" log.
Multiple "Runner" application can write to a single "runners" log as well as write some diagnostic information in "host" log.
Therefore, for both "runner" and "host" logs there are multiple writers.
The configuration above reflects that.
- What is the current result?
At some point during the runtime of the application when archiving of "host" log happens, it gets stuck on "host" application side (at least) with the following message:
2016-12-18 21:15:36.4364 Info Deleting old archive D:\Temp\Logs\HOST_20161218.211223.0.txt.
2016-12-18 21:15:36.4364 Warn Failed to archive file 'D:\Temp\Logs\HOST_20161218.txt'. Exception: System.UnauthorizedAccessException: Access to the path 'D:\Temp\Logs\HOST_20161218.211223.0.txt' is denied.
at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
at System.IO.File.InternalDelete(String path, Boolean checkHost)
at System.IO.File.Delete(String path)
at NLog.Targets.FileTarget.EnsureArchiveCount(List`1 oldArchiveFileNames)
at NLog.Targets.FileTarget.ArchiveByDateAndSequence(String fileName, String pattern, LogEventInfo logEvent)
at NLog.Targets.FileTarget.DoAutoArchive(String fileName, LogEventInfo eventInfo)
at NLog.Targets.FileTarget.TryArchiveFile(String fileName, LogEventInfo ev, Int32 upcomingWriteSize)
If we look at system handles, we see the following picture:
ServiceManager.Host.exe (29528), File, D:\Temp\Logs\HOST_20161218.txt, 0x104c
ServiceManager.Runner.exe (4824), File, D:\Temp\Logs\HOST_20161218.211240.0.txt, 0xb0c
ServiceManager.Runner.exe (7404), File, D:\Temp\Logs\HOST_20161218.211520.0.txt, 0x8c4
ServiceManager.Runner.exe (8404), File, D:\Temp\Logs\HOST_20161218.211223.0.txt, 0x8ac
ServiceManager.Runner.exe (17008), File, D:\Temp\Logs\HOST_20161218.211456.0.txt, 0x87c
ServiceManager.Runner.exe (17812), File, D:\Temp\Logs\HOST_20161218.211432.0.txt, 0xaec
ServiceManager.Runner.exe (23244), File, D:\Temp\Logs\HOST_20161218.211456.0.txt, 0x8dc
ServiceManager.Runner.exe (26364), File, D:\Temp\Logs\HOST_20161218.211536.0.txt, 0x860
ServiceManager.Runner.exe (27284), File, D:\Temp\Logs\HOST_20161218.211552.0.txt, 0x884
ServiceManager.Runner.exe (27892), File, D:\Temp\Logs\HOST_20161218.211536.0.txt, 0x6bc
ServiceManager.Runner.exe (28220), File, D:\Temp\Logs\HOST_20161218.211520.0.txt, 0x884
ServiceManager.Runner.exe (29672), File, D:\Temp\Logs\HOST_20161218.211520.0.txt, 0x8b8
ServiceManager.Runner.exe (37296), File, D:\Temp\Logs\HOST_20161218.211456.0.txt, 0x8ac
ServiceManager.Runner.exe (37856), File, D:\Temp\Logs\HOST_20161218.211601.0.txt, 0x4f4
ServiceManager.Runner.exe (38412), File, D:\Temp\Logs\HOST_20161218.211552.0.txt, 0x8d4
ServiceManager.Runner.exe (40516), File, D:\Temp\Logs\HOST_20161218.txt, 0x8c8
ServiceManager.Runner.x86.exe (26160), File, D:\Temp\Logs\HOST_20161218.211601.0.txt, 0x98c
Where (8404) is process id. We see that "Runner" process with process id of "8404" has got a hold of the "host" log file and none of the processes can now archive it, if we observe this for longer we see that this process never closes this handle, so I expect that it is stuck.
If we attach a debugger to 8404 PID "Runner" process we see the following messages being generated over and over:
NLog: 2016-12-18 20:56:16.0584 Error Error has been raised. Exception: System.ObjectDisposedException: Cannot access a closed file.
at System.IO.__Error.FileNotOpen()
at System.IO.FileStream.Flush(Boolean flushToDisk)
at System.IO.FileStream.get_SafeFileHandle()
at NLog.Internal.Win32FileCharacteristicsHelper.GetFileCharacteristics(String fileName, FileStream fileStream)
at NLog.Internal.FileAppenders.WindowsMultiProcessFileAppender.GetFileLength()
at NLog.Internal.FileAppenders.FileAppenderCache.GetFileLength(String filePath, Boolean fallback)
at NLog.Targets.FileTarget.GetArchiveFileNameBasedOnFileSize(String fileName, Int32 upcomingWriteSize)
at NLog.Targets.FileTarget.GetArchiveFileName(String fileName, LogEventInfo ev, Int32 upcomingWriteSize)
at NLog.Targets.FileTarget.TryArchiveFile(String fileName, LogEventInfo ev, Int32 upcomingWriteSize)
at NLog.Targets.FileTarget.ProcessLogEvent(LogEventInfo logEvent, String fileName, Byte[] bytesToWrite)
at NLog.Targets.Target.Write(AsyncLogEventInfo logEvent)
On some occasions when we attach to the Runner that has the problematic fild handle open - we see no exceptions as above.
- What is the expected result?
The archiving of files does not get stuck when there's multiple log writers.
Yes, it contains the exceptions reported.
- Please post full exception details (message, stacktrace, inner exceptions)
See above
- Are there any work arrounds? yes/no
Not to my knowledge
- Is there a version in which it did worked?
Unknown
- Can you help us by writing an unit test?
At this point I have a repro case and can supply exception traces
Type:
NLog version: 4.4.0
Platform: .Net 4.5
Current NLog config (xml or C#, if relevant)
Bug description:
We have a "host" application that spins up multiple child "runner" applications.
The "host" application can write to it's own single "host" log.
Multiple "Runner" application can write to a single "runners" log as well as write some diagnostic information in "host" log.
Therefore, for both "runner" and "host" logs there are multiple writers.
The configuration above reflects that.
At some point during the runtime of the application when archiving of "host" log happens, it gets stuck on "host" application side (at least) with the following message:
If we look at system handles, we see the following picture:
Where (8404) is process id. We see that "Runner" process with process id of "8404" has got a hold of the "host" log file and none of the processes can now archive it, if we observe this for longer we see that this process never closes this handle, so I expect that it is stuck.
If we attach a debugger to 8404 PID "Runner" process we see the following messages being generated over and over:
On some occasions when we attach to the Runner that has the problematic fild handle open - we see no exceptions as above.
The archiving of files does not get stuck when there's multiple log writers.
Yes, it contains the exceptions reported.
See above
Not to my knowledge
Unknown
At this point I have a repro case and can supply exception traces