Использование diagnostic observers для изоляции кода логгирования

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

Класс DiagnosticListener определен в пакете System.Diagnostics, и особенности его использования описаны в разных статьях, включая одну-две на Хабре.

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

Какую цель мы хотим достичь

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

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

Компания Microsoft предоставила такую реализацию для целого ряда своих компонентов – таких как HttpClient, SqlClient, Asp.Net, Entity Framework, ряд компонентов Azure, и других с помощью класса DiagnosticSource. По сути, каждая из этих библиотек от Microsoft отправляет через метод DiagnosticSource.Write события с данными, исчерпывающе описывающими ту или иную операцию. Коду, отвечающими за логгирование и сбор диагностики, достаточно подписаться на них с помощью соответствующей реализации IObserver.

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

Соглашения и особенности реализации DiagnosticSource, которые необходимо учитывать

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

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

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

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

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

• https://learn.microsoft.com/en-us/dotnet/core/diagnostics/diagnosticsource-diagnosticlistener

• https://learn.microsoft.com/en-us/ef/core/logging-events-diagnostics/diagnostic-listeners

Есть также отдельный раздел, посвященные диагностике в Entity Framework, где описаны все события и их контракты: https://learn.microsoft.com/en-us/dotnet/api/microsoft.entityframeworkcore.diagnostics

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

Базовая реализация diagnostic observer

Чтобы начать получать события диагностики, достаточно выполнить несколько простых шагов:

• создать класс, реализующий два интерфейса – IObserver<DiagnosticListener> и IObserver<KeyValuePair<string, object>>

• подписать экземпляр этого класса на все активные diagnostic listeners в приложении:
  DiagnosticListener.AllListeners.Subscribe(observerInstance);

Самое сложное – это грамотная обработка событий и их данных, но пока что мы сфокусируемся на более простых деталях.

Смысл реализации IObserver<DiagnosticListener>

Интерфейс IObserver предоставляет следующие методы:

• OnNext(T value)

• OnError(Exception error)

• OnCompleted()

Обычно достаточно реализовать только два из этих методов в реализации IObserver<DiagnosticListener>:

Метод OnNext(DiagnosticListener) позволит подписаться на события, получаемые через listener, и можно воспользоваться его свойством Name, чтобы понять, может ли наша реализация обрабатывать его события.

Метод OnComplete позволяет отменить подписку, созданную в методе OnNext. Объект подписки реализует IDisposable, что позволяет просто вызвать метод Dispose для отмены подписки.

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

Вот пример реализации простого Observer:

using System.Diagnostics;  /// <summary> /// Базовый абстрактный класс для реализации diagnostic observers /// </summary> public abstract class AbstractDiagnosticObserver : IObserver<DiagnosticListener> {     /// <summary>     /// Список активных подписок     /// </summary>     protected List<IDisposable>? Subscriptions = new();          /// <summary>     /// Флаг "включено"     /// </summary>     public bool IsEnabled => // логика, определяющая, что объект активен и может получать события          /// <summary>     /// Проверяет имя listener и решает, можно ли подписаться на его события     /// </summary>     /// <param name="name">Diagnostic listener name</param>     /// <returns>true or false</returns>     protected bool ShouldListenTo(string name) => // логика проверки имени          /// <inheritdoc />     void IObserver<DiagnosticListener>.OnNext(DiagnosticListener diagnosticListener) {         if (!IsEnabled) {             return;         }              if (Subscriptions is null) {             throw new ObjectDisposedException(GetType().Name);         }              if (ShouldListenTo(diagnosticListener.Name)) {             Subscriptions.Add(diagnosticListener.Subscribe(this!));         }     }      /// <inheritdoc />     void IObserver<DiagnosticListener>.OnCompleted() {         var subscriptions = Interlocked.Exchange(ref Subscriptions, null);         subscriptions?.ForEach(x => x.Dispose());     }          /// <inheritdoc />     void IObserver<DiagnosticListener>.OnError(Exception error) {         // этот метод может оставаться пустым     } }

Обратите внимание на следующие моменты:

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

• не обязательно реализовывать оба интерфейса – IObserver<DiagnosticListener> и IObserver<KeyValuePair<string, object>> – в одном классе; в этой статье для простоты реализации они оба реализуются в одном классе.

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

