Serilog — на данный момент, пожалуй, самая популярная библиотека логирования для .NET.  Зародилась эта библиотека ещё до появления платформы .NET Core, в которой разработчики платформы предложили своё видение подсистемы логирования приложения. В 2017 году Serilog создаёт библиотеку для интеграции в подсистему логирования .NET Core.

В этой серии статей мы пристально рассмотрим и проанализируем проблемы использования Serilog в .NET Core  и постараемся ответить на вопрос — как их решить? 

В данной статье мы разберёмся с тем, какую роль в логировании играет глобальный логгер из библиотеки Serilog  при интеграции Serilog в подсистему логирования .NET Core. А также выявим возможные проблемы и пути их решения.

Введение

В феврале 2013 года на github.com появился проект Opi, который уже через 6 дней получил знакомое имя Serilog. Этот проект изначально разрабатывался под .NET Framework 4.5. На момент его разработки, платформа .NET не предлагала из коробки никакого встроенного API логирования. На тот момент самыми популярными инструментами для решения этой задачи были NLog и log4net.

График на google trends.

Ещё до официального выхода первой версии .NET Core (27.06.2016) уже шли разговоры о поддержке этой платформы (как, например, тут). Сейчас уже сложно разобраться в подробностях тех времён и как начиналась поддержка .Net Core. Ясность наступает в августе 2017, когда на github.com был создан проект serilog-aspnetcore. Он изначально был разработан под .NET Standard 2.0, т.е. уже поддерживал использование в проектах .NET Core 2.0.

Но это была не переработка под .NET Core, а интеграция инструментов основной библиотеки Serilog в подсистему логирования .NET Core. Эта интеграция не подразумевала пересмотра подсистемы логирования Serilog через призму подходов, которые предлагает платформа .NET Core, как для расширения API логирования, так и для взаимодействия компонент приложения.

Предисловие

При написании статьи эксперименты проводились на платформе .NET Core 3.1. Модульные тесты написаны под xUnit. Для анализа использовались исходники актуальных на момент написания статьи версий библиотек Serilog:

• Serilog v2.10.0 https://github.com/serilog/serilog.git

• Serilog.AspNetCore v4.0.0 https://github.com/serilog/serilog-aspnetcore.git

• Serilog.Extensions.Logging v3.0.1 https://github.com/serilog/serilog-extensions-logging.git

• Serilog.Extensions.Hosting v4.1.1 https://github.com/serilog/serilog-extensions-hosting.git

Интеграция Serilog + .NET Core

В 100% случаев, когда Я сталкивался с применением Serilog, это был код одного из его примеров.

public static int Main(string[] args)
{
    Log.Logger = new LoggerConfiguration()
        .WriteTo.Console()
        .CreateBootstrapLogger();

    Log.Information("Starting up!");

    try
    {
        CreateHostBuilder(args).Build().Run();

        Log.Information("Stopped cleanly");
        return 0;
    }
    catch (Exception ex)
    {
        Log.Fatal(ex, "An unhandled exception occured during bootstrapping");
        return 1;
    }
    finally
    {
        Log.CloseAndFlush();
    }
}

public static IHostBuilder CreateHostBuilder(string[] args) =>
    Host.CreateDefaultBuilder(args)
    .UseSerilog((context, services, configuration) => configuration
                .ReadFrom.Configuration(context.Configuration)
                .ReadFrom.Services(services)
                .Enrich.FromLogContext()
                .WriteTo.Console())
    .ConfigureWebHostDefaults(webBuilder => { webBuilder.UseStartup<Startup>(); });

В этом примере мы видим, как разработчики Serilog предлагают его использовать:

• метод Main:

  • создаём глобальный статический логгер и конфигурируем для вывода в консоль. Это временно, пока не будет применена конфигурация приложения;

  • сообщаем о запуске приложения через глобальный логгер

  • запускаем хост приложения;

  • сообщаем об успешном останове приложения через глобальный логгер;

  • при необходимости логируем ошибку запуска приложения через глобальный логгер;

  • закрываем и флашим глобальный логгер;

