Nlog: Archiving does not work with filetarget in .net core

[larsquick]

Type: Bug
NLog version: 4.5.0-rc06
Also installed Nlog.Extensions.Logging v 1.0.0-rtm-rc6
Platform: UWP/.Net Core
Specifically I'm building a UWP Background Application to be deployed on a Raspberry Pi 3 Model B.
Win10 IoT version: 10.0.16299.248

nlog.config:


xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
autoReload="true"
internalLogFile="c:\logs\nlogMinitrackUdpProxy.log"
internalLogLevel="Info" >



name="testtarget"
fileName="c:\logs\nlogMinitrack.txt"
layout="${date}|${level:uppercase=true}|${message} ${exception:format=message,StackTrace,Data}"
maxArchiveFiles="10"
archiveAboveSize="100"
archiveFileName="c:\logs\nlogMinitrack###.txt"
/>

• What is the current result?
  Logging works as expected, but when NLog tries to archive the logfile I get an UnauthorizedAccessException. This is unexpected since I try to archive to the same folder as I log to, so I should have all needed permissions.

• What is the expected result?
  Archiving will work without generating an error.

• Did you checked the Internal log?
  Yes

• Please post full exception details (message, stacktrace, inner exceptions)
  2018-03-01 16:10:49.3348 Info Archiving c:\logs\nlogMinitrack.txt to c:\logs\nlogMinitrack###.txt
  2018-03-01 16:10:49.3660 Warn FileTarget: Failed to archive file 'c:\logs\nlogMinitrack.txt'. Exception: System.UnauthorizedAccessException: Access to the path is denied.
  at System.IO.Win32FileSystem.MoveFile(String sourceFullPath, String destFullPath)
  at System.IO.MultiplexingWin32WinRTFileSystem.MoveFile(String sourceFullPath, String destFullPath)
  at System.IO.File.Move(String sourceFileName, String destFileName)
  at NLog.Targets.FileTarget.ArchiveFile(String fileName, String archiveFileName)
  at NLog.Targets.FileTarget.DoAutoArchive(String fileName, LogEventInfo eventInfo, Boolean initializedNewFile)
  at NLog.Targets.FileTarget.TryArchiveFile(String fileName, LogEventInfo ev, Int32 upcomingWriteSize, Boolean initializedNewFile)

• Are there any workarounds? yes/no
  Not that I have been able to find.

• Is there a version in which it did work?
  Not that I know of. I updated from rc04 to rc06, rc04 had the same behaviour.
  I have not attempted with any older version.

Additional information:
I have tried to put the archived files in an /archive folder under logs, which I also have permission to write to. I read somewhere in the documentation that the archive should not be in the same folder as the log files, so I tried that. It doesnt change the behaviour.

I tried to use the applications datafolder to store logs. All permissions should be granted to the app in that folder. I used a C# programatic setup in that case instead of nlog.config.
Code:
private void NLogSetup()
{
if (!LogManager.IsLoggingEnabled())
{
LogManager.EnableLogging();
}
//Internal logging of NLog itself
InternalLogger.LogFile = Path.Combine(Windows.Storage.ApplicationData.Current.LocalFolder.Path, "logs", "nlogInternalLog.txt");
InternalLogger.LogLevel = LogLevel.Info;

        var config = new LoggingConfiguration();

        //Create a filetarget for application logging
        var ft = new FileTarget
        {
            FileName = Path.Combine(Windows.Storage.ApplicationData.Current.LocalFolder.Path, "logs", "MinitrackUdpProxyLog.txt"),
            Layout = "${date}|${level:uppercase=true}|${message} ${exception:format=message,StackTrace,Data}",
            MaxArchiveFiles = 10,
            ArchiveAboveSize = 10000, //TODO: Increase
            ArchiveFileName = Path.Combine(Windows.Storage.ApplicationData.Current.LocalFolder.Path, "logs", "MinitrackUdpProxyLogARC{##}.txt"),
            Name = "FileTarget",
            ArchiveNumbering = ArchiveNumberingMode.Rolling
        };

        //Add filetarget
        config.AddTarget(ft);

        //Add loggingrule targeting filetarget.
        config.LoggingRules.Add(new LoggingRule("*", LogLevel.Debug, ft));
        LogManager.Configuration = config;

        logger = LogManager.GetLogger("StartupTask");
    }

