In this post I introduce the Microsoft.AspNetCore.MiddlewareAnalysis package, and how you can use it to visualise the middleware pipeline of your ASP.NET Core apps. In this post I show how to use it with a .NET 6 WebApplication app.
This post is an update to one I wrote over 5 years ago in 2017. I've rewritten large chunks of it to update it for .NET 6, as I recently found I wanted this functionality and it wasn't entirely obvious how to achieve it with .NET 6!
In a recent post I mentioned a powerful interface called IStartupFilter, which enables modification of your ASP.NET Core app's middleware pipeline, different to the standard Add*() commands which just add extra middleware.
In my last two posts (here and here) I looked at the DiagnosticSource logging framework, which provides an alternative mechanism for logging, separate from the typical ILogger infrastructure.
In this post I introduce the Microsoft.AspNetCore.MiddlewareAnalysis package, which uses both of these concepts. It uses an IStartupFilter and the DiagnosticSource framework to show each of the middleware stages a request passes through. This lets you figure out exactly what is in your middleware pipeline, which may not always be obvious!
The output we're going for is something like this, which isn't pretty, but shows clearly all the middleware in your pipeline:
MiddlewareStarting: 'Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware'; Request Path: '/'
MiddlewareStarting: 'Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware'; Request Path: '/'
MiddlewareStarting: 'Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware'; Request Path: '/'
MiddlewareStarting: 'Microsoft.AspNetCore.Routing.EndpointMiddleware'; Request Path: '/'
MiddlewareFinished: 'Microsoft.AspNetCore.Routing.EndpointMiddleware'; Status: '200'
MiddlewareFinished: 'Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware'; Status: '200'
MiddlewareFinished: 'Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware'; Status: '200'
MiddlewareFinished: 'Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware'; Status: '200'
I previously described how to do this back in the .NET Core 1.x days, but things have become a little bit trickier with .NET 6, so I'll show how to work around those issues!
Analysing your middleware pipeline
Before we dig into details, lets take a look at what you can expect when you use the MiddlewareAnalysis package in your solution.
I've started with a simple 'Hello world' ASP.NET Core application using .NET 6's WebApplication minimal hosting, but you can do the same thing with Startup if you prefer. The following simple api returns "Hello World!" when called:
WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
WebApplication app = builder.Build();
app.MapGet("/", () => "Hello World!");
app.Run();
When you run the app, you just get the Hello World response as expected:
On the face of it, it doesn't look like we have much middleware in the WebApplication right? Just a single endpoint, so just a little routing middleware?
Readers of my Building a middleware pipeline with WebApplication post will know that's not the case!
Once we add the MiddlewareAnalysis package to our app, we'll see the following being logged for every request, indicating there's a lot more going on than originally meets the eye!
MiddlewareStarting: 'Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware'; Request Path: '/'
MiddlewareStarting: 'Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware'; Request Path: '/'
MiddlewareStarting: 'Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware'; Request Path: '/'
MiddlewareStarting: 'Microsoft.AspNetCore.Routing.EndpointMiddleware'; Request Path: '/'
MiddlewareFinished: 'Microsoft.AspNetCore.Routing.EndpointMiddleware'; Status: '200'
MiddlewareFinished: 'Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware'; Status: '200'
MiddlewareFinished: 'Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware'; Status: '200'
MiddlewareFinished: 'Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware'; Status: '200'
We have two logs for each piece of middleware in the pipeline, one indicating when it started, and the other when it stopped. This typically won't be something you want to enable in production, as it would be very noisy, but it can be very powerful for diagnosing complex middleware pipelines, or when trying to figure out why a particular request takes a given route through your app.
Note that the log messages shown above are entirely custom, and you have access to far more information than I've shown here. Read on for more details!
Now you've seen what to expect, lets enable the MiddlewareAnalysis package in the application.
Adding middleware analysis to your .NET 6 application
As I've already mentioned, the MiddewareAnalysis package uses the DiagnosticSource framework to emit events when each middleware in your pipeline starts and when it stops. We're going to subscribe to those events, and use that to log to the console.
Unfortunately, the MiddlewareAnalysis package uses anonymous types in its DiagnosticSource events. As you may remember from my previous post, that means we'll need to use reflection to read the data. Rather than do that manually, we'll use the Microsoft.Extensions.DiagnosticAdapter NuGet package to create a declarative interface as I showed in my previous post.
1. Add the required packages
There are a couple of NuGet packages we need for this example. First of all, we need the Microsoft.AspNetCore.MiddlewareAnalysis package, which includes the AnalysisStartupFilter and AnalysisMiddleware which are doing the heavy lifting in my example. You can add this to your project using the .NET CLI:
dotnet add package Microsoft.AspNetCore.MiddlewareAnalysis
or by adding the <PackageReference> directly to your .csproj file.
<PackageReference Include="Microsoft.AspNetCore.MiddlewareAnalysis" Version="6.0.5" />
Next we'll add the Microsoft.Extensions.DiagnosticAdapter package, which we'll use to read the anonymous type event data produced by the AnalysisMiddleware. You can add this using:
dotnet add package Microsoft.Extensions.DiagnosticAdapter
or by adding the <PackageReference> directly to your .csproj file.
<PackageReference Include="Microsoft.Extensions.DiagnosticAdapter" Version="3.1.25" />
Note that the latest stable release of Microsoft.Extensions.DiagnosticAdapter is a 3.1.x release. See my previous post for details.
The next step is to create an adapter to consume the events generated by the MiddlewareAnalysis package.
2. Creating a diagnostic adapter
In order to consume events from the DiagnosticSource, we need to subscribe to the event stream. For further details on how DiagnosticSource works, check out my previous post or the user guide.
The diagnostic adapter is a class with methods for each event you are interested in, decorated with a [DiagnosticName] attribute. I discussed this in more detail in my previous post.
The following adapter subscribes to each of the events emitted by the MiddlewareAnalysis package. I've created a pretty complete adapter, showing all the data available, and using dependency injection for the ILogger.
public class AnalysisDiagnosticAdapter
{
private readonly ILogger<AnalysisDiagnosticAdapter> _logger;
public AnalysisDiagnosticAdapter(ILogger<AnalysisDiagnosticAdapter> logger)
{
_logger = logger;
}
[DiagnosticName("Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareStarting")]
public void OnMiddlewareStarting(HttpContext httpContext, string name, Guid instance, long timestamp)
{
_logger.LogInformation($"MiddlewareStarting: '{name}'; Request Path: '{httpContext.Request.Path}'");
}
[DiagnosticName("Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareException")]
public void OnMiddlewareException(Exception exception, HttpContext httpContext, string name, Guid instance, long timestamp, long duration)
{
_logger.LogInformation($"MiddlewareException: '{name}'; '{exception.Message}'");
}
[DiagnosticName("Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareFinished")]
public void OnMiddlewareFinished(HttpContext httpContext, string name, Guid instance, long timestamp, long duration)
{
_logger.LogInformation($"MiddlewareFinished: '{name}'; Status: '{httpContext.Response.StatusCode}'");
}
}
This adapter creates a separate method for each event that the analysis middleware exposes:
"Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareStarting""Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareFinished""Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareException"
Each event exposes a particular set of named parameters which you can use in your method. For example, the MiddlewareStarting event exposes four parameters:
string name: The name of the currently executing middlewareHttpContext httpContext: TheHttpContextfor the current requestGuid instanceId: A uniqueGuidfor the analysis middlewarelong timestamp: The timestamp at which the middleware started to run, given byStopwatch.GetTimestamp()
Warning: The name of the methods in our adapter are not important, but the name of the parameters are. If you don't name them correctly, you'll get exceptions or
nulls passed to your methods at runtime.
The fact that the whole HttpContext is available to the logger is one of the really powerful points of the DiagnosticSource infrastructure. Instead of the decision about what to log being made at the calling site, it is made by the logging code itself, which has access to the full context of the event.
In this example, we are doing some trivial logging but the possibility is there to do far more interesting things as needs be: inspecting headers; reading query parameters; writing to other data sinks etc.
With an adapter created we can look at wiring it up in our application.
3. Wiring up the diagnostic adapter
In the previous post I described that you need to register your diagnostic adapter using an IObserver<DiagnosticListener>, and using the static DiagnosticListener.AllListeners property. In this post I show a slightly different approach.
By default, the ASP.NET Core GenericHostBuilder adds a DiagnosticListener with the name "Microsoft.AspNetCore" to the dependency injection container (though it does point out this is probably not a good idea!). That means if you retrieve a DiagnosticListener from the DI container and subscribe to it, you will get all the events associated with "Microsoft.AspNetCore".
Armed with that information, lets wire up our diagnostic adapter:
using System.Diagnostics;
WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
WebApplication app = builder.Build();
// Grab the "Microsoft.AspNetCore" DiagnosticListener from DI
var listener = app.Services.GetRequiredService<DiagnosticListener>();
// Create an instance of the AnalysisDiagnosticAdapter using the IServiceProvider
// so that the ILogger is injected from DI
var observer = ActivatorUtilities.CreateInstance<AnalysisDiagnosticAdapter>(app.Services);
// Subscribe to the listener with the SubscribeWithAdapter() extension method
using var disposable = listener.SubscribeWithAdapter(observer);
app.MapGet("/", () => "Hello World!");
app.Run();
We've now fully registered our diagnostic adapter, but we haven't registered the analysis middleware yet, so if you run the application you won't see any events. Let's remedy that and add the middleware.
4. Adding the AnalysisMiddleware
The "simple" way to add the AnalysisMiddleware and AnalysisStartupFilter from the Microsoft.AspNetCore.MiddlewareAnalysis package is to call AddMiddlewareAnalysis() on the IServiceProvider, for example:
WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
// Adds the AnalysisStartupFilter to the pipeline
builder.Services.AddMiddlewareAnalysis();
However, if you do that with .NET 6, you won't get analysis of the full pipeline. This post is already long so I won't go into great detail about why, but in summary, the order IStartupFilters are registered is important. In order to analyse the complete pipeline, the AnalysisStartupFilter needs to be registered first.
Unfortunately, when you call WebApplication.CreateBuilder(args), some filters are automatically registered, so calling AddMiddlewareAnalysis() afterwards means you'll miss some of the pipeline.
The solution is to manually insert the AnalysisStartupFilter at the start of the DI container. With this approach you can capture all the middleware added to the pipeline, including the "implicit" middleware added by the WebApplicationBuilder.
WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
// insert the AnalysisStartupFilter as the first IStartupFilter in the container
builder.Services.Insert(0, ServiceDescriptor.Transient<IStartupFilter, AnalysisStartupFilter>());
WebApplication app = builder.Build();
// ... rest of the configuration
With the IStartupFilter added, and the diagnostic adapter registered, we can fire up the app and give it a test!
5. Run your application and look at the output
With everything setup, you can run your application, make a request, and check the output. If all is setup correctly, you should see the same "Hello World" response, but your console will be peppered with extra details about the middleware being run:
Understanding the analysis output
Assuming this has all worked correctly you should have a series of "MiddlewareStarting" and "MiddlewareFinished" entries in your log. In my case, running in a development environment, and ignoring the other unrelated messages, my sample app gives me the following output when I make a request to the endpoint /:
MiddlewareStarting: 'Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware'; Request Path: '/'
MiddlewareStarting: 'Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware'; Request Path: '/'
MiddlewareStarting: 'Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware'; Request Path: '/'
MiddlewareStarting: 'Microsoft.AspNetCore.MiddlewareAnalysis.AnalysisMiddleware'; Request Path: '/'
MiddlewareStarting: 'Microsoft.AspNetCore.Routing.EndpointMiddleware'; Request Path: '/'
MiddlewareFinished: 'Microsoft.AspNetCore.Routing.EndpointMiddleware'; Status: '200'
MiddlewareFinished: 'Microsoft.AspNetCore.MiddlewareAnalysis.AnalysisMiddleware'; Status: '200'
MiddlewareFinished: 'Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware'; Status: '200'
MiddlewareFinished: 'Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware'; Status: '200'
MiddlewareFinished: 'Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware'; Status: '200'
There are five calls to "MiddlewareStarting" in here, and five corresponding calls to "MiddlewareFinished". That's 4 pieces of middleware added automatically by WebApplication in .NET 6, and one instance of the AnalysisMiddleware.
The presence of the
AnalysisMiddlewarein this list seems like a bug introduced in .NET 6 due to the way it builds the pipeline. I haven't looked into it in detail, as it's not a big issue in general I think—I generally wouldn't use the analysis middleware in production, I consider it more of a debugging tool to visualize your pipeline. But it's something to bear in mind.
As expected, the MiddlewareFinished logs occur in the reverse order to the MiddlewareStarting logs, as the response passes back down through the middleware pipeline. At each stage it lists the status code for the request generated by the completing middleware. This would allows you to see, for example, at exactly which point in the pipeline the status code for a request switched from 200 to an error.
Listening for errors
Previously I said that the analysis middleware generates three different events, one of which is "MiddlewareException". To see this in action, we can throw an exception from a minimal API endpoint, e.g.:
app.Map("/error", ThrowError); // Run ThrowError as the RequestDelegate
app.Run();
static string ThrowError() => throw new NotImplementedException();
The /error endpoint throws an exception when run. If we try this in the browser, the response is handled by the (automatically added) DeveloperExceptionPageMiddleware:
If we look at the logs, you can see that we have "MiddlewareException" entries starting from the EndpointMiddleware, where the exception is bubbling up through the pipeline. At the DeveloperExceptionPageMiddleware, the exception is handled, so we return to seeing "MiddlewareFinished" events instead, though with a status code of 500:
MiddlewareStarting: 'Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware'; Request Path: '/error'
MiddlewareStarting: 'Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware'; Request Path: '/error'
MiddlewareStarting: 'Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware'; Request Path: '/error'
MiddlewareStarting: 'Microsoft.AspNetCore.MiddlewareAnalysis.AnalysisMiddleware'; Request Path: '/error'
MiddlewareStarting: 'Microsoft.AspNetCore.Routing.EndpointMiddleware'; Request Path: '/error'
MiddlewareException: 'Microsoft.AspNetCore.Routing.EndpointMiddleware'; 'The method or operation is not implemented.'
MiddlewareException: 'Microsoft.AspNetCore.MiddlewareAnalysis.AnalysisMiddleware'; 'The method or operation is not implemented.'
MiddlewareException: 'Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware'; 'The method or operation is not implemented.'
MiddlewareFinished: 'Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware'; Status: '500'
MiddlewareFinished: 'Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware'; Status: '500'
Obviously the details I've listed in the log messages are scant, but as I've already described, you have a huge amount of flexibility in your diagnostic adapter to log any details you need.
Event parameters reference
One of the slightly annoying things with the DiagnosticSource infrastructure is the lack of documentation around the events and parameters that a package exposes. You can always look through the source code but that's not exactly user friendly.
As of writing, the current version of Microsoft.AspNetCore.MiddlewareAnalysis exposes three events, with the following parameters:
"Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareStarting"string name: The name of the currently executing middlewareHttpContext httpContext: TheHttpContextfor the current requestGuid instanceId: A unique guid for the analysis middlewarelong timestamp: The current ticks timestamp at which the middleware started to run, given byStopwatch.GetTimestamp()
"Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareFinished"string name: The name of the currently executing middlewareHttpContext httpContext: TheHttpContextfor the current requestGuid instanceId: A unique guid for the analysis middlewarelong timestamp: The timestamp at which the middleware finished runninglong duration: The duration in ticks that the middleware took to run, given by the finish timestamp - the start timestamp.
"Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareException"string name: The name of the currently executing middlewareHttpContext httpContext: TheHttpContextfor the current requestGuid instanceId: A unique guid for the analysis middlewarelong timestamp: The timestamp at which the middleware finished runninglong duration: The duration in ticks that the middleware took to run, given by the finish timestamp - the start timestamp.Exception ex: The exception that occurred during execution of the middleware
Given the names of the events and the parameters must match these values, if you find your diagnostic adapter isn't working, it's worth checking back in the source code to see if things have changed.
Note: The event names must be an exact match, including case, but the parameter names are not case sensitive.
Under the hood
This post is already pretty long, so I won't go into the details of how the middleware analysis filter works in detail, but in summary, the AnalysisStartupFilter adds a piece of AnalysisMiddleware in between each of the "main" middleware. You can read more about this process in a post I wrote some time ago.
Summary
In this post, I showed how you can visualize all the middleware that take part in a request by using the Microsoft.AspNetCore.MiddlewareAnalysis NuGet package. I describe how to create a DiagnosticSource adapter for handling the events it generates, and show how to add it to your application in such a way that you can see all the middleware. This can be useful for debugging exactly what's happening in your middleware pipeline, especially in .NET 6 where some middleware is added transparently without user input.
