Using Diagnostic Observers to Decouple Logging and Observability Code

In this article we will review how to use DiagnosticListener to further decouple and improve logging implementations related to infrastructure specific operations, such as database queries and incoming/outgoing HTTP requests.

DiagnosticSource class is defined in System.Diagnostics package, and its use is covered in a few articles on the Internet.

In this article I will briefly follow the basic steps how to consume the published events and make the best use of them, as well as how to bypass certain limitations inherent in DiagnosticSource implementation and make using this technology worth the effort.

The goal

Most applications have a lot of infrastructure code doing essentially a few general operations - such as querying databases, sending and receiving HTTP requests, processing their responses, etc. Many applications also implement various ways of monitoring these operations, as this contributes a lot to the quality of observability and diagnostics. Essentially, such operations work with external dependencies which are often seen as, and sometimes become, the source of failures or performance degradation. An application cannot control them but critically depends on their performance, even if we implement all sorts of resilience and fault tolerance techniques. Having proper logging and observability code in place would help to detect these issues before they become critical.

Another issue many applications suffer from is that this logging and observability code is added around each call site to database, HTTP, and other external dependency libraries. Which clutters the code, increases its complexity, and makes its maintenance more costly. An obvious solution to that is to extract the logging and observability code into a 'layer' or an implementation that would be indirectly called, or notified, by each operation with all required details included.

Microsoft actually provided a means to do that for many of their components, such as HttpClient, SqlClient, Asp.Net, Entity Framework, various Azure components, etc. via DiagnosticSource class. Essentially, these Microsoft libraries create event data 'containers' with relevant information regarding each operation and send them via DiagnosticSource.Write calls. An observability implementation can subscribe to those events using matching IObserver implementations and analyze and log published event data.

In this article we will review how to implement that and how to bypass certain limitations of this Microsoft implementation.

DiagnosticSource conventions and implementation specifics to consider

As Microsoft states, these observability events and features are done with a goal to be consumed by code that may know nothing of the event origin and at the same time be fully capable of getting the event data and processing it.

Many libraries send the event data as anonymous types that get constructed at the moment an event is emitted. One on hand, this decouples the consumers from the implementation details of the event origin, on the other hand, it creates a challenge how to process the event data in an efficient way.

Some other libraries, such as Entity Framework, use concrete types for the event data, thus partially breaking the initial intent of not forcing the event consumers to know the event origin implementation details, while making it seemingly easier for the consumers to process the event data generated by Entity Framework at the cost of referencing a specific package.

In this article we will review a way how to effectively work-around these differences with a single implementation.

Another area of difficulty is to discover all events generated by a particular library and their data types. While over the past few years Microsoft added a lot of documentation in this area, it is still lacking much. The general process and usage of diagnostic observability is described on these pages:

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

There is a dedicated page for Entity Framework with all event type contracts described: https://learn.microsoft.com/en-us/dotnet/api/microsoft.entityframeworkcore.diagnostics

However, a lot of information is still missing and requires either going through the library source code or extensive research. We will also explore how to do the listener and event discovery in an application.

Diagnostic observer basic code

In order to start receiving the diagnostic events we need to follow a few simple steps:

• implement IObserver<DiagnosticListener> and IObserver<KeyValuePair<string, object>> in a single class;
• subscribe an instance of this class to all active diagnostic listeners in the application:

DiagnosticListener.AllListeners.Subscribe(observerInstance);

The tricky part is how to process the events and their data, but for now we will focus on more simple details.

The purpose of IObserver<DiagnosticListener> implementation

IObserver interface defines three methods:

• OnNext(T value)
• OnError(Exception error)
• OnCompleted()

When implementing IObserver for DiagnosticListener class we normally should provide implementation only for two of these methods.

OnNext(DiagnosticListener) method will allow to subscribe to events received by a particular listener, and we can use its Name property to decide if a particular observer is suitable to listen to these events.

OnComplete method will allow to cancel the subscription we created in OnNext method. Each subscription is a disposable object, so we would simply call its Dispose method here.

As the documentation states, OnError method 'notifies the observer that the provider has experienced an error condition'. If we need to process the exception on the level of our observer code, this method will be helpful. Otherwise no implementation is required here, as this exception is unhandled, and as such should be intercepted by a general 'unhandled exceptions handler' that every application must have in place.

Below is a sample code for such an observer:

using System.Diagnostics;

/// <summary>
/// Base abstract class to implement diagnostic observers
/// </summary>
public abstract class AbstractDiagnosticObserver : IObserver<DiagnosticListener> {
    /// <summary>
    /// List of existing subscriptions
    /// </summary>
    protected List<IDisposable>? Subscriptions = new();
    
    /// <summary>
    /// Enabled flag for the observer 
    /// </summary>
    public bool IsEnabled => // have some logic here to determine of the observer is active and can process events
    
    /// <summary>
    /// Checks if the submitted diagnostic listener name should be handled by the observer
    /// </summary>
    /// <param name="name">Diagnostic listener name</param>
    /// <returns>true or false</returns>
    protected bool ShouldListenTo(string name) => // some logic to validate the listener 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) {
        // this method can be empty
    }
}

There are other ways to handle the event subscription, as we will see later.

The purpose of IObserver<KeyValuePair<string, object>> implementation

This implementation will handle the event data, and we will need to implement only OnNext method:

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

The KeyValuePair parameter will contain the event data: the key contains an event name and the value contains the event data. Since the event data is passed as 'object' type, any event from any source can be consumed. However, now comes the tricky part: how to process all different events with each of them having its own type for the event data.

The most direct way would be to have a switch on the event name with a direct cast to a particular event data type. However, as previously mentioned, many events have their payload as anonymous types. So, we cannot cast them to anything. A naive work-around would be then to use reflection to extract required properties but that would be too expensive.

In case when the event data types are concrete we would need to reference the package that contains the types. This is not often desired or even possible, as it creates hard dependencies in our code and requires knowing them beforehand, including the version lock.

Let's now see how we can address these issues.

Using a diagnostic method adapter

Microsoft provides a package, Microsoft.Extensions.DiagnosticAdapter, which adds a class that can solve many of the aforementioned problems in diagnostic event processing.

Let's review this piece of code again:

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

With the diagnostic method adapter package we can use an extension method instead:

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

And we need to provide additional methods in our class, each designed to handle a specific event we would like to process. For example, for SqlClient observability we can have these 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) { ... }

Here we use DiagnosticName attribute from the package to mark a method that should process a specific event. The method adapter uses one-time method binding to the event data, and it 'unwraps' the anonymous event data type into method parameters using Reflection.Emit - essentially, the method adapter generates the required proxy code to pass from IObserver<KeyValuePair<string, object>>.OnNext(KeyValuePair<string, object> value) to our strongly typed method implementation.

Of course, this has a cost too but this cost is incurred only once when the binding is generated when processing an event for the first time. All subsequent calls will cost only as much as a direct method call with all type casting in place.

Listener and event discovery in an application

As mentioned above, there is not sufficient documentation on existing diagnostic listeners and observability in Microsoft libraries. Some, like Entity Framework, have decent level of documentation while most have none. Let's explore how we can discover the existing diagnostic listeners and their events in our application.

We can rely on a very basic implementation, very close to what we have already seen in the article:

using System.Diagnostics;

/// <summary>
/// Simple diagnostic observer to assist in diagnostic listener and event information discovery
/// </summary>
public sealed class DiscoveringDiagnosticObserver : IObserver<DiagnosticListener>, IObserver<KeyValuePair<string, object>> {
    private List<IDisposable>? Subscriptions = new();
    
    void IObserver<DiagnosticListener>.OnNext(DiagnosticListener diagnosticListener) {
        // this method will output all existing diagnostic listener names
        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) {
        // this method will output produced event names and their data
        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) { }
}

We can introduce any other way of recording the discovery information - writing to console is just an example.

When we run the application, we will see what diagnostic listeners are registered, and what events they produce. Please note that while some listeners get registered on application startup, others do on first use. Of course, in order to see all possible events we would need to make sure all essential code paths get executed. This will give you a complete overview of what diagnostic observability your application has.

While exploring the list of events you can see a general pattern for most, if not all, events: they normally come in pairs. There is a 'before' event and an 'after' event. The 'after' event often comes in two varieties - for normal operation completion and for an error.

Let's have a look at SqlClient command execution events. There are three such events:

• Microsoft.Data.SqlClient.WriteCommandBefore executes before a command will execute;
• Microsoft.Data.SqlClient.WriteCommandAfter executes after a command has successfully completed;
• Microsoft.Data.SqlClient.WriteCommandError executes if a command execution failed.

