Using diagnostic observers to isolate logging code
What goal do we want to achieve?
Many applications have a lot of infrastructure code responsible for a fairly limited set of operations: sending queries to the database, sending and receiving HTTP requests, processing their responses, etc. Most of these applications employ a variety of methods to monitor these activities, which contributes to the quality of the metrics and diagnostic information collected. Essentially, such operations work with external dependencies, which are often considered, and sometimes become, a source of failures or performance problems. The application does not control them and, at the same time, critically depends on them, even if all the necessary approaches have been applied to ensure its stability. Having a smart approach to logging and collecting diagnostics can help detect such problems before they become critical.
Another problem common to many applications is that logging code is added to every place in the code that calls such infrastructure operations (working with the database, HTTP requests, or any other external dependencies). This makes the code more confusing and complex, and maintaining or extending such code becomes problematic. One of the most obvious solutions is to place the logging code for such operations in a separate “layer”, which will be called in one way or another by each infrastructure operation with the transfer of all the data necessary for logging.
Microsoft has provided such an implementation for a number of its components – such as HttpClient, SqlClient, Asp.Net, Entity Framework, a number of Azure components, and others using the DiagnosticSource class. In fact, each of these Microsoft libraries sends events with data that comprehensively describes a particular operation through the DiagnosticSource.Write method. The code responsible for logging and collecting diagnostics simply needs to subscribe to them using the appropriate IObserver implementation.
In this article we will look at the features and subtleties of such implementations, as well as what limitations they have and how they can be overcome.
DiagnosticSource implementation conventions and features to consider
As Microsoft notes, these diagnostic events are implemented in such a way that they can be received and fully processed by code that knows nothing about their source.
Many components send data with such events in the form of anonymous types that are created at the time the data is prepared for the event. On the one hand, this allows subscribers not to depend on the implementation details of these components, on the other hand, it complicates the efficient processing of such data.
A number of other components, such as the Entity Framework, use concrete types to pass their event data, which defeats the purpose of ensuring subscriber independence and forces them to be tied to the implementation details of the event source, although it greatly facilitates data processing on the subscriber side at the cost of including a package containing these data types .
We'll also look at how to effectively overcome these limitations and differences using one universal approach.
Another challenge is to detect all the necessary diagnostic events generated by a particular component. And although Microsoft has significantly improved documentation in this area over the past years, it is still not enough. The general process of working with diagnostic observers is described on these pages:
There is also a separate section dedicated to diagnostics in the Entity Framework, where all events and their contracts are described: https://learn.microsoft.com/en-us/dotnet/api/microsoft.entityframeworkcore.diagnostics
However, a lot of information is still missing, and one must either examine the source code of such components or investigate how the application works. We'll also look at how to discover existing DiagnosticSource implementations and their events in your application.
Basic implementation of diagnostic observer
To start receiving diagnostic events, just follow a few simple steps:
create a class that implements two interfaces –
IObserver<DiagnosticListener>AndIObserver<KeyValuePair<string, object>>Subscribe an instance of this class to all active diagnostic listeners in the application:
DiagnosticListener.AllListeners.Subscribe(observerInstance);
The hardest part is handling events and their data correctly, but for now we'll focus on the simpler details.
The meaning of the IObserver implementation
The IObserver interface provides the following methods:
OnNext(T value)OnError(Exception error)OnCompleted()
It is usually sufficient to implement only two of these methods in an implementation IObserver<DiagnosticListener>:
Method OnNext(DiagnosticListener) will allow us to subscribe to events received through the listener, and we can use its Name property to understand whether our implementation can handle its events.
Method OnComplete allows you to cancel the subscription created in the method OnNext. The subscription object implements IDisposablewhich allows you to simply call the method Dispose to cancel your subscription.
As the documentation says, the method OnError “notifies the Observer object that the event source encountered an exception.” If we need to handle this exception in the Observer code, then we can use this method, otherwise it may remain empty. If the exception is not handled where it occurs, it will be caught by the existing global handler that the application typically has.
Here is an example implementation of a simple 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) {
// этот метод может оставаться пустым
}
}Please note the following points:
Typically, objects that implement IObserver live for the entire duration of the application, since they subscribe to events when the application starts and never unsubscribe from them. However, everything depends on the requirements and implementation features of specific components.
it is not necessary to implement both interfaces –
IObserver<DiagnosticListener>AndIObserver<KeyValuePair<string, object>>– in one class; in this article, for ease of implementation, both of them are implemented in one class.
There are other possibilities for providing event subscriptions, as will be seen later.
The meaning of the IObserver> implementation
This implementation receives events and processes their data, and for this it is enough to implement only the method OnNext:
void IObserver<KeyValuePair<string, object>>.OnNext(KeyValuePair<string, object> value) { ... }
Type parameter KeyValuePair<string, object> will contain information about the event and its data – the event name in the property Key and the data in the property Value. Because event data is passed as type object, any event from any source can be processed. At the same time, this is also a challenge: how to properly process the data from all the different events with their different data types.
The most direct and naive way would be to write a big statement switch by event name with direct conversion of event data to the desired type. However, this will not work for anonymous types, and many events pass their data this way. You can use reflection to access the required fields and properties of these types, but this will be too expensive in terms of performance.
It should be taken into account that sending and processing events occurs synchronously. In effect, this means that the observer must process events as quickly as possible, otherwise it will slow down all the operations of the components whose events we subscribe to.
If event data is transmitted using specific types, then you can connect a package with these types. However, this is not always a good idea, as it creates a tight lock on certain packages and their versions, since the data types may change with a new version of the observable component.
Next we will look at how these limitations can be overcome.
Using DiagnosticAdapter
Microsoft provides a package, Microsoft.Extensions.DiagnosticAdapter, which implements a class designed to solve the problems identified above.
Let's look at this piece of code again:
if (ShouldListenTo(diagnosticListener.Name)) {
Subscriptions.Add(diagnosticListener.Subscribe(this!));
}With a connected package, it can be replaced with a subscription using the extension method SubsribeWithAdapter:
if (ShouldListenTo(diagnosticListener.Name)) {
Subscriptions.Add(diagnosticListener.SubscribeWithAdapter(this));
}We also need to write additional methods in our class, each of which will process a specific event and its data. For example, if we implement SqlClient event handling, we can add the following methods:
[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) { ... }The attribute used here is DiagnosticName from the connected package, which marks that the method should handle the specified event. The adapter implements a one-time binding of a method to an event, and also “unwraps” an object with event data (regardless of its type – anonymous or specific) using code generation via Reflection.Emit – essentially, the adapter automatically generates proxy code that transforms the method call IObserver<KeyValuePair<string, object>>.OnNext(KeyValuePair<string, object> value) into calls to methods tied to a specific event and its data.
Of course, this does not happen for free; the binding code is processed only once when you subscribe. Further, all event processing will occur by direct calling methods without the participation of reflection.
Please note that when using an adapter you no longer need to implement the interface
IObserver<KeyValuePair<string, object>>.
Detecting active listeners and their events in an application
As stated, most components still lack documentation of their diagnostic events. Let's see how we can detect active listeners and their events.
Although this may seem like a lot of time, it usually isn't and everything you need can be found very quickly.
You can use the following very simple implementation, very similar to the one we already looked at:
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) { }
}You can use any other method of saving detected information – console output is given as an example only.
When we run the application, we will see which listeners are available to it and what events they produce. Note that the listener part is registered when the application starts, while the others will only be registered the first time the corresponding component's methods are called. Therefore, to detect all possible events, you need to go through all the main code scenarios.
By examining existing events, a basic pattern of event generation can be seen: most, if not all, of them are generated in pairs. There is a “before” event and an “after” event, which can often occur in two ways – normal completion of the operation and completion with an error (exception).
Here, for example, are the events associated with the execution SqlCommand V SqlClient:
Microsoft.Data.SqlClient.WriteCommandBeforesent before the command is executed;Microsoft.Data.SqlClient.WriteCommandAftersent upon successful completion of the command;Microsoft.Data.SqlClient.WriteCommandErrorsent if the command failed.
That is, in order to fully process the events of a particular operation, you usually need to write code to process all associated events. Sometimes it is enough to process “final” events (normal or with an exception), but “preceding” events often also carry useful information.
How to find information about diagnostic events in source code
It's also very simple – upload the code repository and explore the code 🙂 Perhaps the best approach is to combine runtime research with source code exploration. Research at runtime will give you the general idea and class names, while examining the code will allow you to see the full picture.
For example, upon detecting an event Microsoft.Data.SqlClient.WriteCommandBeforeyou can download the repository for SqlClient (https://github.com/dotnet/SqlClient) and find the use of this class with a simple text search. There is one file in the repository, SqlClientDiagnosticListenerExtensions.cs, which implements all the work with events for SqlClient. There are names of all events and their data types.
Now we are completely ready to implement work with diagnostic events despite the lack of documentation.
Diagnostic adapter improvement
Let's go back to the adapter we looked at earlier. As is often the case, not everything is as smooth as it seems at first glance, and the current implementation contains several shortcomings that can significantly affect its usefulness. Let's look at them.
There are two main disadvantages:
the adapter does not work on platforms that do not support
Reflection.Emitit has problems binding properties of event data types to method parameters
And although the first of the problems is unlikely to be relevant now (it is associated with .Net Standard before version 2.1), the second may turn out to be critical.
The current implementation follows a certain convention when binding properties of anonymous types to method parameters—namely, binding by name and type. For example, in the event WriteCommandBefore V SqlClient there is a property TransactionId type Guid. If we want to access it in an event handler method, this parameter must be named exactly the same (case is optional), although there are no other type properties on the type itself Guid. But this is not a problem – it may just be inconvenient and require several debugging runs.
However, when an adapter binds concrete types to method parameters, as the Entity Framework does for example, a much more serious problem arises. The adapter will not be able to bind a property if it is defined not in the type itself, but in one of its base types. At the same time, most event data types for the same Entity Framework are built hierarchically, and a significant part of the event data lies in the base types.
There are several ways to solve this problem. For example, to implement a similar adapter using source generators, which would also solve the problem with the high cost of the initial binding, but there seems to be no such implementation.
Another option is given below. Essentially, it does everything the existing adapter does, but with minor differences:
the code is generated using expression lambdas and compiling them, which bypasses the limitations inherent in Reflection.Emit, although it does not improve performance
binding type properties to method parameters follows slightly less strict rules, and does not require a name match if a type match is sufficient
can bind all properties of a type to parameters, regardless of the type hierarchy
can also bind the event data type itself to a method parameter if this is the only parameter and its type matches
slightly performs better on the latest versions of .Net thanks to a number of optimizations in the expressions area
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);
}
}To use it, you can add the following extension method:
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);
}
}And then subscribe like this:
if (ShouldListenTo(diagnosticListener.Name)) {
Subscriptions.Add(diagnosticListener.SubscribeWithExpressionsAdapter(this));
}Conclusion
By subscribing to diagnostic events, you can create fairly simple code to log all relevant operations, such as the execution of a SqlCommand with access to all statistics and parameters. Additionally, you can collect metrics and generate warnings when metrics go beyond acceptable limits. And all this code will be in one place, possibly placed in a DI container, which makes it possible to easily replace it with another more suitable implementation. Such code can be packaged as an internal library, accessible to other projects within the company, which will contribute to the simplicity and maintainability of the code.
There are other ways to achieve similar code isolation and separation of concerns. For example, for Asp.Net you can use the capabilities provided by middleware, and for the Entity Framework you can use interceptors. However, these capabilities are more specific to the corresponding components, while subscription to diagnostic events is more universal.
I repeat that the main goal of all these approaches and solutions is to separate the logging code and related tasks from such frequent infrastructure operations as working with the database and HTTP requests (as well as similar ones). This will improve the quality of the code – its maintainability, cleanliness, extensibility, readability, etc. Additionally, according to the “single responsibility principle”, code should have only one responsibility or reason for change, which is much easier to implement if the logging task is completely isolated.
