Знакомимся с ‘log enrichment’

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

В этой статье мы рассмотрим, как можно “обогатить” или дополнить лог-сообщения дополнительным контекстом. Примечание: в таких библиотеках, как Serilog и ряде других, используется термин “log enrichment”, который дословно можно перевести как “обогащение”, хотя в статье будем в основном использовать термин “дополнение”.

По сути концепция “обогащения” или дополнения логгируемых данных вращается вокруг возможности регистрировать дополнительный контекст (или данные), который будет записан вместе с логгируемыми данными. Этот контекст может быть чем угодно: строкой, экземпляром класса или любым примитивным типом данных. Вместе с тем, такой контекст обычно “появляется” в ходе выполнения программы не в тот момент и не в том месте кода, где логгируется некие данные. То есть, его нельзя или неудобно просто добавить в качестве параметра к операции логгирования. Кроме того, этот контекст может быть уместен для записи с последующими операциями логгирования. Например, в рамках обработки одного запроса.

Такой контекст может даже содержать определенные условия для записи – например, должен сохранятся только при логгировании исключений.

В этой статье будет использован Serilog и его реализация log enrichment (дополнение или обогащение логов), поскольку в Serilog этот функционал сделан очень гибким. Другие инструменты логгирования предоставляют схожий функционал, и мы сравним реализацию Serilog с тем, что доступно “из коробки” в Microsoft.Extensions.Logging.

Обзор существующих реализаций log enrichment в Serilog

Таких реализаций довольно много, и они подходят для ряда сценариев. На этой странице – https://github.com/serilog/serilog/wiki/Enrichment – дан их список и краткое описание.

Например, есть LogContext и GlobalLogContext, который позволяют зарегистрировать дополнительные данные для логгирования в рамках определенной области действия (scope). LogContext по своей сути очень похож на то, что предоставляют logging scopes из Microsoft.Extensions.Logging. По сути, обе эти реализации регистриуют дополнительный контекст, который будет сохранен со всеми последующими операциями логгирования, и возвращают объект типа IDisposable. При вызове его метода Dispose этот дополнительный контекст будет удален, и станет недоступен для логгирования.

В документации Serilog и Microsoft есть такие примеры:

// For Serilog log.Information("No contextual properties");  using (LogContext.PushProperty("A", 1)) {     log.Information("Carries property A = 1");      using (LogContext.PushProperty("A", 2))     using (LogContext.PushProperty("B", 1))     {         log.Information("Carries A = 2 and B = 1");     }      log.Information("Carries property A = 1, again"); }  // For Microsoft.Extensions.Logging scopes using (logger.BeginScope(new List<KeyValuePair<string, object>> {     new KeyValuePair<string, object>("TransactionId", transactionId), })) {     _logger.LogInformation(MyLogEvents.GetItem, "Getting item {Id}", id);     todoItem = await _context.TodoItems.FindAsync(id);     if (todoItem == null) {         _logger.LogWarning(MyLogEvents.GetItemNotFound,             "Get({Id}) NOT FOUND", id);              return NotFound();     } }

Эти реализации довольно ограничены, хотя и полезны в ряде сценариев. Они наилучшим образом подходят при логгировании в разнообразных middleware и декораторах, когда область действия четко определена, дополнительный контекст уже существует и при выходе из области действия утрачивает смысл.

Например, эти реализации можно использовать для привязки correlation id ко всем операциям логгирования в рамках обработки HTTP запроса.

GlobalLogContext похож на LogContext с той разницей, что его область действия глобальна: все операции логгирования в рамках приложения будут дополнены его данными. Однако, его практическое применение еще более ограничено.

Пример реализации для Serilog

Написать свою реализацию дополнения логов для Serilog очень просто: достаточно реализовать интерфейс ILogEventEnricher и зарегистрировать эту реализацию в конфигурации Serilog. Интерфейс предоставляет всего один метод – Enrich, принимающий параметр типа LogEvent, который ему и надо “обогатить” дополнительными данными.

Давайте рассмотрим пример такой реализации:

public sealed class CustomLogEnricher : ILogEventEnricher {     private readonly IHttpContextAccessor contextAccessor;          public CustomLogEnricher(IHttpContextAccessor contextAccessor) {         this.contextAccessor = contextAccessor;     }          public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) {         var source = contextAccessor.HttpContext?.RequestServices.GetService<ICustomLogEnricherSource>();         if (source is null) {             return;         }          var loggedProperties = source.GetCustomProperties(logEvent.Level);         foreach (var item in loggedProperties) {             var property = item.ProduceProperty(propertyFactory);             logEvent.AddOrUpdateProperty(property);         }     } }

Эта реализация полагается на ICustomLogEnricherSource для получения дополнительных данных для логгирования. Обычно конкретные реализации ILogEventEnricher являются долгоживущими объектами и регистрируются как синглтоны – то есть, при запуске приложения, и их время жизни совпадает с временем жизни приложения.

То есть, реализации “обогащения” логов и регистрации дополнительного контекста нужно разнести, потому что у них обычно будут разная область действия и время жизни.

public sealed class CustomLogEnricherSource : ICustomLogEnricherSource {     private readonly Dictionary<string, CustomLogEventProperty> properties = new();          public ICustomLogEnricherSource With<T>(string property, T? value, LogEventLevel logLevel) where T : class {         if (value is null) {             return this;         }              properties[property] = new CustomLogEventProperty(property, value, logLevel);              return this;     }          public void Remove(string property) {         properties.Remove(property);     }          public IEnumerable<CustomLogEventProperty> GetCustomProperties(LogEventLevel logLevel) {         foreach (var item in properties.Values) {             if (item.Level <= logLevel) {                 yield return item;             }         }     } }  // CustomLogEventProperty - это простая структура (но может быть и классом при необходимости): public struct CustomLogEventProperty {     private LogEventProperty? propertyValue;          public CustomLogEventProperty(string property, object value, LogEventLevel level) {         Name = property;         Value = value;         Level = level;     }          public string Name { get; }          public object Value { get; }          public LogEventLevel Level { get; }          public LogEventProperty ProduceProperty(ILogEventPropertyFactory propertyFactory) {         propertyValue ??= propertyFactory.CreateProperty(Name, Value, destructureObjects: true);         return propertyValue;     } }

У этой реализации есть несколько простых моментов:

• реализации “обогащения” и регистрации контекста разделены – как указано выше, у них, скорее всего, будет разное время жизни. Кроме того, в сложном приложении может быть несколько объектов, отвечающих за регистрацию дополнительного контекста.

• ICustomLogEnricherSource может быть внедрен как зависимость в те компоненты, которым нужно регистрировать дополнительные данные для логгирования. В идеале, срок жизни этой зависимости должен быть ограниченным, потому что эта реализация не предоставляет удобного способа “удаления” дополнительного контекста.

• Сделана простая логика фильтрации дополнительного контекста, основанная на уровне логгирования. Однако, тут можно реализовать куда более сложную логику, опирающуюся на остальные свойства объекта LogEvent и на глобальное состояние приложения.

• CustomLogEventProperty сохраняет результат, произведенный функцией ILogEventProperty.CreateProperty, что позволяет переиспользовать его при логгировании нескольких сообщений.

Еще один важный момент – это параметр destructureObjects на строке 44:

propertyFactory.CreateProperty(Name, Value, destructureObjects: true);

Когда мы регистрируем сложные объекты, классы, структуры, коллекции и т.п., и этот параметр не установлен в true, Serilog использует метод ToString на таких объектах в качестве механизма сериализации. И если records по умолчанию переопределяют этот метод для вывода всех публичных свойств объекта, и мы можем предоставить аналогичную реализацию для наших классов и структур, полагаться на него все равно не будет лучшим решением.

Кроме того, такая сериализация не поддерживает структурное логгирование (structured logging), поскольку преобразует объект в строку, что не позволит в дальнейшем воспользоваться стандартными средствами поиска и фильтрации по свойствам объекта. Поэтому здесь этот параметр устанавливается в true. Для примитивных типов значение этого параметра не имеет значения.

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

Как это может помочь с разделением кода, отвечающего за логгирование, и бизнес- и инфраструктурного кода