This did not work either. Here I have problems getting nlog to work at all.
If I run my app in debug mode from visual studio (so vs is attached to the running process on the pi), logging works, otherwise I get no log files (not nlogs internal log or application logs).
This have worked once or twice without the debugger attached, but usually no logs are generated. I'm unsure of what the problem is here, but in any case I get the same exception when logs should be archived when everything else works.

So to summarize:
Logging works fine, but archiving a logfile to the same folder as I write logs to throws an UnauthorizedAccessException.

[snakefoot]

Can to increase the Internal Logger LogLevel to Debug ? And update the orignal post with the extra log-statements?

[larsquick]

Here is the log with level Debug on internal logger

2018-03-01 17:04:00.6139 Debug ScanAssembly('NLog, Version=4.0.0.0, Culture=neutral, PublicKeyToken=5120e14c03d0593c')
2018-03-01 17:04:01.1139 Info Message Template Auto Format enabled
2018-03-01 17:04:01.3639 Debug Setting 'UppercaseLayoutRendererWrapper.uppercase' to 'true'
2018-03-01 17:04:01.4420 Debug Setting 'FileTarget.name' to 'testtarget'
2018-03-01 17:04:01.4420 Debug Setting 'FileTarget.fileName' to 'c:\logs\nlogMinitrack.txt'
2018-03-01 17:04:01.4889 Debug Setting 'FileTarget.layout' to '${date}|${level:uppercase=true}|${message} ${exception:format=message,StackTrace,Data}'
2018-03-01 17:04:01.5201 Debug Setting 'UppercaseLayoutRendererWrapper.uppercase' to 'true'
2018-03-01 17:04:01.5983 Debug Setting 'ExceptionLayoutRenderer.format' to 'message,StackTrace,Data'
2018-03-01 17:04:01.6139 Debug Setting 'FileTarget.maxArchiveFiles' to '10'
2018-03-01 17:04:01.6139 Debug Setting 'FileTarget.archiveAboveSize' to '100'
2018-03-01 17:04:01.6139 Debug Setting 'FileTarget.archiveFileName' to 'c:\logs\archive\nlogMinitrack##.txt'
2018-03-01 17:04:01.6295 Debug Setting 'FileTarget.archiveNumbering' to 'Rolling'
2018-03-01 17:04:01.6295 Info Adding target File Target[testtarget]
2018-03-01 17:04:01.6451 Debug Registered target testtarget: NLog.Targets.FileTarget
2018-03-01 17:04:01.6764 Info Configured from an XML element in C:\Data\Users\DefaultAccount\AppData\Local\DevelopmentFiles\MinitrackUdpProxy-uwpVS.Debug_ARM.lars.klundby\nlog.config...
2018-03-01 17:04:01.7233 Debug Unused target checking is started... Rule Count: 1, Target Count: 1
2018-03-01 17:04:01.8014 Debug Unused target checking is completed. Total Rule Count: 1, Total Target Count: 1, Unused Target Count: 0
2018-03-01 17:04:01.8170 Debug --- NLog configuration dump ---
2018-03-01 17:04:01.8170 Debug Targets:
2018-03-01 17:04:01.8170 Debug File Target[testtarget]
2018-03-01 17:04:01.8326 Debug Rules:
2018-03-01 17:04:01.8483 Debug logNamePattern: (:All) levels: [ Trace Debug Info Warn Error Fatal ] appendTo: [ testtarget ]
2018-03-01 17:04:01.8483 Debug --- End of NLog configuration dump ---
2018-03-01 17:04:01.8795 Info Found 16 configuration items
2018-03-01 17:04:01.9889 Info Found 16 configuration items
2018-03-01 17:04:02.0514 Debug Targets for StartupTask by level:
2018-03-01 17:04:02.1572 Debug Trace => testtarget
2018-03-01 17:04:02.1572 Debug Debug => testtarget
2018-03-01 17:04:02.1572 Debug Info => testtarget
2018-03-01 17:04:02.1572 Debug Warn => testtarget
2018-03-01 17:04:02.1572 Debug Error => testtarget
2018-03-01 17:04:02.1572 Debug Fatal => testtarget
2018-03-01 17:04:02.3135 Debug FileTarget: process file 'c:\logs\nlogMinitrack.txt' on startup
2018-03-01 17:04:02.4209 Debug Creating file appender: c:\logs\nlogMinitrack.txt
2018-03-01 17:04:03.0615 Debug Targets for UdpReader by level:
2018-03-01 17:04:03.0615 Debug Trace => testtarget
2018-03-01 17:04:03.0615 Debug Debug => testtarget
2018-03-01 17:04:03.0615 Debug Info => testtarget
2018-03-01 17:04:03.0615 Debug Warn => testtarget
2018-03-01 17:04:03.0771 Debug Error => testtarget
2018-03-01 17:04:03.0771 Debug Fatal => testtarget
2018-03-01 17:04:03.0928 Debug FileAppender Closing Invalidate - c:\logs\nlogMinitrack.txt
2018-03-01 17:04:03.1084 Debug FileTarget: do archive file 'c:\logs\nlogMinitrack.txt'
2018-03-01 17:04:03.2021 Info Archiving c:\logs\nlogMinitrack.txt to c:\logs\archive\nlogMinitrack##.txt
2018-03-01 17:04:03.2021 Debug Move file from 'c:\logs\nlogMinitrack.txt' to 'c:\logs\archive\nlogMinitrack##.txt'
2018-03-01 17:04:03.6084 Warn FileTarget: Failed to archive file 'c:\logs\nlogMinitrack.txt'. Exception: System.UnauthorizedAccessException: Access to the path is denied.
at System.IO.Win32FileSystem.MoveFile(String sourceFullPath, String destFullPath)
at System.IO.MultiplexingWin32WinRTFileSystem.MoveFile(String sourceFullPath, String destFullPath)
at System.IO.File.Move(String sourceFileName, String destFileName)
at NLog.Targets.FileTarget.ArchiveFile(String fileName, String archiveFileName)
at NLog.Targets.FileTarget.DoAutoArchive(String fileName, LogEventInfo eventInfo, Boolean initializedNewFile)
at NLog.Targets.FileTarget.TryArchiveFile(String fileName, LogEventInfo ev, Int32 upcomingWriteSize, Boolean initializedNewFile)
2018-03-01 17:04:03.6553 Debug Creating file appender: c:\logs\nlogMinitrack.txt
2018-03-01 17:04:03.6709 Debug FileTarget: process file 'c:\logs\nlogMinitrack.txt' on startup
2018-03-01 17:04:03.6709 Debug FileAppender Closing Invalidate - c:\logs\nlogMinitrack.txt
2018-03-01 17:04:03.6709 Debug FileTarget: do archive file 'c:\logs\nlogMinitrack.txt'
2018-03-01 17:04:03.7490 Info Archiving c:\logs\nlogMinitrack.txt to c:\logs\archive\nlogMinitrack##.txt
...

