Why is my Windows Service not logging until the service is restarted

Question

tl;dr

I've created a Windows Service using TopShelf, added logging using Log4Net, and then built the project, installed the service and started the service. Then my service runs fine, but it is not logging. The TopShelf logs appear, but not the logs I add to my Windows Service. What makes it more strange is if I restart the Windows Service, the logging starts working.

I've created a GitHub repo of a small project that reproduces this issue if you want to clone it and reproduce the problem yourself.

---

How to tell if it's working

The service should create two files, one that just says "Hello World" and another that contains all the logs. It will be working if the log file has successfully logged the line: Why is this line not logged?

If that line does not appear in the log.txt file then my issue is not solved.

Note: This line will show up if you click the start button in Visual Studio, but I want it to work when I install the service and start the service. It will also work if the service is started, then restarted, but that seems more like a hack than a fix.

---

Project description

This is how I have set up my service. I created a new C# Console Application using .Net Framework 4.6.1 and installed 3 NuGet packages:

<?xml version="1.0" encoding="utf-8"?>
<packages>
  <package id="log4net" version="2.0.8" targetFramework="net461" />
  <package id="Topshelf" version="4.0.4" targetFramework="net461" />
  <package id="Topshelf.Log4Net" version="4.0.4" targetFramework="net461" />
</packages>

I then created the Windows Service:

using log4net.Config;
using System.IO;
using Topshelf;
using Topshelf.HostConfigurators;
using Topshelf.Logging;
using Topshelf.ServiceConfigurators;

namespace LogIssue
{
    public class Program
    {
        public const string Name = "LogIssue";

        public static void Main(string[] args)
        {
            XmlConfigurator.Configure();
            HostFactory.Run(ConfigureHost);
        }

        private static void ConfigureHost(HostConfigurator x)
        {
            x.UseLog4Net();
            x.Service<WindowsService>(ConfigureService);

            x.SetServiceName(Name);
            x.SetDisplayName(Name);
            x.SetDescription(Name);

            x.RunAsLocalSystem();
            x.StartAutomatically();
            x.OnException(ex => HostLogger.Get(Name).Error(ex));
        }

        private static void ConfigureSystemRecovery(ServiceRecoveryConfigurator serviceRecoveryConfigurator) =>
            serviceRecoveryConfigurator.RestartService(delayInMinutes: 1);

        private static void ConfigureService(ServiceConfigurator<WindowsService> serviceConfigurator)
        {
            serviceConfigurator.ConstructUsing(() => new WindowsService(HostLogger.Get(Name)));
            serviceConfigurator.WhenStarted(service => service.OnStart());
            serviceConfigurator.WhenStopped(service => service.OnStop());
        }
    }

    internal class WindowsService
    {
        private LogWriter _logWriter;

        public WindowsService(LogWriter logWriter)
        {
            _logWriter = logWriter;
        }

        internal bool OnStart() {
            new Worker(_logWriter).DoWork();
            return true;
        }

        internal bool OnStop() => true;
    }

    internal class Worker
    {
        private LogWriter _logWriter;

        public Worker(LogWriter logWriter)
        {
            _logWriter = logWriter;
        }

        public async void DoWork() {
            _logWriter.Info("Why is this line not logged?");
            File.WriteAllText("D:\\file.txt", "Hello, World!");
        }
    }
}

and I added the Log4Net config in the app.config:

  <log4net>

    <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
      <file value="D:\log.txt" />
      <appendToFile value="true" />
      <rollingStyle value="Size" />
      <maxSizeRollBackups value="10" />
      <maximumFileSize value="100KB" />
      <staticLogFileName value="true" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
      </layout>
    </appender>

    <appender name="TraceAppender" type="log4net.Appender.TraceAppender">
      <layout type="log4net.Layout.SimpleLayout" />
    </appender>

    <appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
      <mapping>
        <level value="FATAL" />
        <foreColor value="Purple, HighIntensity" />
      </mapping>
      <mapping>
        <level value="ERROR" />
        <foreColor value="Red, HighIntensity" />
      </mapping>
      <mapping>
        <level value="WARN" />
        <foreColor value="Yellow, HighIntensity" />
      </mapping>
      <mapping>
        <level value="INFO" />
        <foreColor value="Green, HighIntensity" />
      </mapping>
      <mapping>
        <level value="DEBUG" />
        <foreColor value="Cyan, HighIntensity" />
      </mapping>
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%message%newline" />
      </layout>
    </appender>

    <root>
      <appender-ref ref="RollingFileAppender" />
      <appender-ref ref="TraceAppender" />
      <appender-ref ref="ColoredConsoleAppender" />
    </root>

  </log4net>

