dotnet core nlog running on Linux logs only one entry

[martinto]

Type (choose one): Bug
NLog version: v4.4.0-beta15
Platform: .NET Core
Current NLog config (xml or C#, if relevant)

    <?xml version="1.0" encoding="utf-8" ?>
    <nlog 
        xmlns="http://www.nlog-project.org/schemas/NLog.xsd" 
        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
        <extensions>
            <!--enable NLog.Web for ASP.NET Core-->
            <add assembly="NLog.Web.AspNetCore"/>
        </extensions>
        <targets>
            <!-- https://github.com/nlog/nlog/wiki/File-target -->
            <!-- http://stackoverflow.com/questions/34679727/use-nlog-in-asp-net-5-application -->
            <target name="allfile" xsi:type="AsyncWrapper" queueLimit="5000" overflowAction="Discard">
                <target name="allfile" xsi:type="File"
                        fileName="${basedir}/logs/all-logfile.csv"
                        archiveFileName="${basedir}/logs/archives/all-log.{#}.csv"
                        archiveEvery="Day"
                        archiveNumbering="Date"
                        archiveDateFormat="yyyyMMdd"
                        maxArchiveFiles="28"
                        concurrentWrites="true"
                        keepFileOpen="false"
                        encoding="utf-8">
                    <layout xsi:type="CSVLayout">
                        <column name="time" layout="${longdate}" />
                        <column name="logger" layout="${logger}" />
                        <column name="authtype" layout="${aspnet-user-authtype}" />
                        <column name="identity" layout="${aspnet-user-identity}" />
                        <column name="level" layout="${uppercase:${level}}" />
                        <column name="message" layout="${message} ${exception:format=ToString,StackTrace}" />
                    </layout>
                </target>
            </target>
            <target name="ownfile" xsi:type="AsyncWrapper" queueLimit="5000" overflowAction="Discard">
                <target name="ownfile" xsi:type="File"
                        fileName="${basedir}/logs/own-logfile.csv"
                        archiveFileName="${basedir}/logs/archives/own-log.{#}.csv"
                        archiveEvery="Day"
                        archiveNumbering="Date"
                        archiveDateFormat="yyyyMMdd"
                        maxArchiveFiles="28"
                        concurrentWrites="true"
                        keepFileOpen="false"
                        encoding="utf-8">
                    <layout xsi:type="CSVLayout">
                        <column name="time" layout="${longdate}" />
                        <column name="logger" layout="${logger}" />
                        <column name="authtype" layout="${aspnet-user-authtype}" />
                        <column name="identity" layout="${aspnet-user-identity}" />
                        <column name="level" layout="${uppercase:${level}}" />
                        <column name="message" layout="${message} ${exception:format=ToString,StackTrace}" />
                    </layout>
                </target>
            </target>
            <target xsi:type="Null" name="blackhole" />
        </targets>

        <rules>
            <!--All logs, including from Microsoft-->
            <logger name="*" minlevel="Debug" writeTo="allfile" />

            <!--Skip Microsoft logs and so log only own logs-->
            <logger name="Microsoft.*" minlevel="Trace" writeTo="blackhole" final="true" />
            <logger name="*" minlevel="Debug" writeTo="ownFile" />    
        </rules>
    </nlog>

I am running an aspnet core site on Linux using Kestrel. I have set up nlog to log to csv files. All is well in my Windows development environment, but when I run it on Linux I only get one entry in the log file. I turned on nlog tracing and found the following error in the output:

2016-09-09 07:22:46.2123 Error Error has been raised. Exception: System.IO.IOException: The file '/var/aspnetcore/CSWebSite/releases/20160909061254/logs/archives/own-log.20160908.csv' already exists.
   at System.IO.UnixFileSystem.MoveFile(String sourceFullPath, String destFullPath)
   at System.IO.File.Move(String sourceFileName, String destFileName)
   at NLog.Targets.FileTarget.ArchiveByDate(String fileName, String pattern, LogEventInfo logEvent)
   at NLog.Targets.FileTarget.ProcessLogEvent(LogEventInfo logEvent, String fileName, Byte[] bytesToWrite)
   at NLog.Targets.FileTarget.FlushCurrentFileWrites(String currentFileName, LogEventInfo firstLogEvent, MemoryStream ms, List`1 pendingContinuations)
2016-09-09 07:22:46.2123 Error Error has been raised. Exception: System.IO.IOException: The file '/var/aspnetcore/CSWebSite/releases/20160909061254/logs/archives/all-log.20160907.csv' already exists.
   at System.IO.UnixFileSystem.MoveFile(String sourceFullPath, String destFullPath)
   at System.IO.File.Move(String sourceFileName, String destFileName)
   at NLog.Targets.FileTarget.ArchiveByDate(String fileName, String pattern, LogEventInfo logEvent)
   at NLog.Targets.FileTarget.ProcessLogEvent(LogEventInfo logEvent, String fileName, Byte[] bytesToWrite)
   at NLog.Targets.FileTarget.FlushCurrentFileWrites(String currentFileName, LogEventInfo firstLogEvent, MemoryStream ms, List`1 pendingContinuations)

I have concurrent writes true and keepFileOpen false which seems necessary as kestrel forks multiple dotnet processes on Linux.

I have found no work around and there are no earlier versions which support dotnet core.

I don't yet know if I could write a unit test for this, the setup required to reproduce the environment would be complex.

I have attached an NLog log file.

nlog.txt

[304NotModified]

2016-09-09 07:22:46.2119 Info Archiving /var/aspnetcore/CSWebSite/releases/20160909061254/logs/all-logfile.csv to /var/aspnetcore/CSWebSite/releases/20160909061254/logs/archives/all-log.20160907.csv
2016-09-09 07:22:46.2123 Info Archiving /var/aspnetcore/CSWebSite/releases/20160909061254/logs/own-logfile.csv to /var/aspnetcore/CSWebSite/releases/20160909061254/logs/archives/own-log.20160908.csv

I think there is something wrong with the timezone, as the file should be named all-log.20160909.csv and own-log.20160909.csv? In which UTC are you located?

[martinto]

This is the listing of the archive folder:

-rwxr--r-- 1 www-data www-data   272 Sep  6 21:53 all-log.20160906.csv
-rwxr--r-- 1 www-data www-data   534 Sep  7 07:49 all-log.20160907.csv
-rwxr--r-- 1 www-data www-data 19228 Sep  6 21:53 own-log.20160906.csv
-rwxr--r-- 1 www-data www-data   118 Sep  7 07:49 own-log.20160907.csv
-rwxr--r-- 1 www-data www-data   118 Sep  8 07:35 own-log.20160908.csv

The date command shows British Summer Time (the machine is set to Europe/London):

Mon Sep 12 06:48:07 BST 2016

[304NotModified]

So the machine is in UTC+1 (summer time) right?

[martinto]

Yes.

[martinto]

I can test in a different timezone if that would help.

[304NotModified]

Well I don't think it's a timezone as the difference in less then expected.

Do you know if the dates in the archive are correct? It should take the date of the last write

[martinto]

I have just done an experiment:

sudo service supervisor stop
sudo rm logs/*.csv
sudo service supervisor start
date
cat logs/all-logfile.csv

The output from date and the cat command are as follows:

Wed Sep 14 10:42:45 BST 2016
time,logger,authtype,identity,level,message
2016-09-14 10:42:46.7334,Microsoft.AspNetCore.Hosting.Internal.WebHost,,,DEBUG,Hosting starting

There is a delay between starting the site and the code logging the message which account for the small difference in time.

Should the logged time be local time?

[304NotModified]

This is an issue with archiving. The issue is also in 4.3, see #1645 (comment)

[saschakloeppner]

Hi,

I am using .NET Core 1.1.0 and NLog.Extensions.Logging 1.0.0-rtm-alpha5.
I have a simmilar issue. When I run the project on windows everything works well.
On linux I get one log file for every log message.
My targes:

<targets>
    <target name="appfile" xsi:type="File"
            fileName="data/logs/app-log.txt"
            layout="${date} | ${level} | ${callsite} | ${message} ${onexception:inner=|} ${exception:format=Message,tostring}"
            archiveFileName="data/logs/app-log.${shortdate}.txt"
            archiveEvery="Day"
            archiveNumbering="Date"
            maxArchiveFiles="30"
            concurrentWrites="true"
            keepFileOpen="false"
            />
  </targets>

My logfiles

drwxrwxr-x 2 loopback loopback 4096 Jan 13 15:05 ./
drwxrwxr-x 3 loopback loopback 4096 Jan 13 14:58 ../
-rwxrw-r-- 1 loopback loopback  130 Jan 13 14:58 app-log.2017-01-13.1.txt*
-rwxrw-r-- 1 loopback loopback   99 Jan 13 14:58 app-log.2017-01-13.2.txt*
-rwxrw-r-- 1 loopback loopback  120 Jan 13 14:58 app-log.2017-01-13.3.txt*
-rwxrw-r-- 1 loopback loopback   91 Jan 13 14:59 app-log.2017-01-13.4.txt*
-rwxrw-r-- 1 loopback loopback  147 Jan 13 14:59 app-log.2017-01-13.5.txt*
-rwxrw-r-- 1 loopback loopback   91 Jan 13 15:05 app-log.2017-01-13.6.txt*
-rwxrw-r-- 1 loopback loopback   80 Jan 13 14:58 app-log.2017-01-13.txt*
-rwxrw-r-- 1 loopback loopback  147 Jan 13 15:05 app-log.txt*

[304NotModified]

We're aware of this issue, but i'm unable to fix this right now.

.NET Core is pretty unstable on my machine, Visual Studio is really slow and working on this is taking for the simplest things a lot of time. I have no time to (waste) my time on these issues. Tried today VS2017, but also a lot of crashes, errors and other issues. Spend hours on reinstalling, but even on AppVeyor (the build server), it's unstable.

Help on this will be appreciated. I will wait for netstandard 2.0 and a stable VS2017 until I will work again on .NET Core stuff.

[snakefoot]

It seems file-creation time doesn't work on Linux when using Ext2 and Ext3 (Works on ext4 + btfrs)

http://www.mail-archive.com/rsync@lists.samba.org/msg21509.html
http://stackoverflow.com/questions/3813541/is-there-a-way-to-know-the-creation-time-of-a-file-in-ubuntu

A workaround on MONO / Linux could be to use UnixFileSystemInfo.LastStatusChangeTimeUtc (ctime). This is not perfect and not the same as file birth time. This is updated for various system calls, any that modify the inode, rather than the data it contains.

A different workaround would be to check the result of GetFileCreationTimeUtc(), and if less than Year 1980, then we regard the result as not trusted. Instead we make fallback to a single call to GetFileLastWriteTimeUtc(), and caches the creation time until the appender is closed.

[304NotModified]

Thanks @snakefoot!

Another way is to administer the creation dates in another file, eg. .nlogcreationdates

[snakefoot]

@304NotModified Have created #1931, that also fixes the UnixMultiProcessFileAppender. Since one cannot always trust File.GetCreationTimeUtc on non-Windows.

[304NotModified]

Should be fixed in the next beta, beta 6

We have to merge the master again into CoreCLR, which give probably a lot of merge conflicts

[304NotModified]

merging now

[DavidYamer]

OS：Linux for Windows 10，Ubuntu 14.04-x64
<targets> <!-- write logs to file --> <target xsi:type="File" name="allfile" fileName="Logs\nlog-all-${shortdate}.log" layout="${longdate}|${event-properties:item=EventId.Id}|${logger}|${uppercase:${level}}|${message} ${exception}" /> <target xsi:type="File" name="ownFile-web" fileName="Logs\nlog-own-${shortdate}.log" layout="${longdate}|${event-properties:item=EventId.Id}|${logger}|${uppercase:${level}}|${message} ${exception}" /> <target xsi:type="Null" name="blackhole" /> </targets>
Error:2017-02-14 11:10:19.1363 Error Error has been raised. Exception: System.IO.IOException: The filename, directory name, or volume label syntax is incorrect.

at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
at System.Threading.Mutex.MutexTryCodeHelper.MutexTryCode(Object userData)
at System.Runtime.CompilerServices.RuntimeHelpers.ExecuteCodeWithGuaranteedCleanup(TryCode code, CleanupCode backoutCode, Object userData)
at System.Threading.Mutex.CreateMutexWithGuaranteedCleanup(Boolean initiallyOwned, String name, Boolean& createdNew, SECURITY_ATTRIBUTES secAttrs)
at NLog.Internal.FileAppenders.RetryingMultiProcessFileAppender.CreateArchiveMutex()
at NLog.Internal.FileAppenders.RetryingMultiProcessFileAppender.Factory.NLog.Internal.FileAppenders.IFileAppenderFactory.Open(String fileName, ICreateFileParameters parameters)
at NLog.Internal.FileAppenders.FileAppenderCache.AllocateAppender(String fileName)
at NLog.Targets.FileTarget.WriteToFile(String fileName, LogEventInfo logEvent, Byte[] bytes, Boolean justData)
at NLog.Targets.FileTarget.ProcessLogEvent(LogEventInfo logEvent, String fileName, Byte[] bytesToWrite)
at NLog.Targets.Target.Write(AsyncLogEventInfo logEvent)

@304NotModified ,I want to know if it has to fixed?

[304NotModified]

Unfortunately not yet. As you can see here, a lot has been changed since NLog 4.4 and need to find some time to fix it. See #1944 for the process.

[304NotModified]

more test results are here. NLog/NLog.Extensions.Logging#63

Will work on this tonight.

[304NotModified]

This should be fixed in beta06. https://www.nuget.org/packages/NLog/5.0.0-beta06

Would be great if you could confirm!