Смысл реализации IObserver<KeyValuePair<string, object>>

Эта реализация получает события и обрабатывает их данные, и для этого достаточно реализовать только метод OnNext:

void IObserver<KeyValuePair<string, object>>.OnNext(KeyValuePair<string, object> value) { ... }

Параметр типа KeyValuePair<string, object> будет содержать информацию о событии и его данные – имя события в свойстве Key и данные в свойстве Value. Поскольку данные события передаются как тип object, может быть обработано любое событие из любого источника. Вместе с тем, это и сложность: как правильно обработать данные всех разнообразных событий с их разными типами данных.

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

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

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

Дальше мы рассмотрим, как можно преодолеть эти ограничения.

Использование DiagnosticAdapter

Мicrosoft предоставляет пакет, Microsoft.Extensions.DiagnosticAdapter, в котором реализован класс, предназначенный для решения обозначенных выше проблем.

Давайте еще раз посмотрим на этот фрагмент кода:

if (ShouldListenTo(diagnosticListener.Name)) {     Subscriptions.Add(diagnosticListener.Subscribe(this!)); }

С помощью подключенного пакета его можно заменить подписку с помощью метода расширения SubsribeWithAdapter:

if (ShouldListenTo(diagnosticListener.Name)) {     Subscriptions.Add(diagnosticListener.SubscribeWithAdapter(this)); }

Также нужно написать дополнительные методы в нашем классе, каждый из которых будет обрабатывать конкретное событие и его данные. Например, если мы реализуем обработку событий SqlClient, мы можем добавить следующие методы:

[DiagnosticName("Microsoft.Data.SqlClient.WriteCommandBefore")] public void OnWriteCommandBefore(Guid? connectionId, SqlCommand command, long? transactionId, long timestamp) { ... }  [DiagnosticName("Microsoft.Data.SqlClient.WriteCommandAfter")] public void OnWriteCommandAfter(Guid? connectionId, SqlCommand command, long? transactionId, IDictionary statistics, long timestamp) { ... }  [DiagnosticName("Microsoft.Data.SqlClient.WriteCommandError")] public void OnWriteCommandError(Guid? connectionId, SqlCommand command, long? transactionId, Exception exception, long timestamp) { ... }

Здесь используется атрибут DiagnosticName из подключенного пакета, который отмечает, что метод должен обрабытывать указанное событие. Адаптер реализует однократную привязку метода к событию, а также “разворачивает” объект с данными события (независимо от его типа – анонимного или конкретного) с помощью генерации кода через Reflection.Emit – по сути, адаптер автоматически генерирует прокси-код, преобразующий вызов метода IObserver<KeyValuePair<string, object>>.OnNext(KeyValuePair<string, object> value) в вызовы методов, привязанных к конкретному событию и его данным.

Само собой, это не происходит бесплатно, на код привязки отрабатывает только один раз при подписке. Дальше вся обработка событий будет происходить прямым вызовом методов без участия reflection.

Обратите внимания, что при использовании адаптера уже не нужно реализовывать интерфейс IObserver<KeyValuePair<string, object>>.

Обнаружение активных listeners и их событий в приложении

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

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

Можно воспользоваться следующей очень простой реализацией, очень похожей на ту, что мы уже рассматривали:

using System.Diagnostics;  /// <summary> /// Простой diagnostic observer для обнаружения активных listener и их событий /// </summary> public sealed class DiscoveringDiagnosticObserver : IObserver<DiagnosticListener>, IObserver<KeyValuePair<string, object>> {     private List<IDisposable>? Subscriptions = new();          void IObserver<DiagnosticListener>.OnNext(DiagnosticListener diagnosticListener) {         // этот метод выведет имена всех активных listener         if (Subscriptions is null) {             throw new ObjectDisposedException(GetType().Name);         }              Subscriptions?.Add(diagnosticListener.Subscribe(this!));         Console.WriteLine("Subscribed to " + diagnosticListener.Name);     }      void IObserver<DiagnosticListener>.OnCompleted() {         var subscriptions = Interlocked.Exchange(ref Subscriptions, null);         subscriptions?.ForEach(x => x.Dispose());     }          void IObserver<DiagnosticListener>.OnError(Exception error) { }        void IObserver<KeyValuePair<string, object>>.OnNext(KeyValuePair<string, object> value) {         // этот метод выведет имена и типых данных всех событий         Console.WriteLine("");         Console.WriteLine("#Event: " + value.Key);         Console.Write("Event type: ");         Console.WriteLine(value.Value.GetType().FullName);         Console.Write("Event value: ");         Console.WriteLine(value.Value);     }          void IObserver<KeyValuePair<string, object>>.OnCompleted() { }          void IObserver<KeyValuePair<string, object>>.OnError(Exception error) { } }