• метод CreateHostBuilder:

  • интегрируем и конфигурируем Serilog, в том числе с помощью конфигурации приложения.

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

Далее в сервисах приложения, в контроллерах, если это вэб приложение, которые создаются с применением DI, можно получить логгер из подсистемы логирования .NET Core, записать туда лог и он попадёт в логгер Serilog и будет записан в соответствии с конфигурацией, определённой в методе CreateHostBuilder.

Глобальный логгер — Как это работает?

Как написано в примере Program.cs перед инициализацией статического логгера:

The initial «bootstrap» logger is able to log errors during start-up. It's completely replaced by the logger configured in UseSerilog() below, once configuration and dependency-injection have both been set up successfully.

Т.е. инициализируется глобальный логгер, который действует до успешного вызова UseSerilog() при создании HostBuilder приложения. После чего он будет заменён на логгер, собранный в соответствии с конфигурацией приложения.

Глобальный логгер в Serilog - свойство Logger статического класса  Log с get и set. Имеет значение по умолчанию — объект типа SilentLogger, который ничего никуда не пишет:

public static class Log
{
    static ILogger _logger = SilentLogger.Instance;

    /// <summary>
    /// The globally-shared logger.
    /// </summary>
    /// <exception cref="ArgumentNullException">When <paramref name="value"/> is <code>null</code></exception>
    public static ILogger Logger
    {
        get => _logger;
        set => _logger = value ?? throw new ArgumentNullException(nameof(value));
    }
    ...
}

Теперь исследуем UseSerilog и где назначается глобальный логгер.

Проходим в UseSerilog — это где-то там назначается глобальный логгер. Что делает этот метод:

• определяет, можно ли переконфигурировать текущий глобальный логгер. Нужно переконфигурировать (перезагрузить в терминах кода), если верны все условия:

  • глобальный логгер является логгером, который можно переконфигурировать после его создания, т.е. он наследуется от ReloadableLogger;

  • входной параметр preserveStaticLogger (не трогать статический (читай глобальный) логгер) == false;

• если необходимо «перезагрузить» глобальный логгер, то для дальнейших целей используется переконфигурированный глобальный логгер. В противном случае на основе конфига приложения создаётся новый логгер;

• далее, в зависимости от необходимости сохранить глобальный логгер (вх параметр preserveStaticLogger), для интеграции в подсистему логирования .NET Core используется полученный на предыдущем этапе логгер, если глобальный логгер надо сохранить. И в противном случае заменяется глобальный логгер на полученный на предыдущем этапе, а для интеграции вместо логгера передаётся null, что потом приведёт к тому, что вместо конкретного переданного для интеграции логгера будет использоваться глобальный логгер.

По умолчанию preserveStaticLogger==false, поэтому глобальный статический логгер по умолчанию заменяется. Как это происходит:

• в фабрику логгеров Serilog передаётся неопределённый логгер (т.е. null). Эта фабрика интегрируется во встроенную в .NET Core подсистему логирования, как фабрика логгеров;

• в фабрике создаётся поставщик логгеров Serilog и туда передаётся логгер — тоже null. Этот поставщик используется фабрикой, чтобы предоставить объект логгера, реализующий платформенный интерфейс Microsoft.Extensions.Logging.ILogger;

• поставщик логгеров создаёт и предоставляет платформенный логгер Serilog для интеграции во встроенную систему логирования .NET Core. В этот объект передаётся логгер Serilog , т.е. опять null;

• в платформенном логгере Serilog  в конструкторе происходит выбор используемого логгера Serilog : если в качестве логгера передан null, то в дальнейшем в качестве логгера Serilog будет использоваться глобальный статический логгер из Log.Logger. И уже этот объект будет использоваться для логирования непосредственно в методе логирования этого платформенного логгера Serilog : тут и тут.

