CODEWITHSUNDEEP
c#.netloggingnlog
Simon Elms
Simon Elms

Reputation: 19758

Upgrading to NLog 5, two targets cannot log to same file

Is there any way for two NLog targets to write to the same log file in NLog 5? It's possible under NLog 4.6.8 but after upgrading my application to NLog 5 I find it no longer works, at least with the current configuration.

This is an old demo .NET Framework 4.5 console app, written using NLog 4.6.8 and including NLog.Config 4.6.8. With this setup the console app works fine, with both targets writing to the same file.

Here is the Program.cs file:

    using NLog;
    using System;
    
    namespace NLogDemo
    {
        class Program
        {
            private static NLog.Logger LOG = LogManager.GetCurrentClassLogger();
            private static NLog.Logger MESSAGEONLYLOG = LogManager.GetLogger("MessageOnlyLogger");
    
            static void Main(string[] args)
            {
                MESSAGEONLYLOG.Debug(" ");
                MESSAGEONLYLOG.Debug(new string('*', 110));
                LOG.Debug("Application Starting");
                MESSAGEONLYLOG.Debug(new string('*', 110));
    
                LOG.Debug("This is a debug message");
                LOG.Info("This is an info message");
                LOG.Error("This is an error message");
    
                MESSAGEONLYLOG.Debug(new string('-', 110));
                LOG.Debug("Application Closing");
                MESSAGEONLYLOG.Debug(new string('-', 110));
    
                Console.WriteLine();
                Console.WriteLine("Press any key to exit");
                Console.ReadKey();
            }
        }
    }

and here is the app.config file:

    <?xml version="1.0" encoding="utf-8" ?>
    <configuration>
      <configSections>
        <section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog" />
      </configSections>
      <startup> 
        <supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.5" />
      </startup>
      
      <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
            xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
            xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
            autoReload="true"
            throwExceptions="false"
            internalLogLevel="Debug" internalLogFile="nlog-internal.log">
        <targets>
          <target
              name="logfile"
              xsi:type="File"
              layout="${longdate} | ${level} | ${callsite} | ${message} ${exception:format=tostring}"
              fileName="demo.log" />
          <target
              name="messageonlylog"
              xsi:type="File"
              layout="${message}"
              fileName="demo.log" />
          <target
              name="console"
              xsi:type="Console"
              layout="${message} ${exception:format=tostring}" />
        </targets>
    
        <rules>
          <logger name="MessageOnlyLogger" minlevel="Debug" writeTo="messageonlylog" final="true" />
          <logger name="*" minlevel="Debug" writeTo="logfile" />
          <logger name="*" minlevel="Debug" writeTo="console" />
        </rules>
      </nlog>
      
    </configuration>

This is the output written to the demo.log file:

    2023-08-30 14:47:33.1975 | Debug | NLogDemo.Program.Main | Application Starting 
    **************************************************************************************************************
    2023-08-30 14:47:33.2235 | Debug | NLogDemo.Program.Main | This is a debug message 
    2023-08-30 14:47:33.2235 | Info | NLogDemo.Program.Main | This is an info message 
    2023-08-30 14:47:33.2235 | Error | NLogDemo.Program.Main | This is an error message 
    --------------------------------------------------------------------------------------------------------------
    2023-08-30 14:47:33.2235 | Debug | NLogDemo.Program.Main | Application Closing 
    --------------------------------------------------------------------------------------------------------------

You can see the MessageOnlyLogger has written the horizontal dividers, and the current class logger has written the log messages which include the timestamps, logging level, etc.

When I upgraded to NLog 5.2.3 I saw that NLog.Config has been deprecated, and this Stackoverflow answer said it was safe to remove, so I uninstalled the NLog.Config package. Now when I run up the app only the MessageOnlyLogger writes to the log file. The output written to the demo.log is as follows:

    **************************************************************************************************************
    **************************************************************************************************************
    --------------------------------------------------------------------------------------------------------------
    --------------------------------------------------------------------------------------------------------------

The nlog-internal.log shows NLog was unable to create a second file appender because the file was already being used by another process (see the Warn message at 15:04:27.7702):