[snakefoot]

Some how this happens for your:

'FileTarget.archiveFileName' to 'c:\logs\archive\nlogMinitrack##.txt'

Not sure why the { are gone, but it should say:

'FileTarget.archiveFileName' to 'c:\logs\archive\nlogMinitrack{##}.txt'

But the code you have pasted also differs from the internal-log you have shown:

You have posted this (which is correct), but doesn't match the filename from the internal logger:

ArchiveFileName = Path.Combine("C:\\", "logs", "MinitrackUdpProxyLogARC{##}.txt"),

[snakefoot]

I can recommend not to fiddle with ArchiveFileName and ArchiveNumbering, but just do this (When using NLog 4.5)

    var ft = new FileTarget
    {
        FileName = Path.Combine(Windows.Storage.ApplicationData.Current.LocalFolder.Path, "logs", "MinitrackUdpProxyLog.txt"),
        Layout = "${date}|${level:uppercase=true}|${message} ${exception:format=message,StackTrace,Data}",
        MaxArchiveFiles = 10,
        ArchiveAboveSize = 10000, //TODO: Increase
        Name = "FileTarget",
    };

[larsquick]

I misread the documentation so I thought I didnt need the {} around the numbers. Either way it gives the same behaviour.
I tried removing the ArchiveFileName and archiveNumbering both with xml config and programatic config.

xml target:
name="testtarget"
fileName="c:\logs\nlogMinitrack.txt"
layout="${date}|${level:uppercase=true}|${message} ${exception:format=message,StackTrace,Data}"
maxArchiveFiles="10"
archiveAboveSize="100"
/>

C# target:
var ft = new FileTarget
{
FileName = Path.Combine(Windows.Storage.ApplicationData.Current.LocalFolder.Path, "logs", "MinitrackUdpProxyLog.txt"),
Layout = "${date}|${level:uppercase=true}|${message} ${exception:format=message,StackTrace,Data}",
MaxArchiveFiles = 10,
ArchiveAboveSize = 10000, //TODO: Increase
//ArchiveFileName = Path.Combine(Windows.Storage.ApplicationData.Current.LocalFolder.Path, "logs", "MinitrackUdpProxyLogARC{##}.txt"),
Name = "FileTarget"
//ArchiveNumbering = ArchiveNumberingMode.Rolling
};

Both setups yielded the same exception.

Internal log with xml config:
2018-03-01 17:32:02.0549 Info Archiving c:\logs\nlogMinitrack.txt to c:\logs\nlogMinitrack.0.txt
2018-03-01 17:32:02.0549 Debug Move file from 'c:\logs\nlogMinitrack.txt' to 'c:\logs\nlogMinitrack.0.txt'
2018-03-01 17:32:02.4924 Warn FileTarget: Failed to archive file 'c:\logs\nlogMinitrack.txt'. Exception: System.UnauthorizedAccessException: Access to the path is denied.
at System.IO.Win32FileSystem.MoveFile(String sourceFullPath, String destFullPath)
at System.IO.MultiplexingWin32WinRTFileSystem.MoveFile(String sourceFullPath, String destFullPath)
at System.IO.File.Move(String sourceFileName, String destFileName)
at NLog.Targets.FileTarget.ArchiveFile(String fileName, String archiveFileName)
at NLog.Targets.FileTarget.DoAutoArchive(String fileName, LogEventInfo eventInfo, Boolean initializedNewFile)
at NLog.Targets.FileTarget.TryArchiveFile(String fileName, LogEventInfo ev, Int32 upcomingWriteSize, Boolean initializedNewFile)

C# config:
2018-03-01 17:39:34.6269 Debug FileTarget: do archive file 'C:\Data\Users\DefaultAccount\AppData\Local\Packages\MinitrackUdpProxy-uwp_9snsj55qnvepy\LocalState\logs\MinitrackUdpProxyLog.txt'
2018-03-01 17:39:34.7363 Info Archiving C:\Data\Users\DefaultAccount\AppData\Local\Packages\MinitrackUdpProxy-uwp_9snsj55qnvepy\LocalState\logs\MinitrackUdpProxyLog.txt to C:\Data\Users\DefaultAccount\AppData\Local\Packages\MinitrackUdpProxy-uwp_9snsj55qnvepy\LocalState\logs\MinitrackUdpProxyLog.0.txt
2018-03-01 17:39:34.7363 Debug Move file from 'C:\Data\Users\DefaultAccount\AppData\Local\Packages\MinitrackUdpProxy-uwp_9snsj55qnvepy\LocalState\logs\MinitrackUdpProxyLog.txt' to 'C:\Data\Users\DefaultAccount\AppData\Local\Packages\MinitrackUdpProxy-uwp_9snsj55qnvepy\LocalState\logs\MinitrackUdpProxyLog.0.txt'
2018-03-01 17:39:35.1738 Warn FileTarget: Failed to archive file 'C:\Data\Users\DefaultAccount\AppData\Local\Packages\MinitrackUdpProxy-uwp_9snsj55qnvepy\LocalState\logs\MinitrackUdpProxyLog.txt'. Exception: System.UnauthorizedAccessException: Access to the path is denied.
at System.IO.Win32FileSystem.MoveFile(String sourceFullPath, String destFullPath)
at System.IO.MultiplexingWin32WinRTFileSystem.MoveFile(String sourceFullPath, String destFullPath)
at System.IO.File.Move(String sourceFileName, String destFileName)
at NLog.Targets.FileTarget.ArchiveFile(String fileName, String archiveFileName)
at NLog.Targets.FileTarget.DoAutoArchive(String fileName, LogEventInfo eventInfo, Boolean initializedNewFile)
at NLog.Targets.FileTarget.TryArchiveFile(String fileName, LogEventInfo ev, Int32 upcomingWriteSize, Boolean initializedNewFile)

[snakefoot]

Now the filenames in the internal logger looks good. Are the you able to move the files yourself?

Ex. Move file from 'c:\logs\nlogMinitrack.txt' to 'c:\logs\nlogMinitrack.0.txt' ?

[snakefoot]

What is the chmod of the logs folder and its files ? Should be 777 or 644 (Btw I'm not good with Linux, just saying random stuff).

[larsquick]

I tried both moving and copying using ssh command prompt. Both worked fine.

Chmod is not avalible on windows, but all permissions are granted.
For win10iot there is a "Folderpermissions" command that is used to give UWP apps read/write access to a folder. I have set this on the logs folder.

[larsquick]

Trying to move file programatically throws the same exception.

I added this code:
try
{
File.AppendAllText(@"c:\logsmylog.txt", "Moving file");
File.Move(@"c:\logs\nlogMinitrack.txt", @"c:\logs\nlogMiniTrackCOPY.txt");
File.AppendAllText(@"c:\logsmylog.txt", "File moved");
}
catch (Exception e)
{
File.AppendAllText(@"c:\logsmylog.txt", "EXception when moving! " + e.Message);
}

Contents of mylog.txt:
Moving fileEXception when moving! Access to the path is denied.

[snakefoot]

Good test. Are your application running with restricted permissions?

[larsquick]

It's an UWP Background application so I assume it's very restricted. I'm not very familiar with the details of how this is managed tho.

This seems to be a windows bug, not an NLog issue anyway.

This code yields the same exception:
try
{
File.AppendAllText(@"c:\logsmylog.txt", "Creating file"+Environment.NewLine);
File.WriteAllText(@"c:\logs\test.file","This is a test");
File.Move(@"c:\logs\test.file", @"c:\logs\test.copy");
File.AppendAllText(@"c:\logsmylog.txt", "File moved"+Environment.NewLine);
}
catch (Exception e)
{
File.AppendAllText(@"c:\logsmylog.txt", "EXception when moving! " + e.Message+Environment.NewLine);
}

mylog.txt:
Creating file
EXception when moving! Access to the path is denied.

I tried this code:
try
{
File.AppendAllText(@"c:\logsmylog.txt", "Creating file"+Environment.NewLine);
File.WriteAllText(@"c:\logs\test.file","This is a test");
File.Copy(@"c:\logs\test.file", @"c:\logs\test.copy");
File.Delete(@"c:\logs\test.file");
File.AppendAllText(@"c:\logsmylog.txt", "File moved"+Environment.NewLine);
}
catch (Exception e)
{
File.AppendAllText(@"c:\logsmylog.txt", "EXception when moving! " + e.Message+Environment.NewLine);
}

Copying works, but I get an exception when trying to delete. So it seems I can't move or delete any files from a UWP app, only create them.

Thank you for your help snakefoot. I will try to contact MS about this issue.

[snakefoot]

@larsquick If you can live without ArchiveAboveSize, but just having a file for each day, then NLog 4.5.0 should work without needing move-file-permissions (Added ${shortdate} to filename)

    var ft = new FileTarget
    {
        FileName = Path.Combine(Windows.Storage.ApplicationData.Current.LocalFolder.Path, "logs", "MinitrackUdpProxyLog-${shortdate}.txt"),
        Layout = "${date}|${level:uppercase=true}|${message} ${exception:format=message,StackTrace,Data}",
        MaxArchiveFiles = 10,
        Name = "FileTarget",
    };

[larsquick]

Thank you @snakefoot
I already solved my issue by giving my app permission to run cmd and delete the logfile using command line if it gets to big.

The problem is that I built a background application that is then considered an UWP app, so it has lots of restrictions.

If I had built a standard console app instead it would have worked fine. The problem with that is that win10iot doesnt have any way to run a service type thing, if I want that I'm back to an UWP background application. So right now the best way this can be solved is to use command line.

For anyone else reading this; to enable command line for an UWP app I had to add record to windows registry.
reg ADD "HKLM\SOFTWARE\Microsoft\Windows\CurrentVersion\EmbeddedMode\ProcessLauncher" /v AllowedExecutableFilesList /t REG_MULTI_SZ /d "c:\windows\system32\cmd.exe\0"

I made a thread asking on MSDN here: https://social.msdn.microsoft.com/Forums/windowsapps/en-US/467e0e8e-8061-4e1e-b18e-4cb17eb4f79b/file-access-permissions-from-a-uwp-background-application?forum=WindowsIoT

Short answer is file access permission will be added as an option to an UWP app so it will be possible to delete files from disk. This will be added in a future update of windows 10 IOT.

[304NotModified]

OK thanks for the feedback!