This post is Part 3 of a four-part series. You might want to read Part 1 and Part 2 first.
Let's continue our series on Middleware in .NET 6 by discussing the pipeline created by Middleware, and specifically why the order in which the middleware are added to the pipeline is very important.
The Sample Project
As with all of my code-focused posts, there's a demo project that demonstrates the ideas in this post over on GitHub. You can check it out here:
exceptionnotfoundOrder of Operations
Recall from Part 1 of this series that middleware forms a pipeline, and the middleware in that pipeline are executed in a certain order, an example of which is shown in this chart:
Requests flow through the middleware in order, and responses bubble up through the middleware in reverse order.
At this point in this series, we have defined two middleware classes: LoggingMiddleware for request/response logging, and SimpleResponseMiddleware which can short-circuit the pipeline to return a response.
In this post, we will start with only LoggingMiddleware in the pipeline:
//...Rest of Program.cs
app.UseLoggingMiddleware();
//...Rest of Program.csAdding a Delay
Let's imagine that we now have a new middleware class, called IntentionalDelayMiddleware, which looks like this:
namespace MiddlewareNET6Demo.Middleware
{
public class IntentionalDelayMiddleware
{
private readonly RequestDelegate _next;
public IntentionalDelayMiddleware(RequestDelegate next)
{
_next = next;
}
public async Task InvokeAsync(HttpContext context)
{
await Task.Delay(100);
await _next(context);
await Task.Delay(100);
}
}
}As you can see, this middleware class waits 100ms both when processing the incoming request and when processing the outgoing response, for a total wait time of 200ms.
This is clearly not something we would want to do in the real world. For this post, we're not operating in the real world. Here, IntentionalDelayMiddleware represents some kind of undefined middleware that takes a predictable amount of time to execute.
We need to add an instance of IntentionalDelayMiddleware to the pipeline. The question is: do we add it before or after the LoggingMiddleware?
In this case, it most likely doesn't matter, since the two middleware classes don't interact and don't process the same thing. For this demo, let's add the IntentionalDelayMiddleware AFTER the LoggingMiddleware:
//...Rest of Program.cs
app.UseLoggingMiddleware();
app.UseIntentionalDelayMiddleware();
//...Rest of Program.csIf we run the app now, we won't really notice a significant difference; 200ms is pretty quick.
Adding an Execution Time Middleware
But now there's a wrinkle (you knew there had to be). Imagine that we get a new requirement from our manager. S/he says that we need to log the execution time of every request to our system.
This is actually pretty straightforward to do with middleware; it uses the Stopwatch class provided by .NET and the LoggingService class we created in Part 2 of this series. Here's the middleware class, named TimeLoggingMiddleware:
using MiddlewareNET6Demo.Logging;
using System.Diagnostics;
namespace MiddlewareNET6Demo.Middleware
{
public class TimeLoggingMiddleware
{
private readonly RequestDelegate _next;
private readonly ILoggingService _logger;
public TimeLoggingMiddleware(RequestDelegate next,
ILoggingService logger)
{
_next = next;
_logger = logger;
}
public async Task InvokeAsync(HttpContext context)
{
Stopwatch watch = new Stopwatch();
watch.Start();
await _next(context);
watch.Stop();
_logger.Log(LogLevel.Information, "Time to execute: " + watch.ElapsedMilliseconds + " milliseconds.");
}
}
}We need to add this to the pipeline. But again, that question remains: exactly where should we do so?
If we add the TimeLoggingMiddleware to the pipeline BEFORE the IntentionalDelayMiddleware, the delay caused by the latter will be included in the measurements taken by the former. If we add it AFTER, the delay will not be included, but is that an accurate measurement, especially if the delay in IntentionalDelayMiddleware changes?
In fact, let's expand our look at the pipeline:
//...Rest of Program.cs
app.UseHttpsRedirection();
app.UseStaticFiles();
//We can also use custom extensions to add middleware to the pipeline.
//Note that if this middleware causes any delay, that delay is
//NOT included in the time logs.
app.UseLoggingMiddleware();
//Here's the time logging middleware
app.UseTimeLoggingMiddleware();
//Here's the delay. At the moment, the delay is INCLUDED in the time logs.
app.UseIntentionalDelayMiddleware();
app.UseRouting();
app.UseAuthorization();
app.MapRazorPages();
app.Run();Given this Program.cs file, where might be a more appropriate place to put the TimeLoggingMiddleware? That answer depends on several questions, such as:
- Do the time logs need to include execution time for things like invalid authorizations? If so, the
TimeLoggingMiddlewaremust be included BEFORE the call toapp.UseAuthorization(). - Routing a call takes a very small, but measurable, amount of time. Do we want to include that? If so, the
TimeLoggingMiddlewaremust be included BEFORE the call toapp.UseRouting().
Like most real-world problems, there's no clear answer here. Given no other direction, I personally would err on the side of NOT including the known delay in the measurement, but this is ultimately a decision that needs to be made by individual developers using their system's known quirks, rules, and guidelines.
The key part that you need to remember is that THIS:
//...Rest of Program.cs
app.UseIntentionalDelayMiddleware();
app.UseTimeLoggingMiddleware();
//...Rest of Program.csis potentially very different from THIS:
//...Rest of Program.cs
app.UseTimeLoggingMiddleware();
app.UseIntentionalDelayMiddleware();
//...Rest of Program.csThis is one example of why the order of the middleware in the pipeline matters.
Coming Up Next!
In the fourth and final part of this series, we will demonstrate a few ways you can conditionally add or execute middleware in the pipeline. Stick around!
Happy Coding!
