为什么我的 Windows 服务在服务重新启动之前没有记录

Question

tl;博士

我使用 TopShelf 创建了一个 Windows 服务，使用 Log4Net 添加了日志记录，然后构建项目，安装服务并启动服务。然后我的服务运行良好，但没有记录。 TopShelf 日志会出现，但不会出现我添加到 Windows 服务的日志。更奇怪的是，如果我重新启动 Windows 服务，日志记录就会开始工作。

我创建了一个小项目的GitHub repo，如果您想克隆它并自己重现该问题，该项目会重现此问题。

---

如何判断它是否工作

该服务应创建两个文件，一个仅显示“Hello World”，另一个包含所有日志。如果日志文件已成功记录以下行，它将起作用：Why is this line not logged?

如果log.txt 文件中没有出现该行，那么我的问题没有解决。

注意：如果您单击 Visual Studio 中的开始按钮，则会显示此行，但我希望它在我安装服务并启动服务时工作。如果服务启动，然后重新启动，它也可以工作，但这似乎更像是一个 hack 而不是修复。

---

项目说明

这就是我设置服务的方式。我使用 .Net Framework 4.6.1 创建了一个新的 C# Console Application 并安装了 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 服务 时，调用如下所示：

  1. 主要
  2. 配置主机

• 当启动 Windows 服务 时，调用如下所示：

  1. 主要
  2. 配置主机
  3. 主要
  4. 配置主机
  5. 构造使用
  6. 何时开始
  7. 开机
  8. 做工作

所以Main 肯定被调用了（实际上它似乎被调用了两次！）。一个可能的问题是 OnStart 从不同的线程调用到 Main，但即使将 XmlConfigurator.Configure() 调用复制到 OnStart 以便从新线程调用它也会导致日志记录不起作用。

此时我想知道是否有人曾让 Log4Net 与 TopShelf 一起工作？

示例日志

这是我在安装服务时生成的日志文件示例：

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 服务，您可以看到日志记录开始工作。特别是这次记录了 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 行为的移动信息，我很想知道。

它还解释了该问题似乎并不适用于所有人。竞争条件在不同的硬件上给出不同的结果。

解决办法

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

1. 关于上面链接的 TopShelf 问题，第一个建议是使用 PowerShell 模块安装服务：

   Start-Service <serviceName>
   

   我们也可以在命令提示符中使用sc start <serviceName> 而不是PowerShell

   这似乎不会启动多个实例并锁定文件，与通过以下方式启动服务的其他方法相比，会产生更加一致和可预测的体验：

   path/to/exe start
   

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

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

   到App.config中的RollingFileAppender。

3. 我们还可以在OnStart 方法中添加一秒延迟，以给第一个实例时间来完成。

4. 我们还可以更改 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）。

Answer 2

为了清楚起见，这里是按文件名列出的所有代码：

assemblyinfo.cs（将其添加到已经存在的代码中）：

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

app.config（将此添加到框架生成的默认配置中）：

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

Log4Net.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>
  <root>
    <appender-ref ref="RollingFileAppender" />
  </root>
</log4net>

程序.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!");
        }
    }
}

编辑：

说明：

1. 其中任何一个...
   • 从 github (https://github.com/jamietwells/log-issue) 下载这个
   • 创建一个新项目并...
     • 添加 topshelf 和 log4net 的引用
     • 将以上代码复制到相关文件中
2. F5 构建并运行。
3. 注意2文件在D盘根目录下创建
4. 停止运行，删除2个文件
5. 以管理员身份打开命令行
6. 输入如下命令进入目录并告诉它安装服务
7. 转到服务管理器“services.msc”并注意“LogIssue”服务已列出
8. 点击启动服务
9. note 文件已重新创建，打开两者查看以下结果

这是我的结果（点击图片放大）...

此时值得注意的是，worker.cs中的日志调用可能不会立即输出到日志中，主要是因为log4net在收集到一定数量的日志语句后会定期“刷新”到文件中或者日志容器已经超出范围并且将被解构。

这可能会导致在将代码部署到服务器时似乎没有进行日志记录调用。

我们可以通过修改上面的服务来定期“处理”工人类并像这样构建一个新的类来测试这一点......

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();
    }
}