Русский
Русский
English
Статистика
Реклама

Log

Новый подход к просмотру логов

25.01.2021 00:11:48 | Автор: admin

Одно время, приходилось много работать с логами. Они могли быть большими и находиться на разных серверах. Требовалось не найти что-то конкретное, а понять почему система ведёт себя не так как надо. По некоторым причинам, лог-агрегатора не было.

Хотелось иметь просмотрщик логов, позволяющий, в любой момент, открыть любой файл, без скачивания на локальную машину, как команда less в linux консоли. Но при этом, должна быть удобная подсветка текста, как в IDE, и фильтрация записей по различным параметрам. Фильтрация и поиск должны работать по событиям в логе, а не по строкам, как grep, это важно когда есть многострочные записи, например ошибки со стектрейсами. Так же должна быть возможность просматривать записи сразу из нескольких файлов на одной странице, смёржив их по таймстемпу, даже если файлы находятся на разных нодах.

И я придумал как сделать такую утилиту!

Log Viewer - это небольшое web-приложение, которое работает на нодах, где лежат логи, и показывает эти логи через Web интерфейс. Это именно просмотрщик, а не агрегатор, нет никакой индексации или считывания всего лога в память, читается только та часть лога, которую пользователь смотрит в текущий момент. Такой подход позволяет почти не занимать ресурсов.

Предвижу вопросы опроизводительности типа Разве можно быстро фильтровать записи без индексации? Вплохих случаях придётся остcканировать весь лог чтобы найти хоть одну запись подходящую под фильтр. Вопервых, сканирование лога работает довольно быстро, 1Гб читается около 3,5сек, это терпимо. Вовторых, обычно известен временной интервал, вкотором ищем проблему, если задан фильтр подате, тобудет сканироваться только тачасть файла, вкоторой находятся записи относящиеся ктому времени. Найти границу временного интервала вфайле можно очень быстро бинарным поиском.

Отображение лога

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

Обратите внимание настектрейс эксепшена, показаны только самые интересные строки, остальные сфолжены под + и , интересными строками считаются классы изпакетов принадлежащий главному приложению, соседнии сними, ипервая строка. Пакеты главного приложения задаются вконфигурации. Втаком виде стектрейс занимает намного меньше места наэкране иего удобней смотреть. Возможно такая идея понравится разработчикам Java IDE.

Имя логгера тоже сокращено: ~.SecurityManager. Показывается только имя класса, апакет сворачивается в ~.

Фолдинг влияет только на отображение, поиск работает по оригинальному тексту. Если совпадение найдётся в сокращённой части текста, то эта часть текста автоматически появится. Также, если пользователь выделит текст и нажмёт Ctrl+C, в буфер скопируется исходный текст, без всяких сокращений.

Архитектура позволяет легко навешивать на текст подсветку или всплывающие подсказки, благодаря этому, сделаны разные приятные мелочи типа показа даты в человеческом формате, если она напечатана в виде числа:

Фильтрация

Набор фильтров зависит от формата лога. Некоторые фильтры доступны всегда, например фильтр по подстроке, а некоторые появляются если в логе присутствует поле определённого типа. Это позволяет создавать специализированные фильтры для некоторых типов полей. Например, если в логе есть поле severity, то в верхней панельке появится такой UI компонент:

Severity filter

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

Добавление фильтров из контекстного меню

Можно кликнуть назапись ивыбрать Скрыть последующие записи или Скрыть предыдущие записи, чтобы работать только сопределённой частью лога. Скрытие происходит добавлением фильтра подате.

Для сложных случаев можно задать фильтр с условием написанным на JavaScript. Такой фильтр представляет из себя функцию принимающую одну записи и возвращающую true или false.