Эффект «нескольких логгеров»

Разработчики Serilog предлагают смешанный подход к использованию Serilog в .NET Core приложениях:

• через стандартную встроенную .NET Core подсистему логирования;

• с использованием глобального логгера через свойство Logger публичного статического класса Serilog.Log.

При этом встраивание Serilog в .NET Core предусматривает принципиально разные комбинации конфигурирования Serilog в зависимости от способа доступа к нему:

• чтобы логи через глобальный логгер писались так же, как через интегрированный в .NET Core (когда используется один и тот же объект — preserveStaticLogger==false) — как в конфигурации приложения

• чтобы логи через глобальный логгер писались как инициировано в самом начале (в примере — в консоль), а интегрированный в .NET Core — как в конфигурации приложения (preserveStaticLogger==true)

Таким образом, есть возможность получить две разные подсистемы логирования в пределах одного приложения просто перепутав входной параметр preserveStaticLogger. И поскольку логи — это то, с помощью чего разбираются с багами, то с таким логированием эту проблему будет сложно найти.

Но всё не так плохо. Параметр preserveStaticLoggerпо умолчанию false. А это значит, если ничего специально не делать, логгер при обоих способах логирования будет один и будет иметь одну и ту же конфигурацию.

Проблемы с тестированием

Так как глобальный логгер хранится в статическом свойстве класса, то это единый объект на домен приложения. Инициализируется для коллекции сервисов, поэтому, если в рамках одного домена приложения будет создано несколько коллекций сервисов и инициализирована подсистема логирования, то в глобальном логгере будет конфигурация последнего из них и все логи от всех сервисов этих коллекций будут писаться через него. Такая проблема, например, возникает в модульных тестах.

Проверим это! Для этого понадобится вспомогательные классы.

Тестовый логгер

Тестовый логгер, который пишет в тестовый output лог-сообщение и добавляет в него префикс:

class TestLogger : Serilog.ILogger
{
    private readonly string _prefix;
    private readonly ITestOutputHelper _output;

    public TestLogger(string prefix, ITestOutputHelper output)
    {
    	_prefix = prefix;
    	_output = output;
    }
    public void Write(LogEvent logEvent)
    {
    	_output.WriteLine(_prefix + " " +  logEvent.MessageTemplate.Render(logEvent.Properties));
    }
}

Отправитель запросов

Вспомогательный класс по отправке запроса тестовому приложению, запущенному прямо в тесте. Нужен для того, чтобы меньше дублировать код в тестах:

class ConcurrentLoggingTestRequestSender
{
    private readonly WebApplicationFactory<Startup> _webAppFactory;
    private readonly ITestOutputHelper _output;
    private readonly string _logPrefix;

    public ConcurrentLoggingTestRequestSender(WebApplicationFactory<Startup> webAppFactory, ITestOutputHelper output, string logPrefix)
    {
        _webAppFactory = webAppFactory;
        _output = output;
        _logPrefix = logPrefix;
    }

    public async Task<HttpResponseMessage> Send()
    {
        var client = _webAppFactory.WithWebHostBuilder(b => b.UseSerilog(
        	(context, config) => config
        		.WriteTo.Logger(new TestLogger(_logPrefix, _output))
        )).CreateClient();

        return await client.SendAsync(new HttpRequestMessage(HttpMethod.Get, "/ping"));
    }
}

В методе Send инициируется приложение с добавлением Serilog и логированием в тестовый логгер.

Тесты

Тесты минимальны, почти одинаковы и отличаются только префиксом в выводимых лог-сообщениях.

Тест1:

public class ConcurrentLoggingTest_1of2 : IClassFixture<WebApplicationFactory<Startup>>
{
    private readonly ConcurrentLoggingTestRequestSender _requestSender;
    private readonly ITestOutputHelper _output;