With that out of the way I can run the application.

Problem description

So, what works? Well, I can run the application as a console app through Visual Studio. This way, it all works, specifically the line: _logWriter.Info("Why is this line not logged?"); logs correctly.

When I install the service:

• Building the project in Release mode
• Running Path/To/Service.exe install in an administrator command prompt
• Running Path/To/Service.exe start

The application starts correctly and the two log files are created (D:\file.txt and D:\log.txt) but when I look inside the D:\log.txt file, I see no log for "Why is this line not logged?" and to make it even stranger - restarting the service (Services > Right click LogIssue > Restart) causes all the logging to start working again perfectly.

Also, it's not like the logging is not working entirely. The log file is full of the TopShelf logs, just not the stuff I log from my application.

What am I doing wrong, that is causing it to not log correctly?

If you want to try and reproduce this you can follow the steps outlined above or you can clone the project if you prefer: https://github.com/jamietwells/log-issue.git

Further Info

On further inspection, this is even more confusing than I thought. I was convinced the issue was something to do with the XmlConfigurator.Configure() call being in the wrong place, however when testing I have found:

• when installing the Windows Service, the calls go something like this:

  1. Main
  2. ConfigureHost

• when starting the Windows Service, the calls go something like this:

  1. Main
  2. ConfigureHost
  3. Main
  4. ConfigureHost
  5. ConstructUsing
  6. WhenStarted
  7. OnStart
  8. DoWork

So Main is certainly called (indeed it appears to be called twice!). One possible problem is that OnStart is called from a different thread to Main, but even copying the XmlConfigurator.Configure() call to OnStart such that it is called from the new thread results in the logging not working.

At this point I wonder if anyone has ever got Log4Net working with TopShelf?

Example logs

Here is an example of a log file that I generated when installing the service:

2018-06-12 11:55:20,595 [1] INFO  Topshelf.HostFactory [(null)] - Configuration Result:
[Success] Name LogIssue
[Success] ServiceName LogIssue
2018-06-12 11:55:20,618 [1] INFO  Topshelf.HostConfigurators.HostConfiguratorImpl [(null)] - Topshelf v4.0.0.0, .NET Framework v4.0.30319.42000
2018-06-12 11:55:20,627 [1] DEBUG Topshelf.Hosts.InstallHost [(null)] - Attempting to install 'LogIssue'
2018-06-12 11:55:20,636 [1] INFO  Topshelf.Runtime.Windows.HostInstaller [(null)] - Installing LogIssue service
2018-06-12 11:55:20,642 [1] DEBUG Topshelf.Runtime.Windows.HostInstaller [(null)] - Opening Registry
2018-06-12 11:55:20,642 [1] DEBUG Topshelf.Runtime.Windows.HostInstaller [(null)] - Service path: "D:\github\log-issue\LogIssue\bin\Release\LogIssue.exe"
2018-06-12 11:55:20,643 [1] DEBUG Topshelf.Runtime.Windows.HostInstaller [(null)] - Image path: "D:\github\log-issue\LogIssue\bin\Release\LogIssue.exe"  -displayname "LogIssue" -servicename "LogIssue"
2018-06-12 11:55:20,644 [1] DEBUG Topshelf.Runtime.Windows.HostInstaller [(null)] - Closing Registry
2018-06-12 11:55:22,839 [1] INFO  Topshelf.HostFactory [(null)] - Configuration Result:
[Success] Name LogIssue
[Success] ServiceName LogIssue
2018-06-12 11:55:22,862 [1] INFO  Topshelf.HostConfigurators.HostConfiguratorImpl [(null)] - Topshelf v4.0.0.0, .NET Framework v4.0.30319.42000
2018-06-12 11:55:22,869 [1] DEBUG Topshelf.Hosts.StartHost [(null)] - Starting LogIssue
2018-06-12 11:55:23,300 [1] INFO  Topshelf.Hosts.StartHost [(null)] - The LogIssue service was started.

At this point in the logs, I then restarted the Windows Service, and you can see the logging then started working. Specifically the line Why is this line not logged? is logged this time, but not last time.

