Все мы знаем, что логирование - вещь очень полезная для современного проекта. С помощью него можно быстро локализовать и устранить ошибку в продукте, восстановить кейс, который к ней привёл, посмотреть историю действий пользователя.
Существует несколько видов логирования, такие как:
Классическое - когда весь лог это набор строк, в котором порой сложно разобраться и что-то в нём проанализировать.
_logger.LogInformation($"The magic number is {number}");
Структурное - когда на одно событие будет создаваться две записи лога, одна запись это шаблон вывода сообщения, вторая запись - объект, который будет подставлен в шаблон.
_logger.LogInformation("The magic number is {number}", number);
Структурное логирование открывает возможности хранить и анализировать события в различного рода хранилищах, таких как NoSql, Sql базах данных. Для .NET существует множество сторонних библиотек для такого логирования, например Serilog или NLog.
Давайте рассмотрим, как воспользоваться одной из этих библиотек и начать вести лог правильно????
Классическое логирование
Создадим новый проект по шаблону ASP.NET Core Web API. По умолчанию после создания мы будем иметь такую структуру решения:
Изменим метод 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();
}
Запустим приложение и выполним GET запрос к http://localhost:7005/weatherforecast?city=Moscow&day=1 и посмотрим результат выполнения в консоли:
Видно, что запись события это просто строка, и куда бы она ни попала (файл, СУБД, журнал событий) - она так и останется строкой, из которой что-то значимое для анализа можно будет вытащить только с помощью регулярных выражений, как пример. Такой вариант мало кого устраивает и на помощь приходит структурное логирование.
Структурное логирование
Теперь изменим немного проект, который создали выше. Для его модификации будем использовать библиотеку Serilog.
Установим NuGet-пакеты Serilog, Serilog.Sinks.Console и Serilog.Extensions.Hosting.
В файле 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();
/*
.....................................
*/
В методе Get контроллера WeatherForecast изменим запись в лог:
_logger.LogInformation("Requested weather for city {City} on {Day} day", city, day);
Мы убрали интерполяцию строки и теперь значения city и day по порядку будут подставляться вместо якорей {City} и {Day} в шаблоне.
Снова запустим приложение и выполним 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)
rezedent12
24.01.2023 09:29-4Я такое уже изобрёл около десяти лет назад. А конкретно добавил в нужные функции прибавление к глобальной строковой переменной подстроки и убирание в точках выхода из функции.
YegorP
24.01.2023 09:39+2Я не совсем понимаю зачем в структурных логах что-то шаблонизировать и подставлять. Простые смертные на это не смотрят, а эльфам вполне понятно
{ "msg": "weather requested", "tempC": 1, "tempF": 33 }
, даже меньше места занимает и грепать проще. Ну то есть само сообщение можно оставить статической строкой.
Kiel
Можно добавить логирование в middleware всех входящих/исходящих реквестов, а бизнес логику покрывать юнит тестами. Это сильно повысит читаемость кода и уберёт ILogger из всех мест приложения
YegorP
... вместе с паролями, токенами и файлами на пару гигабайт.
... и кусать локти пытаясь диагностировать любые непредвиденные кейсы.
Aspect-oriented programming вам в помощь, но только не в виде мидлвари на самом входе и на самом выходе.
Kiel
Не пишите в логи файлы, это ни к чему. С паролями да - нужно будет кастомный атрибут добавить и исключить подробное логирование критически важны методов
и кусать локти пытаясь диагностировать любые непредвиденные кейсы.
Согласен, зачем юнит тесты )))) Давайте логирование во все места засунем )))
YegorP
То есть не всё так просто, как "добавить логирование в middleware всех входящих/исходящих реквестов", да? Про замену юнит-тестов логированием я ничего не говорил.
Kiel
Не вижу ничего сложного, какие то нюансы будут всегда, а код это почистит основательно во всех проектах, коих может быть легион (мой максимум одновременной поддержки - 13)
nronnie
Логгирование "вручную" на самом деле нужно очень и очень редко. Единственное что действительно необходимо логгировать это какие-то исключительные ситуации в приложении, а это делается автоматически самим фреймворком и настройками конфигурации логгера. Раздражает, когда видишь в исходниках в каждом методе
_logger.LogInformation("Start method blablabla.")
и_logger.LogInformation("End method blablabla.")
- совершенно бессмысленнный мусор и в исходниках и в логах.nronnie
Логгирование в файл может быть полезно при разработке и локальном тестировании.