serilog / serilog-aspnetcore

Serilog integration for ASP.NET Core
Apache License 2.0
1.29k stars 203 forks source link

RequestLoggingMiddleware always logs requests to health check endpoint #332

Closed cremor closed 1 year ago

cremor commented 1 year ago

Description The readme states the following for the UseSerilogRequestLogging() method:

The middleware will not time or log components that appear before it in the pipeline.

This seems to be not true for health check endpoints (HealthCheckMiddleware). Requests to those are always logged (and therefore cause log spam).

Reproduction Add the following to a ASP.NET Core 7 project that uses Serilog:

builder.Services.AddHealthChecks();
[...]
app.MapHealthChecks("/healthz");
app.UseSerilogRequestLogging();

Expected behavior Since MapHealthChecks() is called before UseSerilogRequestLogging() I do not expect to see any log lines from RequestLoggingMiddleware for calls to the health check endpoint.

Relevant package, tooling and runtime versions Serilog.AspNetCore 7.0.0 on .NET 7

Additional context There are ways to disable the health check request logging manually, as described in https://github.com/serilog/serilog-aspnetcore/issues/121#issuecomment-525243530. But I think it should either work as documented by default, or at least mention this case (including solutions) in the readme.

nblumhardt commented 1 year ago

Hi @cremor!

I'm quite surprised by this behavior, but it turns out that this is because MapHealthChecks is building endpoint routes, while UseHealthChecks actually adds the middleware at the point in the pipeline that it's called.

TL;DR is - replace your call to MapHealthChecks with UseHealthChecks and pipeline ordering will start working as expected.

This one's not going to be unique (or even related directly to) Serilog.AspNetCore - it just comes down to how the pipeline is built.

Let me know if this sorts it out for you. Cheers!

cremor commented 1 year ago

Interesting, thanks for your analysis.

Both methods register the same HealthCheckMiddleware. The only difference is how it is mapped. See here and here.

The method UseHealthChecks isn't even mentioned in the current version of the documentation. Only MapHealthChecks is. It seems like this also confuses other people, because I found https://github.com/dotnet/AspNetCore.Docs/issues/29421 and https://github.com/dotnet/AspNetCore.Docs/pull/29439 about it.

This solves the problem for me, thanks (altough I still use a Serilog filter to also filter out the EF Core logging that happens during a health check). But what do you think about adding a note for this special case to the readme?

nblumhardt commented 1 year ago

Thanks for the follow up @cremor!

The challenge for detailed usage notes in the README is that they can be a pain to keep up-to-date/get out of date quickly. Given the way search results are ranked, it's pretty likely that people will find this thread when the hit the issue in future.

cremor commented 1 year ago

Ok for me.

IvanPraskov commented 1 month ago

@cremor, @nblumhardt Just to add that you can use short circuiting after a specific endpoint is hit now in .NET 8 for anyone that has still faced this and wants to use MapHealthChecks instead of UseHealthChecks https://learn.microsoft.com/en-us/aspnet/core/fundamentals/routing?view=aspnetcore-8.0#short-circuit-middleware-after-routing Also described as an example here - https://learn.microsoft.com/en-us/aspnet/core/host-and-deploy/health-checks?view=aspnetcore-8.0#usehealthchecks-vs-maphealthchecks