Add unhandled request log and metric to hosting

src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs

@@ -24,6 +24,8 @@ internal sealed class HostingApplicationDiagnostics
     private const string DeprecatedDiagnosticsEndRequestKey = "Microsoft.AspNetCore.Hosting.EndRequest";
     private const string DiagnosticsUnhandledExceptionKey = "Microsoft.AspNetCore.Hosting.UnhandledException";
 
+    private const string RequestUnhandledKey = "__RequestUnhandled";
+
     private readonly ActivitySource _activitySource;
     private readonly DiagnosticListener _diagnosticListener;
     private readonly DistributedContextPropagator _propagator;
@@ -121,11 +123,15 @@ public void RequestEnd(HttpContext httpContext, Exception? exception, HostingApp
         var startTimestamp = context.StartTimestamp;
         long currentTimestamp = 0;
 
-        // If startTimestamp was 0, then Information logging wasn't enabled at for this request (and calculated time will be wildly wrong)
-        // Is used as proxy to reduce calls to virtual: _logger.IsEnabled(LogLevel.Information)
+        // startTimestamp has a value if:
+        // - Information logging was enabled at for this request (and calculated time will be wildly wrong)
+        //   Is used as proxy to reduce calls to virtual: _logger.IsEnabled(LogLevel.Information)
+        // - EventLog or metrics was enabled
         if (startTimestamp != 0)
         {
             currentTimestamp = Stopwatch.GetTimestamp();
+            var reachedPipelineEnd = httpContext.Items.ContainsKey(RequestUnhandledKey);
+
             // Non-inline
             LogRequestFinished(context, startTimestamp, currentTimestamp);
 
@@ -146,6 +152,16 @@ public void RequestEnd(HttpContext httpContext, Exception? exception, HostingApp
                     customTags,
                     startTimestamp,
                     currentTimestamp);
+
+                if (reachedPipelineEnd)
+                {
+                    _metrics.UnhandledRequest();
+                }
+            }
+
+            if (reachedPipelineEnd)
+            {
+                LogRequestUnhandled(context);
             }
         }
 
@@ -247,6 +263,17 @@ private void LogRequestFinished(HostingApplication.Context context, long startTi
         }
     }
 
+    [MethodImpl(MethodImplOptions.NoInlining)]
+    private void LogRequestUnhandled(HostingApplication.Context context)
+    {
+        _logger.Log(
+            logLevel: LogLevel.Information,
+            eventId: LoggerEventIds.RequestUnhandled,
+            state: new HostingRequestUnhandledLog(context.HttpContext!),
+            exception: null,
+            formatter: HostingRequestUnhandledLog.Callback);
+    }
+
     [UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026",
         Justification = "The values being passed into Write have the commonly used properties being preserved with DynamicDependency.")]
     private static void WriteDiagnosticEvent<[DynamicallyAccessedMembers(DynamicallyAccessedMemberTypes.PublicProperties)] TValue>(

src/Hosting/Hosting/src/Internal/HostingMetrics.cs

@@ -16,6 +16,7 @@ internal sealed class HostingMetrics : IDisposable
     private readonly Meter _meter;
     private readonly UpDownCounter<long> _currentRequestsCounter;
     private readonly Histogram<double> _requestDuration;
+    private readonly Counter<long> _unhandledRequestsCounter;
 
     public HostingMetrics(IMeterFactory meterFactory)
     {
@@ -29,6 +30,10 @@ public HostingMetrics(IMeterFactory meterFactory)
             "request-duration",
             unit: "s",
             description: "The duration of HTTP requests on the server.");
+
+        _unhandledRequestsCounter = _meter.CreateCounter<long>(
+            "unhandled-requests",
+            description: "Number of HTTP requests that reached the end of the middleware pipeline without being handled by application code.");
     }
 
     // Note: Calling code checks whether counter is enabled.
@@ -80,12 +85,17 @@ public void RequestEnd(string protocol, bool isHttps, string scheme, string meth
         }
     }
 
+    public void UnhandledRequest()
+    {
+        _unhandledRequestsCounter.Add(1);
+    }
+
     public void Dispose()
     {
         _meter.Dispose();
     }
 
