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

Question

tl;dr

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

我已经创建了一个小型项目的GitHub repo，如果你想克隆它并自己重现问题，那么它就会重现这个问题。

How to tell if it's working

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

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

注意：如果单击Visual Studio中的“开始”按钮，将显示此行，但我希望在安装服务并启动服务时它能够正常工作。如果服务启动然后重新启动它也会起作用，但这看起来更像是一个黑客而不是修复。

Project description

这就是我设置服务的方式。我使用.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>

有了这个，我可以运行应用程序。

Problem description

什么有用？好吧，我可以通过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

Further Info

经过进一步检查，这比我想象的更令人困惑。我确信这个问题与XmlConfigurator.Configure()呼叫在错误的地方有关，但是在测试时我发现：

安装Windows服务时，调用如下所示：主要 ConfigureHost
启动Windows服务时，调用如下所示：主要 ConfigureHost 主要 ConfigureHost ConstructUsing WhenStarted 的OnStart 做工作

所以Main肯定被称为（事实上它似乎被称为两次！）。一个可能的问题是从一个不同的线程调用OnStart到Main，但是甚至将XmlConfigurator.Configure()调用复制到OnStart，以便从新线程调用它会导致日志记录无效。

在这一点上，我想知道是否有人让Log4Net与TopShelf合作？

Example logs

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

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:githublog-issueLogIssueinReleaseLogIssue.exe"
2018-06-12 11:55:20,643 [1] DEBUG Topshelf.Runtime.Windows.HostInstaller [(null)] - Image path: "D:githublog-issueLogIssueinReleaseLogIssue.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:githublog-issueLogIssueinRelease
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

另一答案

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

tl;dr

How to tell if it's working

Project description

Problem description

Further Info

Example logs

The problem

How this explains what we're seeing

The solution

Note