c# - 为什么我的Windows服务在重新启动服务后才记录日志

Question

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服务时，

的调用如下所示:

主

配置主机

启动Windows服务时，调用会如下所示:

主

配置主机

主

配置主机

使用

构造

启动时

OnStart

DoWork

因此 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

Answer 1

我已经解决了这个问题。或者更确切地说，一个叫Kvarv的人在一年前在这里解决了这个问题:https://github.com/Topshelf/Topshelf/issues/206#issuecomment-312581963

问题

基本上，在命令提示符窗口中运行path/to/exe start时，TopShelf将启动该应用程序的两个实例。

第一个实例将进行一些设置和配置，第二个实例将是我们要启动并继续运行的实际Windows服务。

由于两者同时运行，因此引入了竞争条件，任何人都可以进入日志文件并首先锁定它。这意味着TopShelf将记录日志，或者您的应用程序将记录日志，这取决于谁先锁定了文件。

这如何解释我们所看到的

如果TopShelf首先锁定日志文件，则该应用程序不会记录日志。

我意识到，如果我在启动服务之前延迟了1秒钟，就可以修复日志记录，但是直到现在才意识到原因。第一个实例已完成其配置，使用日志文件完成了该操作，并且锁到期，然后我的应用程序可以出现并配置其日志记录并写入该文件。

我还意识到我们可以重新启动该服务，并使它突然开始工作并记录日志。我不知道是这种情况，但是我愿意打赌，当重启被称为TopShelf时，行为会有所不同，并且不会启动程序的第二个实例，它只会调用OnStop，然后调用OnStart。如果有人在重新启动服务时掌握了TopShelf行为的移动信息，我将很想知道。

它还说明了问题似乎并没有为每个人重现。竞争条件在不同的硬件上给出不同的结果。

解决方案

有几种解决方案似乎可以解决此问题。

在第一个建议上方链接的TopShelf问题上，是使用PowerShell模块安装服务:

Start-Service <serviceName>

如果在命令提示符下而不是PowerShell，我们也可以使用sc start <serviceName>
与通过以下方法启动服务的其他方法相比，这似乎无法启动多个实例并锁定文件，从而导致更加一致和可预测的体验:

path/to/exe start

我们可以确保日志记录尽可能短地锁定文件，以减少出现死锁的可能性。使用日志记录时，这可能会对性能产生影响，但可以解决问题。我们可以简单地添加:

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

到App.config中的RollingFileAppender。

我们还可以将一秒钟的延迟添加到OnStart方法中，以使第一个实例有时间完成。

我们还可以更改Log4Net的配置方式，以使它们不会争用该文件。这是我追求的解决方案。在App.config文件的log4net部分中，我添加了:

<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)中看到。