    public ConcurrentLoggingTest_1of2(WebApplicationFactory<Startup> waf, ITestOutputHelper output)
    {
        _output = output;
    	_requestSender = new ConcurrentLoggingTestRequestSender(waf, output, "==1==");
    }

    [Fact]
    public async Task Test()
    {
        _output.WriteLine("Test 1 of 2");
        _output.WriteLine("");
        var resp = await _requestSender.Send();

        Assert.True(resp.IsSuccessStatusCode);
    }
}

Тест2:

public class ConcurrentLoggingTest_2of2 : IClassFixture<WebApplicationFactory<Startup>>
{
    private readonly ConcurrentLoggingTestRequestSender _requestSender;
    private readonly ITestOutputHelper _output;

    public ConcurrentLoggingTest_2of2(WebApplicationFactory<Startup> waf, ITestOutputHelper output)
    {
        _output = output;
    	_requestSender = new ConcurrentLoggingTestRequestSender(waf, output, ">>2<<");
    }

    [Fact]
    public async Task Test()
    {
        _output.WriteLine("Test 2 of 2");
        _output.WriteLine("");
        var resp = await _requestSender.Send();

        Assert.True(resp.IsSuccessStatusCode);
    }
}

Результаты тестирования

Test 1 of 2

==1== Application started. Press Ctrl+C to shut down.
==1== Hosting environment: "Development"
==1== Content root path: "C:\Users\ozzye\Documents\prog\my\serilog-poke\src\SerilogPoke"
==1== Request starting HTTP/1.1 GET http://localhost/ping  
==1== Executing endpoint '"SerilogPoke.Controllers.PingController.Ping (SerilogPoke)"'
==1== Route matched with "{action = \"Ping\", controller = \"Ping\"}". Executing controller action with signature "Microsoft.AspNetCore.Mvc.IActionResult Ping()" on controller "SerilogPoke.Controllers.PingController" ("SerilogPoke").
==1== Executing ObjectResult, writing value of type '"System.String"'.
==1== Executed action "SerilogPoke.Controllers.PingController.Ping (SerilogPoke)" in 13.1068ms
==1== Executed endpoint '"SerilogPoke.Controllers.PingController.Ping (SerilogPoke)"'
==1== Request finished in 76.8507ms 200 text/plain; charset=utf-8


Test 2 of 2

>>2<< Application started. Press Ctrl+C to shut down.
>>2<< Hosting environment: "Development"
>>2<< Content root path: "C:\Users\ozzye\Documents\prog\my\serilog-poke\src\SerilogPoke"
>>2<< Request starting HTTP/1.1 GET http://localhost/ping  
>>2<< Executing endpoint '"SerilogPoke.Controllers.PingController.Ping (SerilogPoke)"'
>>2<< Route matched with "{action = \"Ping\", controller = \"Ping\"}". Executing controller action with signature "Microsoft.AspNetCore.Mvc.IActionResult Ping()" on controller "SerilogPoke.Controllers.PingController" ("SerilogPoke").
>>2<< Executing ObjectResult, writing value of type '"System.String"'.
>>2<< Executed action "SerilogPoke.Controllers.PingController.Ping (SerilogPoke)" in 15.2088ms
>>2<< Executed endpoint '"SerilogPoke.Controllers.PingController.Ping (SerilogPoke)"'
>>2<< Request finished in 78.8673ms 200 text/plain; charset=utf-8

Test 1 of 2

Test 2 of 2

