a-artur Sep 6 2015 at 15:51

Структурное логирование на примере Serilog и Seq

4 min

42K

Структурное логирование делает один небольшой шаг вперед по сравнению с обычными записями.

Идея

Обычные лог-записи состоят из строк и для поиска записи среди массива текста нам приходится использовать регулярные выражение

_logger.Warning("Запись в лог файл. Пост на хабре ID"+postId);

Структурное логирование хранит записи в виде объектов (структур). Например, с помощью JSON

_logger.Warning("Запись в лог файл. Пост на хабре {ID}", postId);

Будет сохранено две записи:

Шаблон для конечного вывода строки «Запись в лог файл. Пост на хабре {ID}»
Объект, который будем подставлять в шаблон: {«ID»:1, type:Number}

Главное преимущество данного подхода заключается в том, что теперь можно хранить объект integer ID в виде отдельного параметра, например в NoSql БД. И осуществлять удобный и быстрый поиск с использованием типизированных операций сравнения вместо написания регулярных выражений.

Serilog

Одной из удобных библиотек .NET, которые поддерживают структурное логирование является Serilog.
Библиотека поддерживает все основные функции логирования, которые есть у log4net, Nlog, и других известных библиотек:

Несколько общепринятых типов записи:
Verbose — самое низкоуровнивое и детальное логирование (например, пришедшие аргументы в метод)
Debug — данные для отладки кода, на один уровень выше Verbose (например, какой метод запускали, и результат выполнения)
Warning — предупреждение для бизнес-процесса, не должно содержать Debug данные (например, запустили расчет зарплат)
Error — ошибка в приложении, которое не ожидали
Fatal — исключительная ошибка останавливающая бизнес процессы приложения (например, перенаправили пользователя в PayPal и оплата покупателя не равна ожидаемой сумме).
Разные типы хранения, называемых в Serilog стоком: текстовый файл, реляционные БД, NoSql БД, Windows Events, http/s запросы, и т.д.
Удобная конфигурация через код, так и через .config файлы

Итак, после установки Serilog Nuget пакета, настраиваем конфигурацию. Сделаем это в коде вместо .config файла.

 var logger = new LoggerConfiguration()
             .MinimumLevel.Verbose() // ставим минимальный уровень в Verbose для теста, по умолчанию стоит Information 
             .WriteTo.ColoredConsole()  // выводим данные на консоль
             .WriteTo.RollingFile(@"C:\Logs\Log-{Date}.txt") // а также пишем лог файл, разбивая его по дате
              // есть возможность писать Verbose уровень в текстовый файл, а например, Error в Windows Event Logs
             .CreateLogger();

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


            logger.Debug("Request for vehicles {Manufature}, {Series}, {ProductionYear}", "BMW", "F02", new DateTime(2015, 1,1));
            // search returns 10 vehicles
            logger.Verbose("Found {FoundVehiclesCount}", 10);

Поскольку мы использовали вывод в консоль и файл, то и результат будет в виде привычной строки.

Одной из удобных особенностей является добавка часто используемых свойств. Для web приложения это может быть сессия пользователя, посещаемый URL, данные браузера. В более общем случае можно добавить версию приложения. Сделать это можно с помощью свойства Enrich и уже встроенных классов, или написать свой.

 var logger = new LoggerConfiguration()
                .Enrich.With<HttpRequestIdEnricher>()
                .Enrich.With<HttpRequestUrlEnricher>()
                .Enrich.With<HttpRequestUserAgentEnricher>()
                .Enrich.With<UserNameEnricher>();
                .Enrich.WithProperty("ApplicationVersion", config.ApplicationVersion)
                .CreateLogger();

Для удобного вывода в консоль или текстовый файл сложных объектов лучше подсказать шаблону Serilog о том, что используем именно сложный объект, а не примитивный тип, добавив символ @. Иначе будет выводится typeof(MyClass).ToSting().


            logger.Debug("We are using anonymous object instead of simple string/integer {@Car}", new {Manufacture="Toyota", Production = new DateTime(2015, 1,1)});

Seq

Приложение Seq приходит на помощь для удобного хранения и поиска структурных логов.
Работает Seq в виде windows сервиса, который принимает REST-запросы, а внутри хранит данные в NoSql БД.

После установки Seq необходимо также добавить в приложение Serilog.Sinks.Seq Nuget пакет. А далее подружить наш Serilog с Seq.

 
            var logger = new LoggerConfiguration()
             .MinimumLevel.Verbose()
             .WriteTo.Seq("http://localhost:5341")
             .CreateLogger();

Теперь можно удобно делать поиск по нашим полям, включая сравнение чисел и дат

Параметры поиска можно сохранять и использовать в других частях приложения. Добавляем Environment в Dashboard

А можно добавить real-time Dashboard отображение ошибок, пришедших именно от приложения «MyApp», версии «1.2.1» и произошедших в методе «Repository.GetUserByIdAndPassword()».

Бизнес требования

Как и любую новую, модную, светящуюся программу надо проверять, задавая вопросы:
«Какую выгоду несет данная программа для бизнеса?», «Какую задачу она решает и за какую цену?».
Часто в отношение логирования цели сводятся к

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

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

С помощью расширений Seq можно информировать о происходящих событиях. К примеру, сразу посылать сообщение программисту/администратору, если случилась критическая ошибка. И отправлять список всех ошибок, произошедших за день или неделю. Настроить расширения можно в разделе Seq -> Settings -> Apps

Минусы структурного логирования

К минусу структурного логирования можно отнести необходимость в определении параметров по которым будет производится поиск. Они же потом будут использоваться для создания NoSql индексов. Если забыли определить параметр, то поиск сводится к старому сканированию строк через регулярные выражения.
Гигантский шаг в этом направлении делает приложение Splunk. Идея заключается в сборе строковых данных, абсолютно любых и в любом формате (логи приложения, события о работе ОС, и т.д.). А далее потрясающее разбиение строки в зависимости от запросов и динамическое построение результата через Map/Reduce. Splunk является большой инфраструктурой для сбора и анализа данных, и выходит за тему логирования и данной статьи.

Tags:

Hubs:

.NET