Skip to content

Commit 188d4b0

Browse files
JamesNKJamesNK
authored
Add unhandled request log and metric to hosting (#48669)
1 parent adf7c0a commit 188d4b0

9 files changed

+151
-34
lines changed

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

Lines changed: 29 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,8 @@ internal sealed class HostingApplicationDiagnostics
2424
private const string DeprecatedDiagnosticsEndRequestKey = "Microsoft.AspNetCore.Hosting.EndRequest";
2525
private const string DiagnosticsUnhandledExceptionKey = "Microsoft.AspNetCore.Hosting.UnhandledException";
2626

27+
private const string RequestUnhandledKey = "__RequestUnhandled";
28+
2729
private readonly ActivitySource _activitySource;
2830
private readonly DiagnosticListener _diagnosticListener;
2931
private readonly DistributedContextPropagator _propagator;
@@ -121,11 +123,15 @@ public void RequestEnd(HttpContext httpContext, Exception? exception, HostingApp
121123
var startTimestamp = context.StartTimestamp;
122124
long currentTimestamp = 0;
123125

124-
// If startTimestamp was 0, then Information logging wasn't enabled at for this request (and calculated time will be wildly wrong)
125-
// Is used as proxy to reduce calls to virtual: _logger.IsEnabled(LogLevel.Information)
126+
// startTimestamp has a value if:
127+
// - Information logging was enabled at for this request (and calculated time will be wildly wrong)
128+
// Is used as proxy to reduce calls to virtual: _logger.IsEnabled(LogLevel.Information)
129+
// - EventLog or metrics was enabled
126130
if (startTimestamp != 0)
127131
{
128132
currentTimestamp = Stopwatch.GetTimestamp();
133+
var reachedPipelineEnd = httpContext.Items.ContainsKey(RequestUnhandledKey);
134+
129135
// Non-inline
130136
LogRequestFinished(context, startTimestamp, currentTimestamp);
131137

@@ -146,6 +152,16 @@ public void RequestEnd(HttpContext httpContext, Exception? exception, HostingApp
146152
customTags,
147153
startTimestamp,
148154
currentTimestamp);
155+
156+
if (reachedPipelineEnd)
157+
{
158+
_metrics.UnhandledRequest();
159+
}
160+
}
161+
162+
if (reachedPipelineEnd)
163+
{
164+
LogRequestUnhandled(context);
149165
}
150166
}
151167

@@ -247,6 +263,17 @@ private void LogRequestFinished(HostingApplication.Context context, long startTi
247263
}
248264
}
249265

266+
[MethodImpl(MethodImplOptions.NoInlining)]
267+
private void LogRequestUnhandled(HostingApplication.Context context)
268+
{
269+
_logger.Log(
270+
logLevel: LogLevel.Information,
271+
eventId: LoggerEventIds.RequestUnhandled,
272+
state: new HostingRequestUnhandledLog(context.HttpContext!),
273+
exception: null,
274+
formatter: HostingRequestUnhandledLog.Callback);
275+
}
276+
250277
[UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026",
251278
Justification = "The values being passed into Write have the commonly used properties being preserved with DynamicDependency.")]
252279
private static void WriteDiagnosticEvent<[DynamicallyAccessedMembers(DynamicallyAccessedMemberTypes.PublicProperties)] TValue>(

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

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@ internal sealed class HostingMetrics : IDisposable
1616
private readonly Meter _meter;
1717
private readonly UpDownCounter<long> _currentRequestsCounter;
1818
private readonly Histogram<double> _requestDuration;
19+
private readonly Counter<long> _unhandledRequestsCounter;
1920

2021
public HostingMetrics(IMeterFactory meterFactory)
2122
{
@@ -29,6 +30,10 @@ public HostingMetrics(IMeterFactory meterFactory)
2930
"request-duration",
3031
unit: "s",
3132
description: "The duration of HTTP requests on the server.");
33+
34+
_unhandledRequestsCounter = _meter.CreateCounter<long>(
35+
"unhandled-requests",
36+
description: "Number of HTTP requests that reached the end of the middleware pipeline without being handled by application code.");
3237
}
3338