2018-06-12 12:09:43,525 [6] INFO  Topshelf.Runtime.Windows.WindowsServiceHost [(null)] - [Topshelf] Stopping
2018-06-12 12:09:43,542 [6] INFO  Topshelf.Runtime.Windows.WindowsServiceHost [(null)] - [Topshelf] Stopped
2018-06-12 12:09:45,033 [1] INFO  Topshelf.HostFactory [(null)] - Configuration Result:
[Success] Name LogIssue
[Success] ServiceName LogIssue
2018-06-12 12:09:45,055 [1] INFO  Topshelf.HostConfigurators.HostConfiguratorImpl [(null)] - Topshelf v4.0.0.0, .NET Framework v4.0.30319.42000
2018-06-12 12:09:45,071 [1] DEBUG Topshelf.Runtime.Windows.WindowsHostEnvironment [(null)] - Started by the Windows services process
2018-06-12 12:09:45,071 [1] DEBUG Topshelf.Builders.RunBuilder [(null)] - Running as a service, creating service host.
2018-06-12 12:09:45,072 [1] INFO  Topshelf.Runtime.Windows.WindowsServiceHost [(null)] - Starting as a Windows service
2018-06-12 12:09:45,074 [1] DEBUG Topshelf.Runtime.Windows.WindowsServiceHost [(null)] - [Topshelf] Starting up as a windows service application
2018-06-12 12:09:45,076 [5] INFO  Topshelf.Runtime.Windows.WindowsServiceHost [(null)] - [Topshelf] Starting
2018-06-12 12:09:45,076 [5] DEBUG Topshelf.Runtime.Windows.WindowsServiceHost [(null)] - [Topshelf] Current Directory: D:\github\log-issue\LogIssue\bin\Release
2018-06-12 12:09:45,076 [5] DEBUG Topshelf.Runtime.Windows.WindowsServiceHost [(null)] - [Topshelf] Arguments: 
2018-06-12 12:09:45,078 [5] INFO  LogIssue.Worker [(null)] - Why is this line not logged?
2018-06-12 12:09:45,083 [5] INFO  Topshelf.Runtime.Windows.WindowsServiceHost [(null)] - [Topshelf] Started

Answer 1

I have solved the issue. Or rather, someone called Kvarv solved the issue a year ago here: https://github.com/Topshelf/Topshelf/issues/206#issuecomment-312581963

The problem

Basically, when running path/to/exe start in a command prompt window TopShelf will start two instances of the application.

The first instance will be to do some setting up and configuration, and the second instance will be the actual Windows Service we want to start and keep running.

Because both are run simultaneously, there is a race condition introduced for whoever can get to the log file and lock it first. This means either TopShelf will log or your application will log, depending on whoever locks the file first.

How this explains what we're seeing

If TopShelf locks the log file first, the application doesn't log.

I realised I could fix the logging if I put a 1 second delay in before starting the service, but didn't realise until now why. The first instance has already completed it's configuration, is done with the log file and the lock expires, then my application can come along and configure its logging and write to the file.

I also realised we could restart the service and have it suddenly start working and logging. I don't know this is the case but I would be willing to bet when restart is called TopShelf behaves differently and doesn't start up the second instance of the program, it just calls OnStop, then OnStart. If anyone has move information of the behaviour of TopShelf when the service is restarted I would be interested to know.

It also explains how the problem doesn't seem to reproduce for everyone. Race conditions give different results on different hardware.

The solution

There are several solutions that appear to fix the issue.

1. On the TopShelf issue linked above the first suggestion is to install the service using the PowerShell module:

   Start-Service <serviceName>
   

   We could also use sc start <serviceName> if in the command prompt rather than PowerShell

   This doesn't seem to start the multiple instances and lock the file, resulting in a more consistent and predictable experience when compared to the other method of starting the service by doing:

   path/to/exe start
   

2. We could make sure the logging locks the file for as small a time as possible to reduce the chance of a deadlock. This would have performance implications when using the logging but it would solve the problem. We could simply add:

   <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
   

   to the RollingFileAppender in the App.config.

3. We could also add the one second delay to the OnStart method to give the first instance time to complete.

4. We could also change how Log4Net is configured so they do not fight over the file. This is the solution I went for. In the log4net section in the App.config file I had added:

   <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
        <file value="D:\log.txt" />
   

   but simply changing it to:

   <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
        <file type="log4net.Util.PatternString" value="D:\Logs\%processid.log" />
   

   will result in the log file being named using the ID of the process that's currently running. This way each instance gets its own log file and the locking issue is no more.