2023-08-30 15:04:27.6422 Info Configuration initialized.
2023-08-30 15:04:27.6482 Debug Targets configured when LogLevel >= Debug for Logger: NLogDemo.Program
2023-08-30 15:04:27.6482 Debug Logger NLogDemo.Program [Debug] => logfile console
2023-08-30 15:04:27.6482 Debug Logger NLogDemo.Program [Info] => logfile console
2023-08-30 15:04:27.6482 Debug Logger NLogDemo.Program [Warn] => logfile console
2023-08-30 15:04:27.6482 Debug Logger NLogDemo.Program [Error] => logfile console
2023-08-30 15:04:27.6482 Debug Logger NLogDemo.Program [Fatal] => logfile console
2023-08-30 15:04:27.6482 Debug Targets configured when LogLevel >= Debug for Logger: MessageOnlyLogger
2023-08-30 15:04:27.6482 Debug Logger MessageOnlyLogger [Debug] => messageonlylog
2023-08-30 15:04:27.6482 Debug Logger MessageOnlyLogger [Info] => messageonlylog
2023-08-30 15:04:27.6482 Debug Logger MessageOnlyLogger [Warn] => messageonlylog
2023-08-30 15:04:27.6482 Debug Logger MessageOnlyLogger [Error] => messageonlylog
2023-08-30 15:04:27.6592 Debug Logger MessageOnlyLogger [Fatal] => messageonlylog
2023-08-30 15:04:27.7152 Debug FileTarget(Name=messageonlylog): Preparing for new file: 'C:\C#\DemoCode\Logging\NLogDemo_SimpleUpgraded\NLogDemo\bin\Debug\demo.log'
2023-08-30 15:04:27.7252 Debug FileTarget(Name=messageonlylog): Creating file appender: 'C:\C#\DemoCode\Logging\NLogDemo_SimpleUpgraded\NLogDemo\bin\Debug\demo.log'
2023-08-30 15:04:27.7452 Debug Watching file-filter 'demo.log' in directory: C:\C#\DemoCode\Logging\NLogDemo_SimpleUpgraded\NLogDemo\bin\Debug
2023-08-30 15:04:27.7632 Debug FileTarget(Name=logfile): Preparing for new file: 'C:\C#\DemoCode\Logging\NLogDemo_SimpleUpgraded\NLogDemo\bin\Debug\demo.log'
2023-08-30 15:04:27.7632 Debug FileTarget(Name=logfile): Creating file appender: 'C:\C#\DemoCode\Logging\NLogDemo_SimpleUpgraded\NLogDemo\bin\Debug\demo.log'
2023-08-30 15:04:27.7702 Warn FileTarget(Name=logfile): Failed to create file appender: C:\C#\DemoCode\Logging\NLogDemo_SimpleUpgraded\NLogDemo\bin\Debug\demo.log Exception: System.IO.IOException: The process cannot access the file 'C:\C#\DemoCode\Logging\NLogDemo_SimpleUpgraded\NLogDemo\bin\Debug\demo.log' because it is being used by another process.
   at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
   at 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)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize)
   at NLog.Internal.FileAppenders.BaseFileAppender.TryCreateFileStream(Boolean allowFileSharedWriting, Int32 overrideBufferSize)
   at NLog.Internal.FileAppenders.BaseFileAppender.CreateFileStream(Boolean allowFileSharedWriting, Int32 overrideBufferSize)
   at NLog.Internal.FileAppenders.SingleProcessFileAppender..ctor(String fileName, ICreateFileParameters parameters)
   at NLog.Internal.FileAppenders.SingleProcessFileAppender.Factory.NLog.Internal.FileAppenders.IFileAppenderFactory.Open(String fileName, ICreateFileParameters parameters)
   at NLog.Internal.FileAppenders.FileAppenderCache.CreateAppender(String fileName, Int32 freeSpot)

Is there any way to configure NLog 5 to handle two targets writing to the same file? Or is it no longer possible?

Upvotes: 1

Views: 619

Answers (1)

Rolf Kristensen
Rolf Kristensen

Reputation: 19867

The issue is not removing the NLog.config-nuget-package, and one is recommended to remove it.

NLog v5 includes several major changes, and one of them is changing FileTarget.KeepFileOpen to true.

When having 2 different FileTarget pointing at the same file, then you must explictly configure keepFileOpen="false", or alternative configure concurrentWrites="true":

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog" />
  </configSections>
  <startup> 
    <supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.5" />
  </startup>
  
  <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
        xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
        autoReload="true"
        throwExceptions="false"
        internalLogLevel="Debug" internalLogFile="nlog-internal.log">
    <targets>
      <target
          name="logfile"
          xsi:type="File"
          layout="${longdate} | ${level} | ${callsite} | ${message} ${exception:format=tostring}"
          concurrentWrites="true"
          fileName="demo.log" />
      <target
          name="messageonlylog"
          xsi:type="File"
          layout="${message}"
          concurrentWrites="true"
          fileName="demo.log" />
      <target
          name="console"
          xsi:type="Console"
          layout="${message} ${exception:format=tostring}" />
    </targets>

    <rules>
      <logger name="MessageOnlyLogger" minlevel="Debug" writeTo="messageonlylog" final="true" />
      <logger name="*" minlevel="Debug" writeTo="logfile" />
      <logger name="*" minlevel="Debug" writeTo="console" />
    </rules>
  </nlog>
  
</configuration>

It is not recommended to use keepFileOpen="false", as sometimes background-applications like walware-detectors / windows-defender / etc. will be able to take over the file-handle and lock the file for writing (blocking application from writing to file)

There is minimal overhead with using concurrentWrites="true" on .NET Framework on Windows, as it changes to performing "atomic" file-append (without using global mutex, that are operating system wide).

Upvotes: 2

Related Questions