Почему моя служба Windows не регистрируется, пока служба не будет перезапущена

Question

Почему моя служба Windows не регистрируется, пока служба не будет перезапущена

ТЛ; др

Я создал службу Windows с помощью TopShelf, добавил ведение журнала с помощью Log4Net, а затем собрал проект, установил службу и запустил службу. Тогда мой сервис работает нормально, но это не логирование. Появляются журналы TopShelf, но не журналы, которые я добавляю в службу Windows. Что делает это еще более странным, если я перезагружаю Windows Service, регистрация начинает работать.

Я создал репозиторий 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?" и чтобы сделать его еще более странным - перезапуск службы (Службы> Щелкните правой кнопкой мыши LogIssue>Restart) приводит к тому, что вся регистрация снова начинает работать идеально.

Кроме того, это не так, как ведение журнала не работает полностью. Файл журнала полон журналов TopShelf, но не того, что я регистрирую из своего приложения.

Что я делаю не так, что вызывает неправильную запись?

Если вы хотите попробовать и воспроизвести это, вы можете выполнить шаги, описанные выше, или вы можете клонировать проект, если вы предпочитаете: https://github.com/jamietwells/log-issue.git

Дальнейшая информация

При дальнейшем осмотре это еще более запутанно, чем я думал. Я был убежден, что проблема была связана с XmlConfigurator.Configure() Звоните, находясь не в том месте, однако при тестировании я обнаружил:

при установке службы Windows вызовы выполняются примерно так:
1. Главный
2. ConfigureHost
при запуске службы Windows вызовы выполняются примерно так:
1. Главный
2. ConfigureHost
3. Главный
4. ConfigureHost
5. ConstructUsing
6. WhenStarted
7. OnStart
8. Работай

Так Main безусловно, называется (действительно, кажется, он вызывается дважды!). Одна из возможных проблем заключается в том, что OnStart вызывается из другого потока Main, но даже копирование XmlConfigurator.Configure() позвонить OnStart такое, что это вызвано из нового потока, приводит к тому, что регистрация не работает.

На этом этапе мне интересно, когда-нибудь кто-нибудь работал с TopShelf в 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, и вы можете увидеть, что запись в журнал начала работать. Конкретно линия 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

6

c# windows-services log4net topshelf

Источник

user1830205 07 июн '18 в 16:48

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>

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

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

РЕДАКТИРОВАТЬ:

Инструкции:

любой из этих...
- загрузите это с github ( https://github.com/jamietwells/log-issue)
- создать новый проект и...
  - добавить ссылки на верхнюю полку и 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();
    }
}

4

Источник

user342932 11 июн '18 в 16:44

Другие вопросы по тегам c# windows-services log4net topshelf

user1830205 13 июн '18 в 14:22 2018-06-13 14:22 · Accepted Answer · 2018-06-13 14:22

Я решил проблему. Вернее, кто-то по имени Кварв решил проблему год назад здесь: https://github.com/Topshelf/Topshelf/issues/206

Эта проблема

В основном, когда работает path/to/exe start В окне командной строки TopShelf запустит два экземпляра приложения.

Первый экземпляр будет выполнять некоторую настройку и настройку, а второй экземпляр будет действительной службой Windows, которую мы хотим запустить и продолжить работу.

Поскольку оба запускаются одновременно, введено условие гонки для тех, кто может получить доступ к файлу журнала и заблокировать его первым. Это означает, что либо TopShelf будет регистрировать, либо ваше приложение будет регистрировать, в зависимости от того, кто заблокирует файл первым.

Как это объясняет то, что мы видим

Если TopShelf сначала блокирует файл журнала, приложение не регистрируется.

Я понял, что могу исправить запись, если перед запуском службы добавлю задержку в 1 секунду, но до сих пор не понял, почему. Первый экземпляр уже завершил свою настройку, завершил работу с файлом журнала, и срок действия блокировки истекает, а затем моё приложение может настроить журналирование и выполнить запись в файл.

Я также понял, что мы могли бы перезапустить службу, и она внезапно начала работать и регистрироваться. Я не знаю, что это так, но я был бы готов сделать ставку, когда перезагрузка называется TopShelf ведет себя по-другому и не запускает второй экземпляр программы, он просто вызывает OnStop, затем OnStart, Если у кого-то есть информация о поведении TopShelf при перезапуске службы, мне было бы интересно узнать.

Это также объясняет, как проблема не воспроизводится для всех. Условия гонки дают разные результаты на разных аппаратных средствах.

Решение

Есть несколько решений, которые, кажется, решают проблему.

В связи с проблемой TopShelf, указанной выше, первым предложением является установка службы с помощью модуля PowerShell:
```
Start-Service <serviceName>
```
Мы могли бы также использовать sc start <serviceName> если в командной строке, а не PowerShell
Это не запускает несколько экземпляров и не блокирует файл, что приводит к более согласованному и предсказуемому восприятию по сравнению с другим методом запуска службы:
```
path/to/exe start
```
Мы могли бы убедиться, что протоколирование блокирует файл как можно меньше, чтобы уменьшить вероятность тупика. Это может повлиять на производительность при использовании ведения журнала, но это решит проблему. Мы могли бы просто добавить:
```
<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
```
для RollingFileAppender в App.config,
Мы также можем добавить одну секунду задержки к OnStart метод, чтобы дать первый экземпляр времени для завершения.
Мы также можем изменить настройку Log4Net, чтобы они не боролись за файл. Это решение, которое я выбрал. В разделе log4net в файле App.config я добавил:
```
<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" />
```
приведет к тому, что файл журнала будет назван с использованием идентификатора процесса, который в данный момент выполняется. Таким образом, каждый экземпляр получает свой собственный файл журнала, и проблема блокировки больше не возникает.

Заметка

Похоже, что в том числе XmlConfigurator.Configure(); как одна из первых строк в Main() важно как-то. Я до сих пор не до конца понимаю, почему это важно, но это может быть потому, что, насколько я могу судить: x.UseLog4Net(); не звонит XmlConfigurator.Configure();, тем не мение HostLogger.Get(Name)) делает. Это можно увидеть в источнике TopShelf (функция CreateLogWriterFactory).