tl; dr
Я создал Службу Windows с использованием TopShelf , добавил ведение журнала с использованием Log4Net , а затем собрал проект, установил сервис и запустил сервис.Тогда мой сервис работает нормально, но это не логирование.Появляются журналы TopShelf , но не журналы, которые я добавляю в службу Windows.Что еще более странно, если я перезапущу Службу Windows , регистрация начнет работать.
Я создал GitHub repo небольшого проекта, который воспроизводит этопроблема, если вы хотите клонировать ее и воспроизвести проблему самостоятельно.
Как узнать, работает ли он?
Служба должна создать два файла, один из которых просто говорит "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?"); logs правильно .
Когда я устанавливаю службу:
- Сборка проекта в режиме
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 Service вызовы выполняются примерно так:
- Main
- ConfigureHost
при запуске Windows Service , вызовы идут примерно так:
- Main
- ConfigureHost
- Main
- ConfigureHost
- ConstructUsing
- WhenStarted
- OnStart
- DoWork
Так что 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