Более глубокое погружение в обогащение журналов

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

Теперь мы рассмотрим, как обогатить зарегистрированные данные дополнительным контекстом.

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

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

Этот контекст может быть даже условным — например, добавление определенных данных только в сообщения журнала ошибок, в то время как всем остальным сообщениям это не требуется.

Мы будем использовать Serilog и его функцию расширения, поскольку Serilog сделал его очень гибким и мощным. Другие решения также имеют схожие функции на разных уровнях зрелости, и мы сравним возможности Serilog с тем, что Microsoft.Extensions.Logging предоставляет «из коробки».

Обзор существующих обогатителей журналов для Serilog

Serilog поставляется со множеством полезных дополнений, которые могут быть очень полезны в некоторых сценариях. Вы можете посетить эту страницу — https://github.com/serilog/serilog/wiki/Enrichment — чтобы увидеть полный список обогатителей и их описания.

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

Обогатитель LogContext очень похож на концепцию областей журналирования в Microsoft.Extensions.Logging. По сути, они одновременно передают некоторые пользовательские данные и предоставляют объект IDisposable, от которого следует избавиться, чтобы удалить данные из контекста журнала.

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

Документация 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(); } }

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

Например, мы можем использовать его для прикрепления идентификатора корреляции ко всем сообщениям журнала в одной области обработки HTTP-запроса.

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

Образец пользовательского обогатителя журналов для Serilog

На самом деле реализовать собственные обогатители журналов для Serilog очень просто — просто реализуйте интерфейс ILogEventEnricher и зарегистрируйте обогатитель в конфигурации регистратора. В интерфейсе есть только один метод — Enrich , который принимает событие журнала и дополняет его нужными вам данными.

Давайте рассмотрим пример реализации пользовательского обогащателя журналов.

 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 для получения пользовательских свойств, которыми можно обогатить событие журнала. Обычно обогатители журналов являются долгоживущими экземплярами и даже следуют шаблону Singleton — они регистрируются один раз при запуске приложения и действуют в течение всего срока службы приложения.

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

 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; } } } } // And CustomLogEventProperty is a simple struct (you can make it a class, too): 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 , поскольку разные компоненты приложения могут создавать разные настраиваемые свойства.

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

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

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

Еще одна важная деталь в этой строке кода — параметр destructureObjects :

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

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

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

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

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

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

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

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

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

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

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

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

Как заявляет Microsoft,

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

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

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

Ниже приведена небольшая таблица результатов тестов, показывающая производительность и потребление памяти как для обогащения журнала Serilog, так и для областей ведения журналов 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 |

К каждому сообщению журнала прикреплены три сложных объекта (записи):

 | 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 |The

Методы Serilog*Context используют LogContext.PushProperty , методы Serilog*Enrichment используют настраиваемый обогатитель и реализацию источника, приведенные в статье, а методы Microsoft* используют области журналирования.

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

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

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

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

Итак, это ограничение областей ведения журнала Microsoft, о котором нам следует знать: отсутствие деструктуризации сложных объектов, в то время как простые типы регистрируются нормально и могут быть доступны для поиска и фильтрации.

Примечание. Исходный код тестового теста и примеры кода для этой статьи можно найти в репозитории GitHub.

Заключение

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

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

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

Рекомендации

• Об обогащении журнала Serilog — https://github.com/serilog/serilog/wiki/Enrichment.
• Области ведения журнала 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 .