Skip to content

Log if request reaches the end of request pipeline #47681

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 6 commits into from
Apr 18, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
27 changes: 26 additions & 1 deletion src/Http/Http/src/Builder/ApplicationBuilder.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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";
Expand Down Expand Up @@ -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.
Expand All @@ -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;
};

Expand All @@ -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);
}
}
57 changes: 54 additions & 3 deletions src/Http/Http/test/ApplicationBuilderTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}

Expand Down Expand Up @@ -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()
{
Expand Down