>>2<< Application started. Press Ctrl+C to shut down.
>>2<< Application started. Press Ctrl+C to shut down.
>>2<< Hosting environment: "Development"
>>2<< Hosting environment: "Development"
>>2<< Content root path: "C:\Users\ozzye\Documents\prog\my\serilog-poke\src\SerilogPoke"
>>2<< Content root path: "C:\Users\ozzye\Documents\prog\my\serilog-poke\src\SerilogPoke"
>>2<< Request starting HTTP/1.1 GET http://localhost/ping  
>>2<< Request starting HTTP/1.1 GET http://localhost/ping  
>>2<< Executing endpoint '"SerilogPoke.Controllers.PingController.Ping (SerilogPoke)"'
>>2<< Executing endpoint '"SerilogPoke.Controllers.PingController.Ping (SerilogPoke)"'
>>2<< Route matched with "{action = \"Ping\", controller = \"Ping\"}". Executing controller action with signature "Microsoft.AspNetCore.Mvc.IActionResult Ping()" on controller "SerilogPoke.Controllers.PingController" ("SerilogPoke").
>>2<< Route matched with "{action = \"Ping\", controller = \"Ping\"}". Executing controller action with signature "Microsoft.AspNetCore.Mvc.IActionResult Ping()" on controller "SerilogPoke.Controllers.PingController" ("SerilogPoke").
>>2<< Executing ObjectResult, writing value of type '"System.String"'.
>>2<< Executing ObjectResult, writing value of type '"System.String"'.
>>2<< Executed action "SerilogPoke.Controllers.PingController.Ping (SerilogPoke)" in 13.5891ms
>>2<< Executed action "SerilogPoke.Controllers.PingController.Ping (SerilogPoke)" in 13.5891ms
>>2<< Executed endpoint '"SerilogPoke.Controllers.PingController.Ping (SerilogPoke)"'
>>2<< Executed endpoint '"SerilogPoke.Controllers.PingController.Ping (SerilogPoke)"'
>>2<< Request finished in 78.0903ms 200 text/plain; charset=utf-8
>>2<< Request finished in 78.0958ms 200 text/plain; charset=utf-8

Test 1 of 2

==1== Application started. Press Ctrl+C to shut down.
==1== Application started. Press Ctrl+C to shut down.
==1== Hosting environment: "Development"
==1== Hosting environment: "Development"
==1== Content root path: "C:\Users\ozzye\Documents\prog\my\serilog-poke\src\SerilogPoke"
==1== Content root path: "C:\Users\ozzye\Documents\prog\my\serilog-poke\src\SerilogPoke"
==1== Request starting HTTP/1.1 GET http://localhost/ping  
==1== Request starting HTTP/1.1 GET http://localhost/ping  
==1== Executing endpoint '"SerilogPoke.Controllers.PingController.Ping (SerilogPoke)"'
==1== Executing endpoint '"SerilogPoke.Controllers.PingController.Ping (SerilogPoke)"'
==1== Route matched with "{action = \"Ping\", controller = \"Ping\"}". Executing controller action with signature "Microsoft.AspNetCore.Mvc.IActionResult Ping()" on controller "SerilogPoke.Controllers.PingController" ("SerilogPoke").
==1== Route matched with "{action = \"Ping\", controller = \"Ping\"}". Executing controller action with signature "Microsoft.AspNetCore.Mvc.IActionResult Ping()" on controller "SerilogPoke.Controllers.PingController" ("SerilogPoke").
==1== Executing ObjectResult, writing value of type '"System.String"'.
==1== Executing ObjectResult, writing value of type '"System.String"'.
==1== Executed action "SerilogPoke.Controllers.PingController.Ping (SerilogPoke)" in 12.7648ms
==1== Executed action "SerilogPoke.Controllers.PingController.Ping (SerilogPoke)" in 12.7649ms
==1== Executed endpoint '"SerilogPoke.Controllers.PingController.Ping (SerilogPoke)"'
==1== Executed endpoint '"SerilogPoke.Controllers.PingController.Ping (SerilogPoke)"'
==1== Request finished in 78.428ms 200 text/plain; charset=utf-8
==1== Request finished in 78.4282ms 200 text/plain; charset=utf-8

Test 2 of 2

Вывод по тестированию