-    public bool IsEnabled() => _currentRequestsCounter.Enabled || _requestDuration.Enabled;
+    public bool IsEnabled() => _currentRequestsCounter.Enabled || _requestDuration.Enabled || _unhandledRequestsCounter.Enabled;
 
     private static void InitializeRequestTags(ref TagList tags, bool isHttps, string scheme, string method, HostString host)
     {

src/Hosting/Hosting/src/Internal/HostingRequestUnhandledLog.cs

@@ -0,0 +1,62 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+
+using System.Collections;
+using Microsoft.AspNetCore.Http;
+
+namespace Microsoft.AspNetCore.Hosting;
+
+internal sealed class HostingRequestUnhandledLog : IReadOnlyList<KeyValuePair<string, object?>>
+{
+    private const string OriginalFormat = "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}";
+
+    internal static readonly Func<object, Exception?, string> Callback = (state, exception) => ((HostingRequestUnhandledLog)state).ToString();
+
+    private readonly HttpContext _httpContext;
+
+    private string? _cachedToString;
+
+    public int Count => 7;
+
+    public KeyValuePair<string, object?> this[int index] => index switch
+    {
+        0 => new KeyValuePair<string, object?>(nameof(_httpContext.Request.Method), _httpContext.Request.Method),
+        1 => new KeyValuePair<string, object?>(nameof(_httpContext.Request.Scheme), _httpContext.Request.Scheme),
+        2 => new KeyValuePair<string, object?>(nameof(_httpContext.Request.Host), _httpContext.Request.Host),
+        3 => new KeyValuePair<string, object?>(nameof(_httpContext.Request.PathBase), _httpContext.Request.PathBase),
+        4 => new KeyValuePair<string, object?>(nameof(_httpContext.Request.Path), _httpContext.Request.Path),
+        5 => new KeyValuePair<string, object?>(nameof(_httpContext.Response.StatusCode), _httpContext.Response.StatusCode),
+        6 => new KeyValuePair<string, object?>("{OriginalFormat}", OriginalFormat),
+        _ => throw new ArgumentOutOfRangeException(nameof(index)),
+    };
+
+    public HostingRequestUnhandledLog(HttpContext httpContext)
+    {
+        _httpContext = httpContext;
+    }
+
+    public override string ToString()
+    {
+        if (_cachedToString == null)
+        {
+            var request = _httpContext.Request;
+            var response = _httpContext.Response;
+            _cachedToString = $"Request reached the end of the middleware pipeline without being handled by application code. Request path: {request.Method} {request.Scheme}://{request.Host}{request.PathBase}{request.Path}, Response status code: {response.StatusCode}";
+        }
+
+        return _cachedToString;
+    }
+
+    public IEnumerator<KeyValuePair<string, object?>> GetEnumerator()
+    {
+        for (var i = 0; i < Count; i++)
+        {
+            yield return this[i];
+        }
+    }
+
+    IEnumerator IEnumerable.GetEnumerator()
+    {
+        return GetEnumerator();
+    }
+}

src/Hosting/Hosting/src/Internal/LoggerEventIds.cs

@@ -20,4 +20,5 @@ internal static class LoggerEventIds
     public const int HostingStartupAssemblyLoaded = 13;
     public const int ServerListeningOnAddresses = 14;
     public const int PortsOverridenByUrls = 15;
+    public const int RequestUnhandled = 16;
 }

src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs

@@ -11,6 +11,7 @@
 using Microsoft.AspNetCore.Testing;
 using Microsoft.Extensions.Diagnostics.Metrics;
 using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Testing;
 using Moq;
 
 namespace Microsoft.AspNetCore.Hosting.Tests;
@@ -672,6 +673,39 @@ public void ActivityListenersAreCalled()
         Assert.Equal("0123456789abcdef", parentSpanId);
     }
 
