Using the DiagnosticSource in .NET Core: Practice

In the previous article, I talked about the DiagnosticSource mechanism and, using a simple example, showed how to use it to intercept queries into the database through the SqlConnection and SqlCommand classes and measure their execution time.

Currently, the DiagnosticSource is already used in AspNetCore, EntityFrameworkCore, HttpClient and SqlClient - each of them sends its own events that can be intercepted and processed.

In this article I want to look at a few examples of how the DiagnosticSource can be used in practice in ASP.NET Core applications.

• CorrelationID and header forwarding between services
• Collecting metrics and traces
• Logging

In addition, in this article I decided to compile a list of events that are available for processing and can be used in your applications, as well as talk about some of the pitfalls that you may encounter if you decide to use the DiagnosticSource mechanism in your project.

Existing events

Before moving on to the examples, we need to understand which components send events through the DiagnosticSource, and what these events are called. Unfortunately, nowhere in the documentation is the complete list of events described, and you can only find it in the source code on GitHub.

Therefore, the easiest way to understand what events exist is to create a class that implements IObserver<DiagnosticListener> and IObserver<KeyValuePair<string, object>> interfaces, subscribe to any DiagnosticListener instances and see which events will be intercepted in the application. In the same way, you can determine the parameters that are transmitted with each event.

To simplify your task, I have already collected some of the most useful events (this is not a complete list) for the four components:

By the way, there is even a DiagnosticSource User's Guide , which describes recommendations and conventions for naming events for the DiagnosticSource.