В идеальном сценарии код логгирования должен быть полностью отделен от инфрастуктурного кода и кода бизнес логики. Этого разделения можно достичь с помощью разнообразныз декораторов, middleware и других шаблонов, которые позволят “обернуть” код бизнес логики кодом, отвечающим за логгирование.

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

При таком подходе код бизнес логики и инфраструктурный код не будут ничего “знать” про само логгирование, хотя все же будут иметь некоторую зависимость, связанную с логгированием.

В любом случае, такой код будет менее связанным (less coupling) и более тестируемым. Можно даже предоставить абстракцию вроде NullLogEnricherSource с пустой реализацией, которая может оказаться полезной в наиболее требовательных с точки зрения производительности сценариях.

Влияние на производительность

Как отмечено в документации Microsoft:

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

То есть, когда мы дополняем лог-сообщения контекстом, нужно учитывать влияние на производительность. В общем, механизм “обогащения”, предоставленный Serilog, достаточно производителен – как минимум, сопоставим по производительности с реализацией logging scopes, данной Microsoft. Но нужно учитывать, что чем больше дополнительного контекста есть в лог-сообщения, тем дороже будет их запись.

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

Ниже приведены результаты простого бенчмарка, показывающие производительность и потребление памяти при использовании как Serilog, так и logging scopes Microsoft. Каждый проход бенчмарка записывает 20 сообщений в логи, используя разные методы “обогащения”.

Без обогащения:

| Method                               | Mean      | Error    | StdDev   | Gen0   | Allocated | | SerilogLoggingNoEnrichment           |  74.22 us | 1.194 us | 1.116 us | 1.2207 |  21.25 KB | | MicrosoftLoggingNoEnrichment         |  72.58 us | 0.733 us | 0.685 us | 1.2207 |  21.25 KB |

С тремя дополнительными строками:

Method                               | Mean      | Error    | StdDev   | Gen0   | Allocated | | SerilogLoggingWithContext            |  77.47 us | 0.551 us | 0.516 us | 1.7090 |   28.6 KB | | SerilogLoggingWithEnrichment         |  79.89 us | 1.482 us | 2.028 us | 1.7090 |  29.75 KB | | MicrosoftLoggingWithEnrichment       |  81.86 us | 1.209 us | 1.131 us | 1.8311 |  31.22 KB 

С тремя дополнительными сложными объектами (records):

| Method                               | Mean      | Error    | StdDev   | Gen0   | Allocated | | SerilogLoggingWithObjectContext      | 108.49 us | 1.193 us | 1.058 us | 5.3711 |  88.18 KB | | SerilogLoggingWithObjectEnrichment   | 106.07 us | 0.489 us | 0.409 us | 5.3711 |  89.33 KB | | MicrosoftLoggingWithObjectEnrichment |  99.63 us | 1.655 us | 1.468 us | 6.1035 | 100.28 KB |

Бенчмарки Serilog*Context используют “обогащение” с помощью LogContext.PushProperty; бенчмарки Serilog*Enrichment используют приведенный выше код CustomLogEnricherSource; а бенчмарки Microsoft* используют logging scopes.

Можно видеть, что производительность и потребление памяти очень близки в большинстве случаев, и использование сложных объектов стоит дороже, чем примитивных типов. Единственное исключение – это использование records с logging scopes от Microsoft.

Эта разница связана с тем, что реализация Microsoft использует метод ToString для сериализации сложных объектов, что делает ее несколько быстрее в данном случае, но и потребляет больше памяти. Logging scopes не “деструктурируют” сложные объекты при сериализации.

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

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

Примечание: исходный код бенчмарков и примеров из статьи доступен на GitHub.

Заключение

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

Этот дополнительный контекст может быть чем угодно: строкой, примитивным типом или сложным объектом (включая анонимные типы). Контекст производится кодом бизнес логики или инфраструктурным кодом.

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

Полезные ссылки

О механизме “обогащения” в Serilog: https://github.com/serilog/serilog/wiki/Enrichment

О logging scopes от Microsoft: https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-8.0#log-scopes

Код из этой статьи: https://github.com/dmitry-slabko/log-enrichment-pub