+    [Fact]
+    public void RequestLogs()
+    {
+        var testSink = new TestSink();
+        var loggerFactory = new TestLoggerFactory(testSink, enabled: true);
+
+        var hostingApplication = CreateApplication(out var features, logger: loggerFactory.CreateLogger("Test"), configure: c =>
+        {
+            c.Request.Protocol = "1.1";
+            c.Request.Scheme = "http";
+            c.Request.Method = "POST";
+            c.Request.Host = new HostString("localhost");
+            c.Request.Path = "/hello";
+            c.Request.ContentType = "text/plain";
+            c.Request.ContentLength = 1024;
+        });
+
+        var context = hostingApplication.CreateContext(features);
+
+        context.HttpContext.Items["__RequestUnhandled"] = true;
+        context.HttpContext.Response.StatusCode = 404;
+
+        hostingApplication.DisposeContext(context, exception: null);
+
+        var startLog = testSink.Writes.Single(w => w.EventId == LoggerEventIds.RequestStarting);
+        var unhandedLog = testSink.Writes.Single(w => w.EventId == LoggerEventIds.RequestUnhandled);
+        var endLog = testSink.Writes.Single(w => w.EventId == LoggerEventIds.RequestFinished);
+
+        Assert.Equal("Request starting 1.1 POST http://localhost/hello - text/plain 1024", startLog.Message);
+        Assert.Equal("Request reached the end of the middleware pipeline without being handled by application code. Request path: POST http://localhost/hello, Response status code: 404", unhandedLog.Message);        
+        Assert.StartsWith("Request finished 1.1 POST http://localhost/hello - 404", endLog.Message);
+    }
+
     private static void AssertProperty<T>(object o, string name)
     {
         Assert.NotNull(o);

src/Hosting/Hosting/test/HostingMetricsTests.cs

@@ -27,6 +27,7 @@ public void MultipleRequests()
 
         using var requestDurationRecorder = new InstrumentRecorder<double>(meterFactory, HostingMetrics.MeterName, "request-duration");
         using var currentRequestsRecorder = new InstrumentRecorder<long>(meterFactory, HostingMetrics.MeterName, "current-requests");
+        using var unhandledRequestsRecorder = new InstrumentRecorder<long>(meterFactory, HostingMetrics.MeterName, "unhandled-requests");
 
         // Act/Assert
         Assert.Equal(HostingMetrics.MeterName, meter.Name);
@@ -62,7 +63,8 @@ public void MultipleRequests()
         // Request 3
         httpContext.Request.Protocol = HttpProtocol.Http3;
         var context3 = hostingApplication.CreateContext(httpContext.Features);
-        context3.HttpContext.Response.StatusCode = StatusCodes.Status200OK;
+        context3.HttpContext.Items["__RequestUnhandled"] = true;
+        context3.HttpContext.Response.StatusCode = StatusCodes.Status404NotFound;
 
         Assert.Collection(currentRequestsRecorder.GetMeasurements(),
             m => Assert.Equal(1, m.Value),
@@ -86,7 +88,9 @@ public void MultipleRequests()
         Assert.Collection(requestDurationRecorder.GetMeasurements(),
             m => AssertRequestDuration(m, HttpProtocol.Http11, StatusCodes.Status200OK),
             m => AssertRequestDuration(m, HttpProtocol.Http2, StatusCodes.Status500InternalServerError, exceptionName: "System.InvalidOperationException"),
-            m => AssertRequestDuration(m, HttpProtocol.Http3, StatusCodes.Status200OK));
+            m => AssertRequestDuration(m, HttpProtocol.Http3, StatusCodes.Status404NotFound));
+        Assert.Collection(unhandledRequestsRecorder.GetMeasurements(),
+            m => Assert.Equal(1, m.Value));
 
         static void AssertRequestDuration(Measurement<double> measurement, string protocol, int statusCode, string exceptionName = null)
         {

src/Hosting/Hosting/test/Internal/HostingRequestStartLogTests.cs

@@ -9,13 +9,13 @@ namespace Microsoft.AspNetCore.Hosting.Tests;
 public class HostingRequestStartLogTests
 {
     [Theory]
-    [InlineData(",XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX", "Request starting GET 1.1 http://,XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX//?query - test 0")]
-    [InlineData(" XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX", "Request starting GET 1.1 http:// XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX//?query - test 0")]
+    [InlineData(",XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX", "Request starting 1.1 GET http://,XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX//?query - test 0")]
+    [InlineData(" XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX", "Request starting 1.1 GET http:// XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX//?query - test 0")]
     public void InvalidHttpContext_DoesNotThrowOnAccessingProperties(string input, string expected)
     {
         var mockRequest = new Mock<HttpRequest>();
-        mockRequest.Setup(request => request.Protocol).Returns("GET");
-        mockRequest.Setup(request => request.Method).Returns("1.1");
+        mockRequest.Setup(request => request.Protocol).Returns("1.1");
+        mockRequest.Setup(request => request.Method).Returns("GET");
         mockRequest.Setup(request => request.Scheme).Returns("http");
         mockRequest.Setup(request => request.Host).Returns(new HostString(input));
         mockRequest.Setup(request => request.PathBase).Returns(new PathString("/"));

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

@@ -3,9 +3,7 @@
 
 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;
 
@@ -16,6 +14,7 @@ public partial class ApplicationBuilder : IApplicationBuilder
 {
     private const string ServerFeaturesKey = "server.Features";
     private const string ApplicationServicesKey = "application.Services";
+    private const string RequestUnhandledKey = "__RequestUnhandled";
 
     private readonly List<Func<RequestDelegate, RequestDelegate>> _components = new();
 
@@ -119,9 +118,6 @@ 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.
@@ -145,16 +141,8 @@ 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);
-            }
+            // Communicates to higher layers that the request wasn't handled by the app pipeline.
+            context.Items[RequestUnhandledKey] = true;
 
             return Task.CompletedTask;
         };
@@ -166,12 +154,4 @@ 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

@@ -99,8 +99,7 @@ public async Task BuildLogAtRequestPipelineEnd()
 
         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);
+        Assert.True(httpContext.Items.ContainsKey("__RequestUnhandled"), "Request unhandled flag should be set.");
     }
 
     [Fact]