So, in order to provide complete observability for a specific operation you would normally need to handle all such events. Sometimes it may be sufficient to handle just the completion events - be it a success or an error - but the 'before' events often carry useful information too.

How to find diagnostic event information in the source code

Well, you just check out its source repository and explore it :) It may usually work best to combine both runtime discovery and going through the source code approaches. Runtime discovery gives an idea about what there is, and then it is possible to search the code base and find all events information it has.

For example, once we have at hand the WriteCommandBefore event name, we can checkout the SqlClient code repository (found at https://github.com/dotnet/SqlClient) and simply run a text search on the event name over all .cs files. There is a single file - SqlClientDiagnosticListenerExtensions.cs - containing all events information, including their names and data types.

Then we are fully prepared to implement required observability in our application even in spite of lacking a thorough documentation.

Improving the diagnostic method adapter

Let's come back to the diagnostic method adapter we used previously in the article. As it often happens, not everything is that simple as it looks at first, and the Microsoft implementation has a few flaws that may substantially limit its usefulness. So, let's review them and see how we can work-around them.

There are two major issues with Microsoft implementation:

• it does not work on platforms not supporting Reflection.Emit;
• it has issues mapping event data type properties to method parameters.

While the first issue may not seem like much nowadays - it mostly affects .Net Standard platforms before 2.1 - the latter might become a real obstacle. Let's see why.

The current Microsoft implementation follows a particular convention when mapping properties of anonymous types - it maps them by name and type. For example, the WriteCommandBefore event for SqlClient has a TransactionId property of Guid type. So, if we want to access the transaction id in our event processing method, we must name it the same way (it does not have to match the casing exactly) even though there are not other Guid typed properties in the event data. This is not a real issue - just some minor inconvenience.

However, when it comes to mapping concrete types, like for Entity Framework, there is a peculiar problem that looks more like a defect - it cannot map a property if it is defined in a base type. Most Entity Framework observability event data types are hierarchical, thus we have an issue - we cannot get access to those event properties that belong to base classes.

There are a few ways, of course, of solving this issue. One of them is to implement a source generator method adapter which will also solve the initial method binding costs using reflection, though I am not aware if anyone has done this.

Another option is presented below - it does essentially the same things as the Microsoft method adapter with a few differences:

• it builds expression lambdas and compiles them - thus bypassing Reflection.Emit limitations, though it is as costly on the first call;
• the event type property to method parameter mapping is slightly more forgiving, as it allows to match only by the data type as long as no other properties have this type, thus no exact name match is required;
• and it can bind all event data type properties to method parameters, regardless if they belong to a base class or to the event data class itself;
• it can also bind the event data type itself to the method parameter if the method has only one parameter, and their types match (of course, this is not applicable for anonymous types);
• it is slightly more efficient on recent .Net versions due to optimizations introduced in the area of 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);
    }
}

Then we need an 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 this is how to use it (please see code samples above for the context):

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

Conclusion

Once the diagnostic observer methods to handle the events are in place (such as for SQL command execution), it is possible to add uniform logging implementation that would log command text and parameters (with proper sanitization), process execution time and potentially write some metrics or generate alerts - all this code would be in one place, potentially resolved from a DI container, thus opening way of substituting the implementation. This code can be included in an internal library to share with other applications within a company, thus contributing to DRY and costs decrease.

There are other ways too to achieve similar concern separation and decoupling. For example, for Asp.Net observability we could use middleware, and for Entity Framework - interceptors. However, these options are specific to a particular implementation while diagnostic observers work the same way for all libraries and components that provide the diagnostic listener feature.

Again, the general goal is to separate logging and observability code from infrastructure operations code, such as database queries, HTTP requests, etc. It will help improving the code quality substantially - better maintainability, testability, readability, and so on. Also, according to the Single Responsibility Principle, the code should have only one responsibility, or solve just one task, or in other words 'have only one reason to change' which will be much easier to achieve when logging and observability code is fully isolated.

Useful references

• https://learn.microsoft.com/en-us/ef/core/logging-events-diagnostics/diagnostic-listeners
• https://learn.microsoft.com/en-us/dotnet/core/diagnostics/diagnosticsource-diagnosticlistener
• https://learn.microsoft.com/en-us/dotnet/api/microsoft.entityframeworkcore.diagnostics