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

Существует несколько видов логирования, такие как:

  1. Классическое - когда весь лог это набор строк, в котором порой сложно разобраться и что-то в нём проанализировать.

_logger.LogInformation($"The magic number is {number}");
  1. Структурное - когда на одно событие будет создаваться две записи лога, одна запись это шаблон вывода сообщения, вторая запись - объект, который будет подставлен в шаблон.

_logger.LogInformation("The magic number is {number}", number);

Структурное логирование открывает возможности хранить и анализировать события в различного рода хранилищах, таких как NoSql, Sql базах данных. Для .NET существует множество сторонних библиотек для такого логирования, например Serilog или NLog.
Давайте рассмотрим, как воспользоваться одной из этих библиотек и начать вести лог правильно????

Классическое логирование

  1. Создадим новый проект по шаблону ASP.NET Core Web API. По умолчанию после создания мы будем иметь такую структуру решения:

Структура решения StructureLogging
Структура решения StructureLogging
  1. Изменим метод Get контроллера WeatherForecast, заменив его на следующий код:

public IEnumerable<WeatherForecast> Get(string city, int day)
{
    _logger.LogInformation($"Requested weather for city {city} on {day} day");

    return Enumerable.Range(1, 5).Select(index => new WeatherForecast
    {
        Date = DateTime.Now.AddDays(index),
        TemperatureC = Random.Shared.Next(-20, 55),
        Summary = Summaries[Random.Shared.Next(Summaries.Length)]
    })
    .ToArray();
}
  1. Запустим приложение и выполним GET запрос к http://localhost:7005/weatherforecast?city=Moscow&day=1 и посмотрим результат выполнения в консоли:

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

Видно, что запись события это просто строка, и куда бы она ни попала (файл, СУБД, журнал событий) - она так и останется строкой, из которой что-то значимое для анализа можно будет вытащить только с помощью регулярных выражений, как пример. Такой вариант мало кого устраивает и на помощь приходит структурное логирование.

Структурное логирование

Теперь изменим немного проект, который создали выше. Для его модификации будем использовать библиотеку Serilog.

  1. Установим NuGet-пакеты Serilog, Serilog.Sinks.Console и Serilog.Extensions.Hosting.

  2. В файле Program.cs добавим настройку и добавление Serilog в качестве логгера:

using Microsoft.AspNetCore.Builder;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using Serilog;

var builder = WebApplication.CreateBuilder(args);
/*
.....................................
*/

Log.Logger = new LoggerConfiguration()
    .Enrich.FromLogContext()
    .WriteTo.Console()
    .CreateLogger();

builder.Host.ConfigureLogging(logging =>
{
    logging.AddSerilog();
    logging.SetMinimumLevel(LogLevel.Information);
})
.UseSerilog();

/*
.....................................
*/
  1. В методе Get контроллера WeatherForecast изменим запись в лог:

_logger.LogInformation("Requested weather for city {City} on {Day} day", city, day);

Мы убрали интерполяцию строки и теперь значения city и day по порядку будут подставляться вместо якорей {City} и {Day} в шаблоне.

  1. Снова запустим приложение и выполним GET запрос к http://localhost:7005/weatherforecast?city=Moscow&day=1 и посмотрим результат выполнения в консоли:

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

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

Также можно передавать и более сложные объекты, например пользовательские типы данных.
Единственное, что нужно помнить для сложных объектов - при указании якоря впереди ставится @ {@Weather} для обозначения Serilog'у, что объект пользовательский, либо в пользовательском объекте нужно переопределить метод ToString, дополнив его собственной реализацией.

Снова изменим код метода Get контроллера WeatherForecast:

public IEnumerable<WeatherForecast> Get(string city, int day)
{
    var result = Enumerable.Range(1, 5).Select(index => new WeatherForecast
    {
        Date = DateTime.Now.AddDays(index),
        TemperatureC = Random.Shared.Next(-20, 55),
        Summary = Summaries[Random.Shared.Next(Summaries.Length)]
    })
    .ToArray();

    _logger.LogInformation("Requested weather for city {City} on {Day} day. The weather is {@Weather}", city, day, result.First());

    return result;
}

Затем запустим приложение и выполним GET запрос к http://localhost:7005/weatherforecast?city=Moscow&day=1 и посмотрим результат выполнения в консоли:

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

Сложный объект "разложился" по своим свойствам и в будущем готов для анализа логов(если мы сейчас говорим о чём-то более сложном, чем консоль).
В следующий раз мы разберемся, как воспользоваться структурным логированием в связке с ElasticSearch и увидим, как оно позволяет анализировать логи нашего приложения.

Вывод

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

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


  1. Kiel
    24.01.2023 09:22
    +1

    Можно добавить логирование в middleware всех входящих/исходящих реквестов, а бизнес логику покрывать юнит тестами. Это сильно повысит читаемость кода и уберёт ILogger из всех мест приложения


    1. YegorP
      24.01.2023 09:30
      +1

      добавить логирование в middleware всех входящих/исходящих реквестов

      ... вместе с паролями, токенами и файлами на пару гигабайт.

      а бизнес логику покрывать юнит тестами

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

      уберёт ILogger из всех мест приложения

      Aspect-oriented programming вам в помощь, но только не в виде мидлвари на самом входе и на самом выходе.


      1. Kiel
        24.01.2023 10:04

        Не пишите в логи файлы, это ни к чему. С паролями да - нужно будет кастомный атрибут добавить и исключить подробное логирование критически важны методов

        • и кусать локти пытаясь диагностировать любые непредвиденные кейсы.

        Согласен, зачем юнит тесты )))) Давайте логирование во все места засунем )))


        1. YegorP
          24.01.2023 10:10
          +2

          То есть не всё так просто, как "добавить логирование в middleware всех входящих/исходящих реквестов", да? Про замену юнит-тестов логированием я ничего не говорил.


          1. Kiel
            24.01.2023 10:16
            +1

            Не вижу ничего сложного, какие то нюансы будут всегда, а код это почистит основательно во всех проектах, коих может быть легион (мой максимум одновременной поддержки - 13)


        1. nronnie
          24.01.2023 13:06
          +1

          Логгирование "вручную" на самом деле нужно очень и очень редко. Единственное что действительно необходимо логгировать это какие-то исключительные ситуации в приложении, а это делается автоматически самим фреймворком и настройками конфигурации логгера. Раздражает, когда видишь в исходниках в каждом методе _logger.LogInformation("Start method blablabla.") и _logger.LogInformation("End method blablabla.") - совершенно бессмысленнный мусор и в исходниках и в логах.


        1. nronnie
          24.01.2023 13:56

          Не пишите в логи файлы, это ни к чему.

          Логгирование в файл может быть полезно при разработке и локальном тестировании.


  1. rezedent12
    24.01.2023 09:29
    -4

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


    1. Oceanshiver
      24.01.2023 13:49

      В статье речь не про изобретение структурного логирования же


  1. YegorP
    24.01.2023 09:39
    +2

    Я не совсем понимаю зачем в структурных логах что-то шаблонизировать и подставлять. Простые смертные на это не смотрят, а эльфам вполне понятно { "msg": "weather requested", "tempC": 1, "tempF": 33 }, даже меньше места занимает и грепать проще. Ну то есть само сообщение можно оставить статической строкой.


    1. vabka
      25.01.2023 12:02

      В хранилище оно так и попадёт. Вернее будет статический шаблон и параметры