Можно воспользоваться любым другим способом сохранения обнаруженной информации – вывод в консоль дан лишь для примера.

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

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

Вот, для примера, события, связанные с выполнением SqlCommand в SqlClient:

• Microsoft.Data.SqlClient.WriteCommandBefore отправляется перед выполнением команды;

• Microsoft.Data.SqlClient.WriteCommandAfter отправляется по успешному завершению команды;

• Microsoft.Data.SqlClient.WriteCommandError отправляется, если команда завершилась с ошибкой.

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

Как найти информацию о диагностических событиях в исходном коде

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

Например, обнаружив событие Microsoft.Data.SqlClient.WriteCommandBefore, можно выгрузить репозиторий для SqlClient (https://github.com/dotnet/SqlClient) и найти применение этого класса простым текстовым поиском. В репозитории есть один файл, SqlClientDiagnosticListenerExtensions.cs, в котором реализована вся работа с событиями для SqlClient. Там есть имена всех событий и типы их данных.

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

Улучшение диагностического адаптера

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

Таких основных недостатков два:

• адаптер не работает на платформах, не поддерживающих Reflection.Emit

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

И хотя первая из проблем сейчас вряд ли актуальна (она связана с .Net Standard до версии 2.1), вторая может оказаться критической.

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

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

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

Другой вариант приведен ниже. По сути, он делает все то же самое, что и существующий адаптер, но с небольшими отличиями:

• код генерируется с помощью expression lambdas и их компиляции, что обходит ограничения, свойственные Reflection.Emit, хотя не улучшает проивзодительности

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

• может привязать все свойства типа к параметрам, независимо от иерархии типов

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

• слегка более производителен на последних версиях .Net благодаря ряду оптимизаций в области expressions

public sealed class DiagnosticObserverMethodAdapter : IDiagnosticSourceMethodAdapter {     private static readonly ConcurrentDictionary<(MethodInfo, Type), Func<object, object, bool>> Adapters = new();          public static IDiagnosticSourceMethodAdapter Adapter { get; } = new DiagnosticObserverMethodAdapter();          private DiagnosticObserverMethodAdapter() { }          public Func<object, object, bool> Adapt(MethodInfo method, Type inputType) {         if (!Adapters.TryGetValue((method, inputType), out var adapter)) {             var methodParameters = method.GetParameters();                  adapter = methodParameters.Length == 0                 ? BuildNoParametersCall(method)                 : BuildCallWithParameters(method, inputType, methodParameters);                  Adapters.TryAdd((method, inputType), adapter);         }              return adapter;     }          private static Func<object, object, bool> BuildNoParametersCall(MethodInfo method) {         var thisParameter = Expression.Parameter(typeof(object), "this");         var call = Expression.Call(Expression.Convert(thisParameter, method.DeclaringType!), method);              var lambda = Expression.Lambda<Action<object>>(call, thisParameter);         var compiled = lambda.Compile();              return (listener, _) => {             compiled(listener);                  return true;         };     }          private static Func<object, object, bool> BuildCallWithParameters(MethodInfo method, Type inputType, ParameterInfo[] methodParameters) {         var lambda = methodParameters.Length == 1 && !inputType.IsConstructedGenericType             ? BuildSingleParameterCall(method, inputType, methodParameters[0])             : BuildMultipleParametersCall(method, inputType, methodParameters);              var compiled = lambda.Compile();              return (listener, data) => {             compiled(listener, data);                  return true;         };     }          private static Expression<Action<object, object>> BuildSingleParameterCall(MethodInfo method, Type inputType, ParameterInfo methodParameter) {         if (!methodParameter.ParameterType.IsAssignableFrom(inputType)) {             if (inputType.GetProperties().Any(p => methodParameter.ParameterType.IsAssignableFrom(p.PropertyType))) {                 return BuildMultipleParametersCall(method, inputType, [methodParameter]);             }                  throw new ArgumentException($"Cannot assign {inputType.Name} to {methodParameter.ParameterType.Name}");         }              var thisParameter = Expression.Parameter(typeof(object), "this");         var parameter = Expression.Parameter(typeof(object), methodParameter.Name);              var call = Expression.Call(             Expression.Convert(thisParameter, method.DeclaringType!),             method,             Expression.Convert(parameter, inputType));              return Expression.Lambda<Action<object, object>>(call, thisParameter, parameter);     }          private static Expression<Action<object, object>> BuildMultipleParametersCall(MethodInfo method, Type inputType, ParameterInfo[] methodParameters) {         var mappings = GetPropertyToParameterMappings(inputType, methodParameters);              var thisParameter = Expression.Parameter(typeof(object), "this");         var input = Expression.Parameter(typeof(object), "input");              var parameters = mappings             .Select(m => Expression.Property(Expression.Convert(input, inputType), m))             .ToList();              var call = Expression.Call(Expression.Convert(thisParameter, method.DeclaringType!), method, parameters);              return Expression.Lambda<Action<object, object>>(call, thisParameter, input);     }          private static PropertyInfo[] GetPropertyToParameterMappings(Type inputType, ParameterInfo[] parameters) {         var properties = inputType.GetProperties().ToList();         var mappings = new PropertyInfo[parameters.Length];         int mappedCount = 0;              foreach (var parameter in parameters) {             foreach (var property in properties) {                 if (IsMatch(parameter, property, properties)) {                     mappings[mappedCount++] = property;                     properties.Remove(property);                          break;                 }             }         }              if (mappedCount != mappings.Length) {             throw new ArgumentException("Method parameters do not match input type properties", nameof(inputType));         }              return mappings;     }          private static bool IsMatch(ParameterInfo parameter, PropertyInfo property, IList<PropertyInfo> allProperties) {         if (!IsTypeMatch(parameter, property)) {             return false;         }              if (property.Name.Equals(parameter.Name, StringComparison.OrdinalIgnoreCase)) {             return true;         }              foreach (var item in allProperties) {             if (item != property && IsTypeMatch(parameter, item)) {                 return false;             }         }              return true;     }          private static bool IsTypeMatch(ParameterInfo parameter, PropertyInfo property) {         if (parameter.ParameterType.IsValueType) {             return parameter.ParameterType == property.PropertyType;         }              return parameter.ParameterType.IsAssignableFrom(property.PropertyType);     } }

Для его использования можно добавить такой метод расширения:

internal static class DiagnosticListenerExtensions {     public static IDisposable SubscribeWithExpressionsAdapter(this DiagnosticListener listener, AbstractDiagnosticObserver observer) {         var adapter = new DiagnosticSourceAdapter(observer, observer.IsEventObserved, DiagnosticObserverMethodAdapter.Adapter);         return listener.Subscribe(adapter);     } }

И затем оформить подписку так:

if (ShouldListenTo(diagnosticListener.Name)) {     Subscriptions.Add(diagnosticListener.SubscribeWithExpressionsAdapter(this)); }

Заключение

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

Есть и другие способы достичь аналогичной изоляции кода и разделения ответственностей. Например, для Asp.Net можно воспользоваться возможностями, предоставляемыми middleware, а для Entity Framework использовать interceptors. Однако, эти возможности более специфичны для соответствующих компонентов, тогда как подписка на диагностические события более универсальна.

Повторю, что основная цель всех этих подходов и решений – это вынести код логгирования и связаных с ним задач отдельно от таких частых инфраструктурных операций, как работа с базой данных и HTTP запросами (а также схожими с ними). Это улучшит качество кода – его поддерживаемость, чистоту, расширяемость, читаемость, и т.д. Кроме того, в соответствии с “single responsibility principle”, у кода должна быть только одна ответственность или причина для изменения, что намного легче реализовать, если задача логгирования полностью изолирована.