3439
// Note: Calling code checks whether counter is enabled.
@@ -80,12 +85,17 @@ public void RequestEnd(string protocol, bool isHttps, string scheme, string meth
8085
}
8186
}
8287

88+
public void UnhandledRequest()
89+
{
90+
_unhandledRequestsCounter.Add(1);
91+
}
92+
8393
public void Dispose()
8494
{
8595
_meter.Dispose();
8696
}
8797

88-
public bool IsEnabled() => _currentRequestsCounter.Enabled || _requestDuration.Enabled;
98+
public bool IsEnabled() => _currentRequestsCounter.Enabled || _requestDuration.Enabled || _unhandledRequestsCounter.Enabled;
8999

90100
private static void InitializeRequestTags(ref TagList tags, bool isHttps, string scheme, string method, HostString host)
91101
{

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

Lines changed: 62 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,62 @@
1+
// Licensed to the .NET Foundation under one or more agreements.
2+
// The .NET Foundation licenses this file to you under the MIT license.
3+
4+
using System.Collections;
5+
using Microsoft.AspNetCore.Http;
6+
7+
namespace Microsoft.AspNetCore.Hosting;
8+
9+
internal sealed class HostingRequestUnhandledLog : IReadOnlyList<KeyValuePair<string, object?>>
10+
{
11+
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}";
12+
13+
internal static readonly Func<object, Exception?, string> Callback = (state, exception) => ((HostingRequestUnhandledLog)state).ToString();
14+
15+
private readonly HttpContext _httpContext;
16+
17+
private string? _cachedToString;
18+
19+
public int Count => 7;
20+
21+
public KeyValuePair<string, object?> this[int index] => index switch
22+
{
23+
0 => new KeyValuePair<string, object?>(nameof(_httpContext.Request.Method), _httpContext.Request.Method),
24+
1 => new KeyValuePair<string, object?>(nameof(_httpContext.Request.Scheme), _httpContext.Request.Scheme),
25+
2 => new KeyValuePair<string, object?>(nameof(_httpContext.Request.Host), _httpContext.Request.Host),
26+
3 => new KeyValuePair<string, object?>(nameof(_httpContext.Request.PathBase), _httpContext.Request.PathBase),
27+
4 => new KeyValuePair<string, object?>(nameof(_httpContext.Request.Path), _httpContext.Request.Path),
28+
5 => new KeyValuePair<string, object?>(nameof(_httpContext.Response.StatusCode), _httpContext.Response.StatusCode),
29+
6 => new KeyValuePair<string, object?>("{OriginalFormat}", OriginalFormat),
30+
_ => throw new ArgumentOutOfRangeException(nameof(index)),
31+
};
32+
33+
public HostingRequestUnhandledLog(HttpContext httpContext)
34+
{
35+
_httpContext = httpContext;
36+
}
37+
38+
public override string ToString()
39+
{
40+
if (_cachedToString == null)
41+
{
42+
var request = _httpContext.Request;
43+
var response = _httpContext.Response;
44+
_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}";
45+
}
46+
47+
return _cachedToString;
48+
}
49+
50+
public IEnumerator<KeyValuePair<string, object?>> GetEnumerator()
51+
{
52+
for (var i = 0; i < Count; i++)
53+
{
54+
yield return this[i];
55+
}
56+
}
57+
58+
IEnumerator IEnumerable.GetEnumerator()
59+
{
60+
return GetEnumerator();
61+
}
62+
}

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

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,4 +20,5 @@ internal static class LoggerEventIds
2020
public const int HostingStartupAssemblyLoaded = 13;
2121
public const int ServerListeningOnAddresses = 14;
2222
public const int PortsOverridenByUrls = 15;
23+
public const int RequestUnhandled = 16;
2324
}

‎src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs

Lines changed: 34 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@
1111
using Microsoft.AspNetCore.Testing;
1212
using Microsoft.Extensions.Diagnostics.Metrics;
1313
using Microsoft.Extensions.Logging;
14+
using Microsoft.Extensions.Logging.Testing;
1415
using Moq;
1516

1617
namespace Microsoft.AspNetCore.Hosting.Tests;
@@ -672,6 +673,39 @@ public void ActivityListenersAreCalled()
672673
Assert.Equal("0123456789abcdef", parentSpanId);
673674
}
674675