Так как логгер глобальный и один на все тесты, а тесты выполняются параллельно, то после инициализации веб-приложения в каждом тесте, в качестве глобального логгера остаётся тот логгер, который был присвоен статическому полю Serilog.Log.Logger позже. Поскольку сдвиг по времени в работе тестов непредсказуем, то в разных случаях глобальным становится логгер из разных тестов.

Поэтому при выполнении кода в тестах надо всегда помнить и использовать при интеграции Serilog в .NET Core (метод UseSerilog())  параметр preserveStaticLogger = true, чтобы при инициализации в каждом тесте подсистемы логирования использовался в каждом случаи свой логгер. При этом будет возникать эффект «нескольких логгеров» с соответствующими последствиями.

Глобальный логгер — где нужен?

При должном подходе, работа всего приложения сводится к взаимодействию объектов, создаваемых и связываемых по средствам DI платформой .NET Core, а точнее объектом хоста, который создаётся в примере при использовании метода CreateHostBuilder. И в этом случае самым подходящим способом логирования было бы использование встроенного механизма логирования.

Однако разработчики Serilogтак же предлагают нам так же использовать глобальный логгер в том месте, где нет DI платформы .NET Core — в методе Main вне области работы объекта хоста:

• Запуск!

• Перехват необработанной ошибки

• Успешное окончание

Запуск!

На данном этапе мы ещё не добрались до конфигурации. Работа с конфигурацией и создание логгера в соответствии с конфигурацией будет позже. Поэтому тут можно иметь дело только с хардкодом. Самые популярные логгеры, которые не требуют конфигурирование — это Console и Debug. Они не требуют конфигурирования, зависящего от окружения и их можно быстро прописать прямо в коде. Эти логгеры выводят сообщения туда, где и так понятно, что приложение запускается:

• в консоли мы в любом случае как-то понимаем, что приложение начало запускаться;

• Debug — ну, это, скорее всего IDE и тут тоже понятно.

Вот и получается, что:

• это не даёт понимания о начале запуска приложения, так как оно уже запущено на этот момент и находится в процессе инициализации прикладных механизмов (инициализация объекта хоста, сервисов, загрузка конфигурации и прочее);

• после успешного запуска хоста веб приложения, хост сам отправит сообщение об успешном запуске:

[01:53:06 INF] Now listening on: http://localhost:5000
[01:53:06 INF] Application started. Press Ctrl+C to shut down.
[01:53:06 INF] Hosting environment: Development
[01:53:06 INF] Content root path: C:\Users\ozzye\Documents\prog\my\serilog-poke\src\SerilogPoke

Вывод:

это лог-сообщение малоинформативное и избыточное

Перехват необработанной ошибки - что получаем?

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

Проведём пару тестов, в которых запустим веб-приложение а консоли и в методе конфигурации сервисов выкинем ошибку.

public class Startup
{
    public void ConfigureServices(IServiceCollection services)
    {
        throw new Exception("Ololo!");

        services.AddControllers();
    }
}

Вывод в консоли:

Теперь закомментируем перехват необработанной ошибки в Main:

public static int Main(string[] args)
{
    Log.Logger = new LoggerConfiguration()
        .WriteTo.Console()
        .CreateBootstrapLogger();

    Log.Information("Starting up!");

    try
    {
        CreateHostBuilder(args).Build().Run();

        Log.Information("Stopped cleanly");
        return 0;
    }
    //catch (Exception ex)
    //{
    //    Log.Fatal(ex, "An unhandled exception occured during bootstrapping");
    //    return 1;
    //}
    finally
    {
        Log.CloseAndFlush();
    }
}

Вывод в консоли:

Вывод:

Даже без логирования через Serilog, необработанное исключение было выведено в консоль.

Перехват необработанной ошибки - что может случиться?

Теперь проведём тесты, в которых обернём запуск веб-приложения в try-catch и используем для логирования глобальный логгер Serilog, который будет выводить сообщения  с префиксом initial, а при запуске веб-приложения установим другой логгер — с префиксом configured.

