Log if request reaches the end of request pipeline (dotnet#47681)

Co-authored-by: Brennan <[email protected]>

Author: 2 people

src/Http/Http/src/Builder/ApplicationBuilder.cs

@@ -3,14 +3,16 @@
 
 using Microsoft.AspNetCore.Http;
 using Microsoft.AspNetCore.Http.Features;
+using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Internal;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Builder;
 
 /// <summary>
 /// Default implementation for <see cref="IApplicationBuilder"/>.
 /// </summary>
-public class ApplicationBuilder : IApplicationBuilder
+public partial class ApplicationBuilder : IApplicationBuilder
 {
     private const string ServerFeaturesKey = "server.Features";
     private const string ApplicationServicesKey = "application.Services";
@@ -117,6 +119,9 @@ public IApplicationBuilder New()
     /// <returns>The <see cref="RequestDelegate"/>.</returns>
     public RequestDelegate Build()
     {
+        var loggerFactory = ApplicationServices?.GetService<ILoggerFactory>();
+        var logger = loggerFactory?.CreateLogger<ApplicationBuilder>();
+
         RequestDelegate app = context =>
         {
             // If we reach the end of the pipeline, but we have an endpoint, then something unexpected has happened.
@@ -139,6 +144,18 @@ public RequestDelegate Build()
             {
                 context.Response.StatusCode = StatusCodes.Status404NotFound;
             }
+
+            if (logger != null && logger.IsEnabled(LogLevel.Information))
+            {
+                Log.RequestPipelineEnd(logger,
+                    context.Request.Method,
+                    context.Request.Scheme,
+                    context.Request.Host.Value,
+                    context.Request.PathBase.Value,
+                    context.Request.Path.Value,
+                    context.Response.StatusCode);
+            }
+
             return Task.CompletedTask;
         };
 
@@ -149,4 +166,12 @@ public RequestDelegate Build()
 
         return app;
     }
+
+    private static partial class Log
+    {
+        [LoggerMessage(1, LogLevel.Information,
+            "Request reached the end of the middleware pipeline without being handled by application code. Request path: {Method} {Scheme}://{Host}{PathBase}{Path}, Response status code: {StatusCode}",
+            SkipEnabledCheck = true)]
+        public static partial void RequestPipelineEnd(ILogger logger, string method, string scheme, string host, string? pathBase, string? path, int statusCode);
+    }
 }

src/Http/Http/test/ApplicationBuilderTests.cs

@@ -3,20 +3,22 @@
 
 using Microsoft.AspNetCore.Http;
 using Microsoft.AspNetCore.Http.Features;
+using Microsoft.AspNetCore.Testing;
+using Microsoft.Extensions.DependencyInjection;
 
 namespace Microsoft.AspNetCore.Builder.Internal;
 
-public class ApplicationBuilderTests
+public class ApplicationBuilderTests : LoggedTest
 {
     [Fact]
-    public void BuildReturnsCallableDelegate()
+    public async Task BuildReturnsCallableDelegate()
     {
         var builder = new ApplicationBuilder(null);
         var app = builder.Build();
 
         var httpContext = new DefaultHttpContext();
 
-        app.Invoke(httpContext);
+        await app.Invoke(httpContext);
         Assert.Equal(404, httpContext.Response.StatusCode);
     }
 
@@ -74,6 +76,55 @@ public async Task BuildImplicitlyThrowsForMatchedEndpointAsLastStep()
         Assert.False(endpointCalled);
     }
 
+    [Fact]
+    public async Task BuildLogAtRequestPipelineEnd()
+    {
+        var services = new ServiceCollection();
+        services.AddSingleton(LoggerFactory);
+        var serviceProvider = services.BuildServiceProvider();
+
+        var builder = new ApplicationBuilder(serviceProvider);
+        var app = builder.Build();
+
+        var httpContext = new DefaultHttpContext();
+        httpContext.Request.Protocol = "HTTP/2";
+        httpContext.Request.Scheme = "https";
+        httpContext.Request.Method = "GET";
+        httpContext.Request.Host = new HostString("localhost:5000");
+        httpContext.Request.Path = "/path";
+        httpContext.Request.PathBase = "/pathbase";
+        httpContext.Request.QueryString = new QueryString("?query=true");
+
+        await app.Invoke(httpContext);
+
+        Assert.Equal(404, httpContext.Response.StatusCode);
+
+        var log = TestSink.Writes.Single(w => w.EventId.Name == "RequestPipelineEnd");
+        Assert.Equal("Request reached the end of the middleware pipeline without being handled by application code. Request path: GET https://localhost:5000/pathbase/path, Response status code: 404", log.Message);
+    }
+
+    [Fact]
+    public async Task BuildDoesNotLogOrChangeStatusWithTerminalMiddleware()
+    {
+        var services = new ServiceCollection();
+        services.AddSingleton(LoggerFactory);
+        var serviceProvider = services.BuildServiceProvider();
+
+        var builder = new ApplicationBuilder(serviceProvider);
+        builder.Use((HttpContext context, RequestDelegate next) =>
+        {
+            context.Response.StatusCode = StatusCodes.Status204NoContent;
+            return Task.CompletedTask;
+        });
+        var app = builder.Build();
+
+        var httpContext = new DefaultHttpContext();
+        await app.Invoke(httpContext);
+
+        Assert.Equal(StatusCodes.Status204NoContent, httpContext.Response.StatusCode);
+        Assert.DoesNotContain(TestSink.Writes, w => w.EventId.Name == "RequestPipelineEnd");
+    }
+
     [Fact]
     public void BuildDoesNotCallMatchedEndpointWhenTerminated()
     {