tl; dr
我已经使用TopShelf创建了Windows服务,使用Log4Net添加了日志记录,然后构建了项目,安装了服务并启动了该服务。然后我的服务运行良好,但未记录日志。将显示TopShelf日志,但不会显示我添加到Windows服务的日志。更奇怪的是,如果我重新启动Windows Service,则日志记录开始工作。
我创建了一个小项目的GitHub repo,如果您要克隆它并自己重现该问题,则会重现此问题。
如何判断它是否在工作
该服务应创建两个文件,一个仅显示“Hello World”,另一个包含所有日志。如果日志文件已成功记录以下行,则它将起作用:Why is this line not logged?
如果该行未出现在log.txt
文件中,那么我的问题无法解决。
注意:如果单击Visual Studio中的“开始”按钮,则会显示此行,但是我希望它在安装服务并启动该服务时起作用。如果先启动服务然后重新启动服务,它也将起作用,但这似乎更像是黑客,而不是修复程序。
项目介绍
这就是我设置服务的方式。我使用.Net Framework 4.6.1创建了一个新的C#控制台应用程序,并安装了3个NuGet软件包:
<?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>
然后,我创建了Windows服务:
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!");
}
}
}
我在app.config中添加了Log4Net配置:
<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>
这样,我就可以运行该应用程序了。
问题描述
那么,什么有效?好了,我可以通过Visual Studio将应用程序作为控制台应用程序运行。这样,都能正常工作,特别是以下行:
_logWriter.Info("Why is this line not logged?");
正确记录 。当我安装服务时:
Release
模式构建项目Path/To/Service.exe install
Path/To/Service.exe start
该应用程序正确启动并创建了两个日志文件(
D:\file.txt
和D:\log.txt
),但是当我查看D:\log.txt
文件时,我看不到"Why is this line not logged?"
的日志并使它变得更加陌生-重新启动服务(服务>右键单击) LogIssue>重新启动)使所有日志再次完美地开始工作。另外,这并不意味着日志记录无法完全正常工作。日志文件中充满了TopShelf日志,只是,而不是我从应用程序中记录的内容。
我在做什么错,导致它无法正确记录?
如果要尝试重现此步骤,可以按照上面概述的步骤进行操作,也可以根据需要克隆该项目:https://github.com/jamietwells/log-issue.git
进一步的信息
进一步检查,这比我想像的还要困惑。我确信问题出在
XmlConfigurator.Configure()
调用在错误的地方,但是在测试时我发现:在安装Windows服务时,
因此
Main
肯定会被调用(实际上它似乎被调用了两次!)。一个可能的问题是,从与OnStart
不同的线程调用了Main
,但是即使将XmlConfigurator.Configure()
调用复制到OnStart
,使得从新线程调用它也导致日志记录无法正常工作。在这一点上,我想知道是否有人曾经与TopShelf一起使用Log4Net?
日志示例
这是我在安装服务时生成的日志文件的示例:
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.
此时,在日志中,我随后重新启动了Windows Service,您可以看到日志记录,然后开始工作。具体来说,这次记录的是
Why is this line not logged?
行,但不是上次记录的。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
最佳答案
我已经解决了这个问题。或者更确切地说,一个叫Kvarv的人在一年前在这里解决了这个问题:https://github.com/Topshelf/Topshelf/issues/206#issuecomment-312581963
问题
基本上,在命令提示符窗口中运行path/to/exe start
时,TopShelf将启动该应用程序的两个实例。
第一个实例将进行一些设置和配置,第二个实例将是我们要启动并继续运行的实际Windows服务。
由于两者同时运行,因此引入了竞争条件,任何人都可以进入日志文件并首先锁定它。这意味着TopShelf将记录日志,或者您的应用程序将记录日志,这取决于谁先锁定了文件。
这如何解释我们所看到的
如果TopShelf首先锁定日志文件,则该应用程序不会记录日志。
我意识到,如果我在启动服务之前延迟了1秒钟,就可以修复日志记录,但是直到现在才意识到原因。第一个实例已完成其配置,使用日志文件完成了该操作,并且锁到期,然后我的应用程序可以出现并配置其日志记录并写入该文件。
我还意识到我们可以重新启动该服务,并使它突然开始工作并记录日志。我不知道是这种情况,但是我愿意打赌,当重启被称为TopShelf时,行为会有所不同,并且不会启动程序的第二个实例,它只会调用OnStop
,然后调用OnStart
。如果有人在重新启动服务时掌握了TopShelf行为的移动信息,我将很想知道。
它还说明了问题似乎并没有为每个人重现。竞争条件在不同的硬件上给出不同的结果。
解决方案
有几种解决方案似乎可以解决此问题。
Start-Service <serviceName>
如果在命令提示符下而不是PowerShell,我们也可以使用
sc start <serviceName>
与通过以下方法启动服务的其他方法相比,这似乎无法启动多个实例并锁定文件,从而导致更加一致和可预测的体验:
path/to/exe start
<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
到
App.config
中的RollingFileAppender。 OnStart
方法中,以使第一个实例有时间完成。 <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
<file value="D:\log.txt" />
但只需将其更改为:
<appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
<file type="log4net.Util.PatternString" value="D:\Logs\%processid.log" />
将导致使用当前正在运行的进程的ID命名日志文件。这样,每个实例都有自己的日志文件,锁定问题不再存在。
笔记
看起来
XmlConfigurator.Configure();
作为Main()
的第一行之一是很重要的。我仍然没有完全理解为什么这很重要,但是可能是因为据我所知:x.UseLog4Net();
不会调用XmlConfigurator.Configure();
,但是HostLogger.Get(Name))
会。可以在TopShelf源代码(函数CreateLogWriterFactory)中看到。
关于c# - 为什么我的Windows服务在重新启动服务后才记录日志,我们在Stack Overflow上找到一个类似的问题: https://stackoverflow.com/questions/50746454/