Middleware in ASP.NET 6 - Order of Operations

 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.cs

Adding 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.cs

If 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 TimeLoggingMiddleware must be included BEFORE the call to app.UseAuthorization().
• Routing a call takes a very small, but measurable, amount of time. Do we want to include that? If so, the TimeLoggingMiddleware must be included BEFORE the call to app.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.cs

is potentially very different from THIS:

//...Rest of Program.cs

app.UseTimeLoggingMiddleware();
app.UseIntentionalDelayMiddleware();

//...Rest of Program.cs

This is one example of why the order of the middleware in the pipeline matters.