Тест1: ошибка на этапе конфигурирования сервисов. В этом тесте ошибка происходит при конфигуировании сервисов приложения.

//Arrange
var initialLogger = new TestLogger("initial: ", _output);
var configuredLogger = new TestLogger("configured: ", _output);
HttpClient client;

Log.Logger = initialLogger;

Log.Information("Starting up!");

try
{
    client = _waf.WithWebHostBuilder(
        builder => builder
        	.UseSerilog((context, config) => config
                    .WriteTo.Logger(configuredLogger))
        	.ConfigureServices(collection =>
                           {
                               throw new Exception("Ololo!");
                           })
    ).CreateClient();
}
catch (Exception e)
{
    Log.Fatal(e, "An unhandled exception occured during bootstrapping");
    throw;
}
finally
{
    Log.CloseAndFlush();
}

//Act
var resp = await client.SendAsync(new HttpRequestMessage(HttpMethod.Get, "/ping"));

//Assert
Assert.True(resp.IsSuccessStatusCode);

Лог:

initial:  Starting up!
configured:  An unhandled exception occured during bootstrapping

Тест2: ошибка до инициализации подсистемы логирования .NET Core. В этом тесте ошибка происходит при попытке загрузить отсутствующий конфигурационный файл.

//Arrange
var initialLogger = new TestLogger("initial: ", _output);
var configuredLogger = new TestLogger("configured: ", _output);
HttpClient client;

Log.Logger = initialLogger;

Log.Information("Starting up!");

try
{
    client = _waf.WithWebHostBuilder(
        builder => builder
        	.UseSerilog((context, config) => 
                        	config.WriteTo.Logger(configuredLogger)
                       )
        	.ConfigureAppConfiguration((context, configurationBuilder) => 		
                            configurationBuilder.AddJsonFile("absent.json"))
                    	)
            .CreateClient();
}
catch (Exception e)
{
    Log.Fatal(e, "An unhandled exception occured during bootstrapping");

    throw;
}
finally
{
    Log.CloseAndFlush();
}

//Act
var resp = await client.SendAsync(new HttpRequestMessage(HttpMethod.Get, "/ping"));

//Assert
Assert.True(resp.IsSuccessStatusCode);

Лог:

initial:  Starting up!
initial:  An unhandled exception occured during bootstrapping

Вывод:

В зависимости от места ошибки при запуске приложения, перехваченная ошибка может быть записана в лог разными логгерами:  стартовым (обычно в консоль) или логгером, который создан по конфигурации приложения. Поэтому отсутствие такого сообщения в логах (не в консоли) может говорить о том, что ошибка не произошла или произошла на этапе до готовности подсистемы логирования .NET Core. Т.е. то ли была ошибка, то ли нет. А для вывода необработанного сообщения в консоль не обязательно это делать через логгер.

Успешное окончание

Сообщение об успешном завершении работы приложения по факту логируется ещё до факта завершения приложения. Как минимум, может произойти ошибка при дальнейшем обращении к логгеру с целью его закрыть в блоке finally:

public static int Main(string[] args)
{
    ...
    try
    {
        CreateHostBuilder(args).Build().Run();

        Log.Information("Stopped cleanly");
        return 0;
    }
    catch (Exception ex)
    {
        ...
    }
    finally
    {
        Log.CloseAndFlush();
    }
}

Вывод:

Данное сообщение не соответствует действительности.

Вывод по логированию в Main

Лог-записи о начале запуска приложения и окончании работы приложения — это зона ответственности инфраструктуры, которая запускает и фиксирует факт остановки приложения. Само приложение должно отчитаться о том, что оно успешно запущено и готово к работе, и, возможно, что начинает процедуру останова.

По опыту, ошибки на этапе запуска веб-приложения — это редкая ситуация, которая быстро выявляется и устраняется, потому что при запуске приложения в основном формируется и конфигурируется объектная модель приложения. Самые, наверное, вероятные ситуации:

