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

Идея


Обычные лог-записи состоят из строк и для поиска записи среди массива текста нам приходится использовать регулярные выражение
_logger.Warning("Запись в лог файл. Пост на хабре ID"+postId); 


Структурное логирование хранит записи в виде объектов (структур). Например, с помощью JSON
_logger.Warning("Запись в лог файл. Пост на хабре {ID}", postId); 

Будет сохранено две записи:
  1. Шаблон для конечного вывода строки «Запись в лог файл. Пост на хабре {ID}»
  2. Объект, который будем подставлять в шаблон: {«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 является большой инфраструктурой для сбора и анализа данных, и выходит за тему логирования и данной статьи.

Комментарии (2)


  1. freeAKK
    07.09.2015 11:07

    Добавлю про splunk, там в лог пишешь что-то типа:
    event_type=login, user=alice, client_ip=17.4.5.6

    И потом спланк парсит это и можно делать удобные выборки. Плюс подхода в том, что быстро привыкаешь к таким логам и легко их читать, в случае, когда события похожи:
    event_type=login, success=true, user=alice, client_ip=17.4.5.6
    event_type=login, success=false, user=alice, client_ip=17.4.5.6, reason=«wtf?»

    Но стоит спланк, как космолёт.


  1. Dywar
    08.09.2015 09:54

    Напоминает журнал событий Windows, где у событий тоже есть ID и т.д., по которым есть фильтры.