RequestLoggingMiddleware sets the RequestPath property using IHttpRequestFeature.RawTarget

[mjolka]

Description
RequestLoggingMiddleware sets the RequestPath log event property using IHttpRequestFeature.RawTarget.

As a result, the RequestPath property in the log event emitted by RequestLoggingMiddleware can be different to that in a regular log event.

Reproduction
Configuration is standard:

public static int Main(string[] args)
{
	Log.Logger = new LoggerConfiguration()
		.MinimumLevel.Debug()
		.MinimumLevel.Override("Microsoft", LogEventLevel.Information)
		.MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning)
		.Enrich.FromLogContext()
		.WriteTo.Console(new JsonFormatter())
		.CreateLogger();

	try
	{
		Log.Information("Starting web host");
		CreateHostBuilder(args).Build().Run();
		return 0;
	}
	catch (Exception ex)
	{
		Log.Fatal(ex, "Host terminated unexpectedly");
		return 1;
	}
	finally
	{
		Log.CloseAndFlush();
	}
}

public static IHostBuilder CreateHostBuilder(string[] args) =>
	Host.CreateDefaultBuilder(args)
		.UseSerilog()
		.ConfigureWebHostDefaults(webBuilder =>
		{
			webBuilder.UseStartup<Startup>();
		});

public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
	if (env.IsDevelopment())
	{
		app.UseDeveloperExceptionPage();
		app.UseSwagger();
		app.UseSwaggerUI(c => c.SwaggerEndpoint("/swagger/v1/swagger.json", "SerilogRequestPath v1"));
	}

	app.UseSerilogRequestLogging();

	app.UseHttpsRedirection();

	app.UseRouting();

	app.UseAuthorization();

	app.UseEndpoints(endpoints =>
	{
		endpoints.MapControllers();
	});
}

Logging from the controller:

[ApiController]
[Route("[controller]")]
public class TestController : ControllerBase
{
	private readonly ILogger<TestController> _logger;

	public TestController(ILogger<TestController> logger)
	{
		_logger = logger;
	}

	[HttpGet]
	public IActionResult Get([FromQuery] string token)
	{
		_logger.LogInformation("Hello");
		
		return Ok();
	}
}

Expected behavior
I expect the RequestPath property in the event logged by RequestLoggingMiddleware to be equal to the RequestPath property in the event logged by the controller. However, the RequestPath property in the event logged by the controller includes the query string.

{
	"Timestamp": "2021-02-09T18:16:28.3418609+11:00",
	"Level": "Information",
	"MessageTemplate": "Hello",
	"Properties": {
		"SourceContext": "SerilogRequestPath.Controllers.TestController",
		"ActionId": "1b917552-e13e-49ff-8ff1-d949e0b7a24d",
		"ActionName": "SerilogRequestPath.Controllers.TestController.Get (SerilogRequestPath)",
		"RequestId": "0HM6CPA8DRC2U:00000005",
		"RequestPath": "/Test",
		"ConnectionId": "0HM6CPA8DRC2U"
	}
}

{
	"Timestamp": "2021-02-09T18:16:28.3459735+11:00",
	"Level": "Information",
	"MessageTemplate": "HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms",
	"Properties": {
		"RequestMethod": "GET",
		"RequestPath": "/Test?token=helloworld",
		"StatusCode": 200,
		"Elapsed": 50.1784,
		"SourceContext": "Serilog.AspNetCore.RequestLoggingMiddleware",
		"RequestId": "0HM6CPA8DRC2U:00000005",
		"ConnectionId": "0HM6CPA8DRC2U"
	},
	"Renderings": {
		"Elapsed": [
			{
				"Format": "0.0000",
				"Rendering": "50.1784"
			}
		]
	}
}

Relevant package, tooling and runtime versions
Serilog.AspNetCore 3.4.0.

Additional context
This behaviour can't be changed by the user because RequestLoggingMiddleware adds the RequestPath property after the call to EnrichDiagnosticContext.

RequestPath is already set in the request scope. It doesn't seem necessary for RequestLoggingMiddleware to set a value for it.

[nblumhardt]

Thanks, I think this deserves a closer look 👍

[jarronshih]

Hi, I would like to follow up on this issue.

Just wondering if it is reasonable to use IHttpRequestFeature.Path?
https://docs.microsoft.com/en-us/dotnet/api/microsoft.aspnetcore.owin.owinfeaturecollection.microsoft-aspnetcore-http-features-ihttprequestfeature-path?view=aspnetcore-5.0

Since the fallback code uses httpContext.Request.Path.ToString()

serilog-aspnetcore/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs

Line 120 in abb94e9

requestPath = httpContext.Request.Path.ToString();

[nblumhardt]

Thanks for follow-up, @jarronshih. I guess the question to answer here is whether this will cause problems for users who already rely on the raw path value for monitoring etc.

I hate to fall back on RequestLoggingOptions, but perhaps an options.IncludeRawPath or similar switch might be the way to to?

It'd also be nice to verify that the value we use, and RequestPath pushed by ASP.NET Core, have the same value when IncludeRawPath is false.

[mjolka]

@nblumhardt would you consider making a breaking change and not setting RequestPath in RequestLoggingMiddleware? Users who want the old behaviour could use EnrichDiagnosticContext.

I saw you mention in another issue that query strings were not logged by design. Since RawTarget includes the query string, using the value of RequestPath set by ASP.NET Core would align with that decision.

It'd also be nice to verify that the value we use, and RequestPath pushed by ASP.NET Core, have the same value when IncludeRawPath is false.

I believe this is the relevant code:

https://github.com/dotnet/aspnetcore/blob/8b30d862de6c9146f466061d51aa3f1414ee2337/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs#L406-L408

[nblumhardt]

Thanks for the pointer to the relevant code, @mjolka.

I don't think we should skip setting some value for RequestPath, here; the event includes RawPath in its template, and won't be self-consistent unless the logger pulls in ASP.NET Core's context, which isn't always the case (though it's definitely the most common configuration).

Switching to use ASP.NET Core's logic for constructing the path by default, and opting into the old behavior with IncludeRawPath seems like it could be the nicest middle-ground.

[jarronshih]

@nblumhardt Thanks for the feedback. I update the PR which makes a new option and test it with Sample project. #265

[nblumhardt]

Sorry about the delay on this, should have some time to take a look soon :-)