tl;dr
Я создал службу Windows с помощью TopShelf, добавил ведение журнала с помощью Log4Net, а затем создал проект, установил службу и запустил ее. Тогда моя служба работает нормально, но не регистрируется. Появляются журналы TopShelf, но не журналы, которые я добавляю в свою службу Windows. Что делает это более странным, так это то, что если я перезапускаю службу Windows, ведение журнала начинает работать.
Я создал репозиторий GitHub небольшого проекта, который воспроизводит эту проблему, если вы хотите клонировать его и воспроизвести проблему самостоятельно.
Как узнать, работает ли он
Служба должна создать два файла, один из которых просто говорит «Hello World», а другой содержит все журналы. Он будет работать, если файл журнала успешно зарегистрировал строку: Why is this line not logged?
Если эта строка не отображается в файле log.txt, моя проблема не решена.
Примечание. Эта строка появится, если вы нажмете кнопку запуска в Visual Studio, но я хочу, чтобы она работала, когда я устанавливаю службу и запускаю ее. Это также будет работать, если служба запущена, а затем перезапущена, но это больше похоже на взлом, чем на исправление.
Описание Проекта
Вот как я настроил свой сервис. Я создал новое консольное приложение C# с помощью .Net Framework 4.6.1 и установил 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!");
}
}
}
и я добавил конфигурацию 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:\log.txt, я не вижу журнала для "Why is this line not logged?" и, что еще более странно, перезапускаю service (Службы > Щелкните правой кнопкой мыши LogIssue > Перезапустить) заставляет все журналы снова начать работать.
Кроме того, это не похоже на то, что ведение журнала не работает полностью. Файл журнала заполнен журналами TopShelf, но не тем, что я записываю из своего приложения.
Что я делаю неправильно, из-за чего он не регистрируется правильно?
Если вы хотите попробовать воспроизвести это, вы можете выполнить шаги, описанные выше, или вы можете клонировать проект, если хотите: https://github.com/jamietwells/log-issue.git
Дополнительная информация
При дальнейшем рассмотрении это еще более запутанно, чем я думал. Я был убежден, что проблема связана с вызовом XmlConfigurator.Configure() в неправильном месте, однако при тестировании я обнаружил:
при установке службы Windows вызовы выглядят примерно так:
- Main
- Настроить хост
при запуске службы Windows вызовы выглядят примерно так:
- Main
- Настроить хост
- Главный
- Настроить хост
- ConstructUsing
- КогдаНачало
- при запуске
- Выполнять работу
Так что 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