• нет какой-то библиотеки

• нет конфига

И такие ошибки, конечно, приводят к тому, что приложение завершает свою работу. Поэтому при диагностике проблемы вариантов немного. Как показали тесты, весьма вероятны ситуации, когда на момент необработанной ошибки глобальный логгер будет начальный и запишет сообщение только в консоль. Учитывая, что даже если не логировать необработанное исключение, то оно всё равно будет выведено в консоль, почти так же, как если бы это делал логгер, то польза от данного логирования вызывает сомнения.

Таким образом, делаю вывод, что глобальный логгер в рекомендациях от разработчиков Serilog присутствует не из-за необходимости решить важную задачу, а чтобы как-то оправдать присутствие глобального логгера в .NET Core приложении после подключения Serilog.

Глобальный логгер — Вред

Глобальный логгер — это объект, через который осуществляется логирование в Serilog, присвоенный публичному статическому свойству Logger статического класса Serilog.Log. Это свойство инициализируется при запуске приложения с конфигурацией в коде, а затем второй раз инициализируется при инициализации хоста веб-приложения на основе загруженной конфигурации.

Таким образом это не Singleton в чистом виде. Но в пределах работы веб-приложения он задумывается как единственный глобальный экземпляр.

Проблемы:

• потеря лог-сообщений в модульных тестах. В зависимости от особенностей интеграции Serilog в .NET Core (параметр preserveStaticLogger в методе UseSerilog()) могут возникнуть проблемы:

  • с логированием в логгер из последнего теста

  • эффект «нескольких логгеров»

• по тем же причинам могут не задействоваться средства расширения подсистемы логирования, тестируемые в модульных тестах в составе развёрнутой подсистемы логирования .NET Core и Serilog

• возможность в любой момент использовать Serilog.Log.Logger мимо системы DI от .NET Core, которая реализуется под самыми весомыми предлогами:

  • «это временно»;

  • «а ну чё, и так же работает»;

  • «Я так привык на .NET Framework»;

• как следствие, использование в коде статического сервис-локатора - антипаттерн;

• т.к. статическое свойство Logger изменяемое, то есть вероятность несанкционированного замены логгера в непредназначенных для этого местах. Например, это могут быть временные костыли, которые имеют особенность становиться постоянными;

• в библиотеке присутствует нехарактерное решение для .NET Core. Сильно напоминает антипаттерн Boat Anchor .

Заключение

График на google trends.

Serilog был и есть отличным инструментом. Но он не был переработан и адаптирован в полной мере для .NET Core, поэтому в нём остались механизмы, которые больше характерны для решений на .NET Framework.  Как показывает прогресс, .NET, в виде .NET 5, двигается в направлении архитектуры, взятой из .NET Core.  Поэтому разработчикам Serilog рано или поздно придётся заняться вопросом адаптации более плотно.

К сожалению, простым запросом слияния в github проблему с глобальным логом полностью не решить. Тут требуется глобальный рефакторинг, который может, например включать такие изменения:

• вынести из основной библиотеки Serilog все механизмы,  относящиеся к .NET Framework в отдельную библиотеку на подобии serilog-aspnetcore, которая будет использовать основную библиотеку. И туда перенести в т.ч. класс Serilog.Log. тогда при подключении Serilog к проекту на .NET Core в приложении этот класс не будет доступен;

• в serilog-aspnetcore в методе интеграции Serilog в подсистему логирования .NET Core всегда использовать алгоритм работы, соответствующий тому случаю, если указать вх. параметр preserveStaticLogger = true, т.е. вместо глобального логгера создать новый.

В данной статье мы разобрались с тем, какое место в логировании через Serilog в .NET Core занимает глобальный логгер и какие проблемы он может принести.

В следующих статьях будут разобраны другие особенности интеграции Serilog в .NET Core.