Note

It appears that including XmlConfigurator.Configure(); as one of the first lines in Main() is important somehow. I'm still not fully understanding why this is important but it could be because as far as I can tell: x.UseLog4Net(); doesn not call XmlConfigurator.Configure();, however HostLogger.Get(Name)) does. This can be seen in the TopShelf source (function CreateLogWriterFactory).

Answer 2

For clarity here goes all the code listed by file name:

assemblyinfo.cs (add this to code already there):

[assembly: log4net.Config.XmlConfigurator(ConfigFile = "Log4Net.config", Watch = true)]

app.config (add this to a default config generated by the framework):

  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
  </configSections>
  <log4net configSource="Log4Net.config"/>

Log4Net.config (there's more here but i removed it as it's not relevant to the question here):

<log4net>
  <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
    <file value="D:\log.txt" />
    <appendToFile value="true" />
    <rollingStyle value="Size" />
    <maxSizeRollBackups value="10" />
    <maximumFileSize value="100KB" />
    <staticLogFileName value="true" />
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
    </layout>
  </appender>
  <root>
    <appender-ref ref="RollingFileAppender" />
  </root>
</log4net>

Program.cs:

using Topshelf;
using Topshelf.HostConfigurators;
using Topshelf.Logging;
using Topshelf.ServiceConfigurators;

namespace LogIssue
{
    public class Program
    {
        public const string Name = "LogIssue";

        public static void Main(string[] args)
        {
            HostFactory.Run(ConfigureHost);
        }

        private static void ConfigureHost(HostConfigurator x)
        {
            x.Service<WindowsService>(ConfigureService);

            x.SetServiceName(Name);
            x.SetDisplayName(Name);
            x.SetDescription(Name);

            x.RunAsLocalSystem();
            x.StartAutomatically();
            x.OnException(ex => HostLogger.Get(Name).Error(ex));
        }

        private static void ConfigureSystemRecovery(ServiceRecoveryConfigurator serviceRecoveryConfigurator) =>
            serviceRecoveryConfigurator.RestartService(delayInMinutes: 1);

        private static void ConfigureService(ServiceConfigurator<WindowsService> serviceConfigurator)
        {
            serviceConfigurator.ConstructUsing(() => new WindowsService());
            serviceConfigurator.WhenStarted(service => service.OnStart());
            serviceConfigurator.WhenStopped(service => service.OnStop());
        }
    }
}

WindowsService.cs:

using log4net;

namespace LogIssue
{
    internal class WindowsService
    {
        static ILog _log = LogManager.GetLogger(typeof(WindowsService));

        internal bool OnStart() {
            new Worker().DoWork();
            return true;
        }

        internal bool OnStop() => true;
    }
}

Worker.cs:

using log4net;
using System.IO;

namespace LogIssue
{
    internal class Worker
    {
        static ILog _log = LogManager.GetLogger(typeof(Worker));

        public void DoWork() {
            _log.Info("Why is this line not logged?");
            File.WriteAllText("D:\\file.txt", "Hello, World!");
        }
    }
}

EDIT:

Instructions:

1. either of these ...
   • download this from github (https://github.com/jamietwells/log-issue)
   • create a new project and ...
     • add the references for topshelf and log4net
     • copy the code above in to the relevant files
2. F5 to build and run.
3. Note 2 files created on root of D drive
4. stop running, delete 2 files
5. open command line as admin
6. enter commands as shown below to go to the directory and tell it to install service
7. go to service manager "services.msc" and note "LogIssue" service is listed
8. click to start the service
9. note files have been re created, open both for results below

Here are my results (click on the image to zoom in) ...

It's worth noting at this point that the log call made in worker.cs may not output immediately to the logs mainly because of "flushing" to files which log4net does on a regular basis after a certain number of log statements has been collected or the logs container has gone out of scope and is due to be de-constructed.

This can result in seemingly the logging call not having been made when the code is deployed to a server.

we can test this by modifying the service above to regularly "dispose of" the worker class and build a new one like so ...

using log4net;
using System.Timers;

namespace LogIssue
{
    internal class WindowsService
    {
        static ILog _log = LogManager.GetLogger(typeof(WindowsService));
        readonly Timer _timer = new Timer(1000);

        public WindowsService() =>  _timer.Elapsed += (s, e) => new Worker().DoWork();

        internal void OnStart() =>  _timer.Start();

        internal void OnStop() => _timer.Stop();
    }
}