676+
[Fact]
677+
public void RequestLogs()
678+
{
679+
var testSink = new TestSink();
680+
var loggerFactory = new TestLoggerFactory(testSink, enabled: true);
681+
682+
var hostingApplication = CreateApplication(out var features, logger: loggerFactory.CreateLogger("Test"), configure: c =>
683+
{
684+
c.Request.Protocol = "1.1";
685+
c.Request.Scheme = "http";
686+
c.Request.Method = "POST";
687+
c.Request.Host = new HostString("localhost");
688+
c.Request.Path = "/hello";
689+
c.Request.ContentType = "text/plain";
690+
c.Request.ContentLength = 1024;
691+
});
692+
693+
var context = hostingApplication.CreateContext(features);
694+
695+
context.HttpContext.Items["__RequestUnhandled"] = true;
696+
context.HttpContext.Response.StatusCode = 404;
697+
698+
hostingApplication.DisposeContext(context, exception: null);
699+
700+
var startLog = testSink.Writes.Single(w => w.EventId == LoggerEventIds.RequestStarting);
701+
var unhandedLog = testSink.Writes.Single(w => w.EventId == LoggerEventIds.RequestUnhandled);
702+
var endLog = testSink.Writes.Single(w => w.EventId == LoggerEventIds.RequestFinished);
703+
704+
Assert.Equal("Request starting 1.1 POST http://localhost/hello - text/plain 1024", startLog.Message);
705+
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);
706+
Assert.StartsWith("Request finished 1.1 POST http://localhost/hello - 404", endLog.Message);
707+
}
708+
675709
private static void AssertProperty<T>(object o, string name)
676710
{
677711
Assert.NotNull(o);

‎src/Hosting/Hosting/test/HostingMetricsTests.cs

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,7 @@ public void MultipleRequests()
2727

2828
using var requestDurationRecorder = new InstrumentRecorder<double>(meterFactory, HostingMetrics.MeterName, "request-duration");
2929
using var currentRequestsRecorder = new InstrumentRecorder<long>(meterFactory, HostingMetrics.MeterName, "current-requests");
30+
using var unhandledRequestsRecorder = new InstrumentRecorder<long>(meterFactory, HostingMetrics.MeterName, "unhandled-requests");
3031

3132
// Act/Assert
3233
Assert.Equal(HostingMetrics.MeterName, meter.Name);
@@ -62,7 +63,8 @@ public void MultipleRequests()
6263
// Request 3
6364
httpContext.Request.Protocol = HttpProtocol.Http3;
6465
var context3 = hostingApplication.CreateContext(httpContext.Features);
65-
context3.HttpContext.Response.StatusCode = StatusCodes.Status200OK;
66+
context3.HttpContext.Items["__RequestUnhandled"] = true;
67+
context3.HttpContext.Response.StatusCode = StatusCodes.Status404NotFound;
6668

6769
Assert.Collection(currentRequestsRecorder.GetMeasurements(),
6870
m => Assert.Equal(1, m.Value),
@@ -86,7 +88,9 @@ public void MultipleRequests()
8688
Assert.Collection(requestDurationRecorder.GetMeasurements(),
8789
m => AssertRequestDuration(m, HttpProtocol.Http11, StatusCodes.Status200OK),
8890
m => AssertRequestDuration(m, HttpProtocol.Http2, StatusCodes.Status500InternalServerError, exceptionName: "System.InvalidOperationException"),
89-
m => AssertRequestDuration(m, HttpProtocol.Http3, StatusCodes.Status200OK));
91+
m => AssertRequestDuration(m, HttpProtocol.Http3, StatusCodes.Status404NotFound));
92+
Assert.Collection(unhandledRequestsRecorder.GetMeasurements(),
93+
m => Assert.Equal(1, m.Value));
9094

9195
static void AssertRequestDuration(Measurement<double> measurement, string protocol, int statusCode, string exceptionName = null)
9296
{

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

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -9,13 +9,13 @@ namespace Microsoft.AspNetCore.Hosting.Tests;
99
public class HostingRequestStartLogTests
1010
{
1111
[Theory]
12-
[InlineData(",XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX", "Request starting GET 1.1 http://,XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX//?query - test 0")]
13-
[InlineData(" XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX", "Request starting GET 1.1 http:// XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX//?query - test 0")]
12+
[InlineData(",XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX", "Request starting 1.1 GET http://,XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX//?query - test 0")]
13+
[InlineData(" XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX", "Request starting 1.1 GET http:// XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX//?query - test 0")]
1414
public void InvalidHttpContext_DoesNotThrowOnAccessingProperties(string input, string expected)
1515
{
1616
var mockRequest = new Mock<HttpRequest>();
17-
mockRequest.Setup(request => request.Protocol).Returns("GET");
18-
mockRequest.Setup(request => request.Method).Returns("1.1");
17+
mockRequest.Setup(request => request.Protocol).Returns("1.1");
18+
mockRequest.Setup(request => request.Method).Returns("GET");
1919
mockRequest.Setup(request => request.Scheme).Returns("http");
2020
mockRequest.Setup(request => request.Host).Returns(new HostString(input));
2121
mockRequest.Setup(request => request.PathBase).Returns(new PathString("/"));

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

Lines changed: 3 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -3,9 +3,7 @@
33

44
using Microsoft.AspNetCore.Http;
55
using Microsoft.AspNetCore.Http.Features;
6-
using Microsoft.Extensions.DependencyInjection;
76
using Microsoft.Extensions.Internal;
8-
using Microsoft.Extensions.Logging;
97

108
namespace Microsoft.AspNetCore.Builder;
119

@@ -16,6 +14,7 @@ public partial class ApplicationBuilder : IApplicationBuilder
1614
{
1715
private const string ServerFeaturesKey = "server.Features";
1816
private const string ApplicationServicesKey = "application.Services";
17+
private const string RequestUnhandledKey = "__RequestUnhandled";
1918

2019
private readonly List<Func<RequestDelegate, RequestDelegate>> _components = new();
2120

@@ -119,9 +118,6 @@ public IApplicationBuilder New()
119118
/// <returns>The <see cref="RequestDelegate"/>.</returns>
120119
public RequestDelegate Build()
121120
{
122-
var loggerFactory = ApplicationServices?.GetService<ILoggerFactory>();
123-
var logger = loggerFactory?.CreateLogger<ApplicationBuilder>();
124-
125121
RequestDelegate app = context =>
126122
{
127123
// 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()
145141
context.Response.StatusCode = StatusCodes.Status404NotFound;
146142
}
147143

148-
if (logger != null && logger.IsEnabled(LogLevel.Information))
149-
{
150-
Log.RequestPipelineEnd(logger,
151-
context.Request.Method,
152-
context.Request.Scheme,
153-
context.Request.Host.Value,
154-
context.Request.PathBase.Value,
155-
context.Request.Path.Value,
156-
context.Response.StatusCode);
157-
}
144+
// Communicates to higher layers that the request wasn't handled by the app pipeline.
145+
context.Items[RequestUnhandledKey] = true;
158146

159147
return Task.CompletedTask;
160148
};
@@ -166,12 +154,4 @@ public RequestDelegate Build()
166154

167155
return app;
168156
}
169-
170-
private static partial class Log
171-
{
172-
[LoggerMessage(1, LogLevel.Information,
173-
"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}",
174-
SkipEnabledCheck = true)]
175-
public static partial void RequestPipelineEnd(ILogger logger, string method, string scheme, string host, string? pathBase, string? path, int statusCode);
176-
}
177157
}

‎src/Http/Http/test/ApplicationBuilderTests.cs

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -99,8 +99,7 @@ public async Task BuildLogAtRequestPipelineEnd()
9999

100100
Assert.Equal(404, httpContext.Response.StatusCode);
101101

102-
var log = TestSink.Writes.Single(w => w.EventId.Name == "RequestPipelineEnd");
103-
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);
102+
Assert.True(httpContext.Items.ContainsKey("__RequestUnhandled"), "Request unhandled flag should be set.");
104103
}
105104

106105
[Fact]

0 commit comments

Comments
 (0)