Пример фильтра на JavaScript
function isVisibleEvent(text, fields) {    var match = text.match(/Task completed, elapsed time: (\d+)ms$/)    if (!match)        return false // Don't show events not matched the pattern            var time = parseInt(match[1])    return time > 500 // Show only events where elapsed time is more than a threshold}

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

Состояние панели фильтров отображается в параметрах URL, чтобы можно было добавить в закладки браузера текущую конфигурацию.

Мелкие, но полезные фичи

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

Если сервер расположен в другой таймзоне, над текстом с датой будет всплывающая подсказка с датой в таймзоне пользователя.

Конфигурация

Я старался сделать конфигурацию как можно проще, чтобы всё работало из коробки. Если попросить пользователя задать формат лога, то большинство просто закроют приложение и пойдут смотреть по старинке. Поэтому формат лога распознаётся автоматически. Конечно, это работает не всегда и часто не точно. Для таких случаев можно задать формат лога вручную в файле конфигурации. Можно использовать паттерны log4j, logback или просто регексп. Если ваш лог не распознался, но вам кажется что должен создайте issue на GitHub, этим вы поможете проекту.

Самая нужная настройка список видимых файлов. Поумолчанию доступны все файлы срасширением .log ивидна вся структура каталогов, ноэто неочень хорошо сточки зрения секьюрити. Вконфигурационном файле можно ограничить видимость файлов спомощью списка паттернов типа такого:

logs = [  {    path: "/opt/my-app/logs/*.log"  },  {    path: ${HOME}"/work/**"  }]

Пользователю будут доступны только .log файлы в директории /opt/my-app/logs и любые файлы в директории ~/work и её поддиректориях.

Более подробная информация в документации на GitHub.

Работа с несколькими нодами

Мёрж файлов, расположенных наразных нодах это киллер фича, ради которой изатевался проект. Как яуже говорил, файл никогда нескачивается полностью содной ноды надругую инеиндексируется. Поэтому, накаждой изнод должен быть запущен Log Viewer. Пользователь открывает webUI наодной изнод, указывает расположение логов, иLog Viewer коннектится кдругим инстансам LogViewer чтобы подгружать содержимое лога через них. Записи извсех открытых файлов мёржатся потаймстемпу ипоказываются как буд-то это один файл.

Вкрадце опишу как это работает под капотом. Когда пользователь открывает страницу, надо показать конец лога, для этого накаждую ноду отправляется запрос дай последниеN записей, где N количество строк помещающихся наэкран. Полученные записи сортируются потаймстемпу, берутся последниеN записей ипоказываются пользователю. Когда пользователь скролит страницу вверх, навсе ноды посылается запрос дай последниеN записей стаймстемпом меньшеT, где T таймстемп самой верхней записи наэкране. Полученные записи сортируются идобавляются настраницу. При скроле вниз происходит тоже самое, только вдругую сторону. Поиск позиции вфайле, где находятся записи старше/младше T,работает очень быстро, так как записи отсортированы потаймстемпу иможно использовать бинарный поиск. Там есть много нюансов, нообщая схема такая. Мёрж работает только если система смогла определить фомат лога ивкаждой записи задан полный тайстемп.

Наданный момент, нетUI для выбора файлов наразных нодах, приходится прописывать файлы впараметрах URL втаком виде:
http://localhost:8111/log?path=/opt/my-app/logs/a.log@hostname1&path=/opt/my-app/logs/b.log@hostname1&path=/opt/my-app/logs/c.log@hostname2
здесь каждый параметр "path" задаёт один файл, после "@" указывается хост, накотором лежит файл изапущен инстанс просмотрщика логов. Можно указать несколько хостов через запятую. Если "@" отсутствует файл находится натекущей ноде. Чтобы неиметь дела согромными URL, есть возможность задать короткие ссылки вконфигурации, вразделе log-paths = { }.

Встраивание просмотрщика в своё приложение

Log Viewer можно подключить ксвоему Java Web приложению как библиотеку, чтобы оно могло показывать пользователю свои логи. Иногда это удобней чем запуск отдельным приложением. Достаточно просто добавить зависимость на библиотеку библиотеку черезMaven/Gradle иподключить один конфигурационный класс вspring context. Всё остальное сконфигурится автоматически, log viewer сам распознает какая система логгирования используется ивозьмёт изеёконфигурации расположение иформат логов. ПоумолчаниюUI маппится на/logs, новсё можно кастомизировать. Пока автоматическая конфигурация работает только сLog4j иLogback.

Это тестировалось на маленьком количестве приложений, если у вас возникнут проблемы смело пишите в discussions на GitHub.

Что планируется сделать в будущем

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

Есть много идей по мелкому улучшению UI. Например, если в тексте встретился кусок JSON, то хочется чтобы просмотрщик умел показывать его в отформатированном виде, а не одной строкой. Хочется иметь возможность задать фильтр по severity для отдельного класса, а не сразу для всех.

Иногда нет возможности открыть порт на сервере для просмотра логов, есть только SSH доступ. Можно сделать поддержку работы через SSH. Web UI будет подниматься на локальной машине, коннектиться через SSH к серверу и запускать там специального агента. Агент будет принимать команды через input stream и возвращать нужные части лога через output stream.

Буду рад услышать фидбэк.

Подробнее..

Страсти по Serilog .NET Core Глобальный логгер

04.04.2021 12:12:21 | Автор: admin

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.

Статистика популярности log4net и NLog 2012-2014 гг.Статистика популярности log4net и NLog 2012-2014 гг.

График на 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 + .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-8Test 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
Запуск тестов вместе 1
Test 1 of 2Test 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
Запуск тестов вместе 2
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-8Test 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: ошибка на этапе конфигурирования сервисов. В этом тесте ошибка происходит при конфигуировании сервисов приложения.

//Arrangevar 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();}//Actvar resp = await client.SendAsync(new HttpRequestMessage(HttpMethod.Get, "/ping"));//AssertAssert.True(resp.IsSuccessStatusCode);

Лог:

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

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

//Arrangevar 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();}//Actvar resp = await client.SendAsync(new HttpRequestMessage(HttpMethod.Get, "/ping"));//AssertAssert.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 .

Заключение

Статистика популярности log4net, NLog и Serilog 2013-2021 гг.Статистика популярности log4net, NLog и Serilog 2013-2021 гг.

График на 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.

Подробнее..
Категории: C , Net , Net core , Logging , Log , Logger , Serilog

Категории

Последние комментарии

  • Имя: Макс
    24.08.2022 | 11:28
    Я разраб в IT компании, работаю на арбитражную команду. Мы работаем с приламы и сайтами, при работе замечаются постоянные баны и лаги. Пацаны посоветовали сервис по анализу исходного кода,https://app Подробнее..
  • Имя: 9055410337
    20.08.2022 | 17:41
    поможем пишите в телеграм Подробнее..
  • Имя: sabbat
    17.08.2022 | 20:42
    Охренеть.. это просто шикарная статья, феноменально круто. Большое спасибо за разбор! Надеюсь как-нибудь с тобой связаться для обсуждений чего-либо) Подробнее..
  • Имя: Мария
    09.08.2022 | 14:44
    Добрый день. Если обладаете такой информацией, то подскажите, пожалуйста, где можно найти много-много материала по Yggdrasil и его уязвимостях для написания диплома? Благодарю. Подробнее..
© 2006-2024, personeltest.ru