代码之家 › 专栏 › 技术社区 › Jamie Twells

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

topshelf log4net windows-services c#

Jamie Twells · 技术社区 · 6 年前

DR

我创造了一个 Windows服务 使用顶棚 ,添加了使用 Log4NET ,然后生成项目,安装服务并启动服务。然后我的服务运行良好,但它没有日志记录。这个顶棚显示日志,但不显示我添加到Windows服务的日志。更奇怪的是如果我重新启动 Windows服务 ,日志记录开始工作。

我创造了一个 GitHub repo 一个小项目,如果你想复制这个问题,并复制自己的问题。

如何判断它是否有效

服务应该创建两个文件,一个只显示“hello world”,另一个包含所有日志。如果日志文件已成功记录行,则它将正常工作: Why is this line not logged?

如果该行不出现在 log.txt 我的问题没有解决。

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

项目说明

这就是我如何建立我的服务。我创造了一个新的 C控制台应用程序 使用 .NET框架4.6.1 并安装了3个纽戈包装:

<?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!");
        }
    }
}

我加上了 Log4NET 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>

这样我就可以运行应用程序了。

问题描述

那么,什么有效?好吧,我可以通过控制台应用程序运行这个应用程序 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: 文件, 我看不到木头 对于 "Why is this line not logged?" 让它变得更陌生- 重新启动服务 (services>右键单击logissue>restart)会导致 开始工作的日志记录 再次完美。

而且,日志记录并不是完全工作的。日志文件里全是上层日志,只是 不是我从应用程序中记录的内容 .

我做错了什么,导致它无法正确记录?

如果要尝试复制,可以按照上面概述的步骤进行操作,或者如果愿意,可以克隆项目: https://github.com/jamietwells/log-issue.git

进一步信息

经进一步检查,这比我想象的还要混乱。我确信这个问题和 XmlConfigurator.Configure() 打电话到错误的地方,但是在测试时我发现:

当安装 Windows服务 ,通话内容如下:
1. 主要的
2. 配置主机
启动时 Windows服务 ,通话内容如下:
1. 主要的
2. 配置主机
3. 主要的
4. 配置主机
5. 构造
6. 何时开始
7. 开始时
8. 道沃克

所以 Main 当然是被调用的(实际上它似乎被调用了两次!)一个可能的问题是 OnStart 从不同的线程调用 主要的 ,但即使复制 xmlconfigurator.configure() 打电话给 开始时 这样从新线程调用它将导致日志记录不起作用。

现在我想知道是否有人 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服务 ,您可以看到 日志记录然后开始工作 . 特别是这条线 为什么这一行没有记录? 这次记录,但不是上次。

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

2 回复 | 直到 6 年前

War 6 年前

为了清楚起见,下面列出了按文件名列出的所有代码:

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>

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

windows服务.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!");
        }
    }
}

编辑:

说明:

这两个…
- 从github下载( https://github.com/jamietwells/log-issue )
- 创建新项目并…
  - 添加topshelf和log4net的引用
  - 将上面的代码复制到相关文件中
F5生成并运行。
注意2在d驱动器的根目录上创建的文件
停止运行,删除2个文件
以管理员身份打开命令行
输入如下所示的命令以转到目录并告诉它安装服务
转到服务管理器“services.msc”,注意“logissue”服务已列出
单击以启动服务
已重新创建便笺文件,请在下面的结果中同时打开

这是我的结果(点击图片放大)。

值得注意的是,在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();
    }
}

Jamie Twells 6 年前

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

问题

基本上,跑步时 path/to/exe start 在命令提示窗口中,topshelf将启动应用程序的两个实例。

第一个实例将进行一些设置和配置,第二个实例将是实际的 Windows服务 我们要开始,继续跑。

因为两者都是同时运行的,所以会引入一个竞争条件,供任何人先访问日志文件并锁定它。这意味着要么topshelf将记录,要么您的应用程序将记录,这取决于谁先锁定文件。

这解释了我们所看到的

如果topshelf首先锁定日志文件,则应用程序不会进行日志记录。

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

我也意识到我们可以 重新启动 服务,让它突然开始工作和记录。我不知道是这样,但我愿意打赌,当restart被称为topshelf时,它的行为不同,不会启动程序的第二个实例,它只是调用 OnStop 然后 OnStart . 如果有人在服务期间移动了上直升机的行为信息 重新启动 我很想知道。

这也解释了为什么这个问题似乎并没有为每个人重现。在不同的硬件上,竞争条件会产生不同的结果。

解决方案

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

在上面链接的topshelf问题上,第一个建议是使用 动力壳 模块:
```
Start-Service <serviceName>
```
我们也可以用 sc start <serviceName> 如果在命令提示符下而不是 动力壳

与通过执行以下操作启动服务的其他方法相比,这似乎不会启动多个实例并锁定文件,从而获得更一致和可预测的体验:
```
path/to/exe start
```
我们可以确保日志记录将文件锁定尽可能短的时间,以减少死锁的可能性。这在使用日志记录时会对性能产生影响,但可以解决问题。我们可以简单地补充:
```
<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
```
到 滚动文件 在 App.config 。
我们还可以在 开始时 方法指定第一个实例的完成时间。
我们还可以更改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 )。