As you can easily guess, Microsoft doesn’t follow these recommendations and does the opposite =) (Ok, I’m exaggerating. It’s just that the DiagnosticSource was used in the .NET Core components before the DiagnosticSource User's Guide appeared)

Common code

It is assumed that all the examples that I will discuss below will be used in an ASP.NET Core application (although this is not necessary) and will use the DiagnosticObserverBase base class to subscribe to and process events from the DiagnosticSource.

This class is based on the ExampleDiagnosticObserver class from my previous article where you can find a description of its work. This class will use the SubscribeWithAdapter method from the Microsoft.Extensions.DiagnosticAdapter NuGet package to subscribe and handle events.

 public abstract class DiagnosticObserverBase : IObserver<DiagnosticListener> { private readonly List<IDisposable> _subscriptions = new List<IDisposable>(); protected abstract bool IsMatch(string name); void IObserver<DiagnosticListener>.OnNext(DiagnosticListener diagnosticListener) { if (IsMatch(diagnosticListener.Name)) { var subscription = diagnosticListener.SubscribeWithAdapter(this); _subscriptions.Add(subscription); } } void IObserver<DiagnosticListener>.OnError(Exception error) { } void IObserver<DiagnosticListener>.OnCompleted() { _subscriptions.ForEach(x => x.Dispose()); _subscriptions.Clear(); } } 

To subscribe to events from certain components, you need to create a new class, inherit it from the DiagnosticObserverBase , override the IsMatch method IsMatch that it returns true for those components that we want to subscribe to, add methods to handle the events and mark them with the DiagnosticNameAttribute attributes, where you can enter the name processed event. For example:

 public sealed class SomeDiagnosticObserver : DiagnosticObserverBase { protected override bool IsMatch(string name) { return name == "SomeComponent"; } [DiagnosticName("SomeEvent")] public void OnSomeEvent(/* EventParameters */) { // ... } } 

In order to register handlers based on the DiagnosticObserverBase class in the DI container, we will use the AddDiagnosticObserver extension AddDiagnosticObserver , which will be used in the ConfigureServices method in the Startup.cs file:

 public static class DiagnosticServiceCollectionExtensions { public static void AddDiagnosticObserver<TDiagnosticObserver>( this IServiceCollection services) where TDiagnosticObserver : DiagnosticObserverBase { services.TryAddEnumerable(ServiceDescriptor .Transient<DiagnosticObserverBase, TDiagnosticObserver>()); } } 

And in order to subscribe to events from the DiagnosticSource, add the following lines to the Configure method:

 public void Configure(IApplicationBuilder app, IHostingEnvironment env) { var diagnosticObservers = app .ApplicationServices.GetServices<DiagnosticObserverBase>(); foreach (var diagnosticObserver in diagnosticObservers) { DiagnosticListener.AllListeners.Subscribe(diagnosticObserver); } // ... app.UseMvc(); } 

Perhaps this is not the best way to register and in practice we usually use the IHostedService interface for such purposes, but our examples will be quite enough.

Some pitfalls

If you decide to use the DiagnosticSource in your projects, you may encounter some unobvious points that I would like to dwell on.

Sometimes dummy handlers may be required for non-existent events.

Usually, if a component sends events about its work, the code for sending an event is as follows:

 if (_diagnosticSource.IsEnabled("SomeEvent")) _diagnosticSource.Write("SomeEvent", new { /* parameters */ }); 

This allows you not to create an object with parameters if no one is going to process the event, and save a little on garbage collection.

However, in some cases there are paired events with the suffixes .Start and .Stop , both of which must either work or not. The code for sending such events might look something like this:

  //  ,     . var someEventIsEnabled = _diagnosticSource.IsEnabled("SomeEvent"); if (someEventIsEnabled && _diagnosticSource.IsEnabled("SomeEvent.Start")) _diagnosticSource.Write("SomeEvent.Start", new { /* parameters */ }); // ... if (someEventIsEnabled && _diagnosticSource.IsEnabled("SomeEvent.Stop")) _diagnosticSource.Write("SomeEvent.Stop", new { /* parameters */ }); 

Therefore, to subscribe to the SomeEvent.Start and SomeEvent.Stop events, SomeEvent.Stop must also add a dummy handler for the SomeEvent event, which will never be called, but its presence will be checked.

Some events are paired and some are triple.

Some events are paired, for example System.Net.Http.HttpRequestOut.Start and System.Net.Http.HttpRequestOut.Stop . This means that the event with the suffix .Start will be triggered before the start of some operation, and the event with the suffix .Stop - at the end. In this case, the last event will be guaranteed to be called (if there are corresponding handlers), regardless of whether the operation ended with an error or not.

However, some events are triple, for example System.Data.SqlClient.WriteCommandBefore , System.Data.SqlClient.WriteCommandAfter and System.Data.SqlClient.WriteCommandError , where the last event depends on the result of the operation. In this case, if the operation was completed successfully, only the System.Data.SqlClient.WriteCommandAfter event will be triggered, and if an error occurred during the operation, only the System.Data.SqlClient.WriteCommandError event occurred.

This should be taken into account if, for example, you use events to measure the time of operations. For example, if you start a stopwatch at the beginning of an operation, then you need to stop it in two places in order not to lose data.

Examples of using the DiagnosticSource

Now we are ready to consider how the DiagnosticSource mechanism can be put into practice in real-world applications.

CorrelationID and header forwarding between services

In the world of microservices you can often find the term CorrelationID. This is some identifier that is generated each time any service is accessed and then is transferred from the service to the service via http headers. This identifier is usually written to the logs, allowing you to link messages from several services received as part of a single transaction.

For ASP.NET Core, there is the NuGet CorrelationId package, but it requires that developers manually add the appropriate header to all outgoing requests, and therefore is not very convenient to use.

We implement CorrelationId through DiagnosticSource. To begin with, let's add the CorrelationId class which will be responsible for storing our identifier:

 public static class CorrelationId { private static readonly AsyncLocal<Guid?> _current = new AsyncLocal<Guid?>(); public static Guid Current { get { var value = _current.Value; if (value == null) throw new InvalidOperationException("CorrelationId isn't assigned."); return value.Value; } set { _current.Value = value; } } } 

This class uses an instance of the AsyncLocal <T> type to store the current CorrelationId value, which will be unique for each request, but will be correctly transferred from one thread from ThreadPool to another when working with asynchronous code.

The next step is to add an event handler from the DiagnosticSource, which will intercept incoming and outgoing http requests. In incoming requests, we will check for the presence of the X-Correlation-ID header and, if it is not there, we will generate a new identifier via Guid.NewGuid() . In outgoing requests, we will simply add a header using CorrelationId.Current .

 public sealed class CorrelationIdHandler : DiagnosticObserverBase { protected override bool IsMatch(string name) { return name == "Microsoft.AspNetCore" || name == "HttpHandlerDiagnosticListener"; } //   http  [DiagnosticName("Microsoft.AspNetCore.Hosting.HttpRequestIn")] public void OnHttpRequestIn() { } [DiagnosticName("Microsoft.AspNetCore.Hosting.HttpRequestIn.Start")] public void OnHttpRequestInStart(HttpContext httpContext) { //    CorrelationId    http . var headers = httpContext.Request.Headers; if (headers.TryGetValue("X-Correlation-ID", out var header)) { if (Guid.TryParse(header, out var correlationId)) { CorrelationId.Current = correlationId; return; } } //    CorrelationId. CorrelationId.Current = Guid.NewGuid(); } //   http  [DiagnosticName("System.Net.Http.HttpRequestOut")] public void OnHttpRequestOut() { } [DiagnosticName("System.Net.Http.HttpRequestOut.Start")] public void OnHttpRequestOutStart(HttpRequestMessage request) { //     http    CorrelationId var correlationId = CorrelationId.Current.ToString(); request.Headers.Add("X-Correlation-ID", correlationId); } } 

In this class, in the IsMatch method IsMatch we report that we want to handle events from Microsoft.AspNetCore components (responsible for incoming http requests) and HttpHandlerDiagnosticListener (responsible for outgoing http requests). Direct handling of headers occurs in the OnHttpRequestInStart and OnHttpRequestOutStart .

In addition, we had to add two dummy methods OnHttpRequestIn and OnHttpRequestOut . They will not be called during processing, but are used to determine whether to call the Start and Stop handlers. Without them, these events will not be triggered.

It remains only to register our handler in the Startup.cs file:

 services.AddDiagnosticObserver<CorrelationIdHandler>(); 

In practice, it is also useful to forward not one, but several headers with a certain prefix (for example, "X-Api-"), thereby realizing the so-called Context Propagation. This mechanism allows you to set a value with a specific key in one service and read it in another, without transferring this value explicitly through the request body. Such a mechanism can be easily implemented based on the CorrelationIdHandler class described above.

Collecting metrics and traces

Metrics and traces are an important part of any application. Metrics allow you to customize monitoring and dashboards for applications, and traces to find bottlenecks in them.

We at OZON.ru use Prometheus to collect metrics and, for ASP.NET Core services, NuGet Prometheus.Client.AspNetCore package.

We use OpenTracing and Jaeger to collect traces. (If you wish, you can view my report “Using OpenTracing in .NET” with DotNetMsk Meetut # 30)

However, many developers do not really want to cover their applications with metrics and traces, since this often requires the writing of additional uniform code and is not very consistent with the “business objectives”.

Fortunately, most of the components that send events through the DiagnosticSource give out pairwise events, the first of which indicates the beginning of a certain operation, and the second - its completion. This allows, for example, to start the stopwatch first, and then stop it and give a certain metric.

For example, if we go to collect a metric based on the execution time of all controller actions, we can use the following class:

 public sealed class AspNetCoreMetricsHandler : DiagnosticObserverBase { private readonly Histogram requestDurationSeconds; public MetricsHandler(MetricFactory metricFactory) { //  ,  NuGet  Prometheus.Client. //        . requestDurationSeconds = metricFactory.CreateHistogram( "request_duration_seconds", "", labelNames: new[] {"action_name"}); } protected override bool IsMatch(string name) { return name == "Microsoft.AspNetCore"; } [DiagnosticName("Microsoft.AspNetCore.Hosting.HttpRequestIn")] public void OnHttpRequestIn() { } [DiagnosticName("Microsoft.AspNetCore.Hosting.HttpRequestIn.Start")] public void OnHttpRequestInStart(HttpContext httpContext) { //     http   . httpContext.Items["Stopwatch"] = Stopwatch.StartNew(); } [DiagnosticName("Microsoft.AspNetCore.Mvc.BeforeAction")] public void OnBeforeAction(HttpContext httpContext, ActionDescriptor actionDescriptor) { //    , //     . httpContext.Items["ActionName"] = actionDescriptor.DisplayName; } [DiagnosticName("Microsoft.AspNetCore.Hosting.HttpRequestIn.Stop")] public void OnHttpRequestInStop(HttpContext httpContext) { //     http    //      . if (!httpContext.Items.TryGetValue("Stopwatch", out object stopwatch)) return; if (!httpContext.Items.TryGetValue("ActionName", out object actionName)) actionName = "Unknown"; var duration = ((Stopwatch) stopwatch).Elapsed.TotalSeconds; requestDurationSeconds .WithLabels(actionName.ToString()) .Observe(duration); } } 

Here we declare a Histogram type metric from NuGet of the Prometheus.Client package in the constructor. To this metric we add the label "action_name", which will allow us to distinguish metrics collected in different actions of the controllers.

At the beginning of event processing ( OnHttpRequestInStart method), we start a stopwatch to measure the time of the request. We also remember the name of the action being processed ( OnBeforeAction method). Finally, after processing the request (the OnHttpRequestInStop method), we again obtain all the data from the httpContext.Items collection and write them into the metric.

It remains only to register our handler and the MetricFactory instance in the MetricFactory file:

 services.AddSingleton(Prometheus.Client.Metrics.DefaultFactory); services.AddDiagnosticObserver<AspNetCoreMetricsHandler>(); 

A similar technique can also be used when collecting traces using NuGet OpenTracing package.

Logging

Another very useful application of DiagnosticSource is logging exceptions. But the question may arise: "Why is this needed?". After all, you can simply wrap your code in a try-catch block or even configure one global handler for all unhandled exceptions.

The point is that exception handling through DiagnosticSource events occurs at a very early stage, when various objects are still available that can help us understand the reason for the exception. (It should be noted that DiagnosticSource allows only to handle the exception, but will not prevent its further spreading)

Suppose we want to centrally handle all exceptions when accessing the database, while recording the query text and its parameters in the log. Using the DiagnosticSource we can do this as follows:

 public sealed class SqlClientLoggingHandler : DiagnosticObserverBase { private readonly ILogger<SqlClientLoggingHandler> _logger; public SqlClientLoggingHandler(ILogger<SqlClientLoggingHandler> logger) { _logger = logger; } protected override bool IsMatch(string name) { return name == "SqlClientDiagnosticListener"; } [DiagnosticName("System.Data.SqlClient.WriteCommandError")] public void OnCommandError(DbCommand command, Exception exception) { var sb = new StringBuilder(); sb.AppendLine("Command: " + command.CommandText); if (command.Parameters.Count > 0) { sb.AppendLine("Parameters: "); foreach (DbParameter parameter in command.Parameters) { sb.AppendLine($"\t{parameter.ParameterName}: {parameter.Value}"); } } _logger.LogError(exception, sb.ToString()); } } 

IsMatch , SqlClientDiagnosticListener , OnCommandError .

Startup.cs :

 services.AddDiagnosticObserver<SqlClientLoggingHandler>(); 

Conclusion

DiagnosticSource. , , , DiagnosticSource, ASP.NET Core.

OZON.ru . , NuGet , , .

, , DiagnosticSource .