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
Releasemode - Running
Path/To/Service.exe installin 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:
- Main
- ConfigureHost
when starting the Windows Service, the calls go something like this:
- Main
- ConfigureHost
- Main
- ConfigureHost
- ConstructUsing
- WhenStarted
- OnStart
- 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
