serilog / serilog

Simple .NET logging with fully-structured events
https://serilog.net
Apache License 2.0
7.26k stars 798 forks source link

SourceContext for generated code contains fully qualified name #1793

Closed yohny closed 1 year ago

yohny commented 1 year ago

I have an ASP.NET 6 web API project that uses Serilog. The logging is configured to with app.UseSerilogRequestLogging() and with customized message template, which includes {SourceContext} in addition to default. The log messages with one exception have expected value for {SourceContext}, which is the type name, like MyAssembly.MyClass. The one case where the {SourceContext} value is a bit unexpected has to do with Refit.

Normally when making request from controller to some external API using normal httpClient the log looks as follows:

2023-01-05 18:45:53.898 +01:00 [INF] System.Net.Http.HttpClient.MyController.LogicalHandler Start processing HTTP request POST http://example.com/stuff
2023-01-05 18:45:53.902 +01:00 [INF] System.Net.Http.HttpClient.MyController.ClientHandler Sending HTTP request POST http://example.com/stuff
2023-01-05 18:45:56.141 +01:00 [INF] System.Net.Http.HttpClient.MyController.ClientHandler Received HTTP response headers after 2233.1195ms - 200
2023-01-05 18:45:56.145 +01:00 [INF] System.Net.Http.HttpClient.MyController.LogicalHandler End processing HTTP request after 2247.3057ms - 200

However when makig a request using Refit (aka. runtime generated code), the log looks like this:

2023-01-05 18:45:53.861 +01:00 [INF] System.Net.Http.HttpClient.Refit.Implementation.Generated+MyProjectIApi, MyProject, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null.LogicalHandler Start processing HTTP request POST http://example.com/stuff
2023-01-05 18:45:56.157 +01:00 [INF] System.Net.Http.HttpClient.Refit.Implementation.Generated+MyProjectIApi, MyProject, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null.ClientHandler Sending HTTP request POST http://example.com/stuff
2023-01-05 18:45:58.288 +01:00 [INF] System.Net.Http.HttpClient.Refit.Implementation.Generated+MyProjectIApi, MyProject, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null.ClientHandler Received HTTP response headers after 2127.1207ms - 200
2023-01-05 18:45:58.290 +01:00 [INF] System.Net.Http.HttpClient.Refit.Implementation.Generated+MyProjectIApi, MyProject, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null.LogicalHandler End processing HTTP request after 4438.029ms - 200

The problem being that instead of just type name, there appears to be fully qualified type name (including assembly, version, culture and public token)

Describe the solution you'd like I would prefer if only the type name would be in SourceContext also for generated code, to avoid unnecessary log pollution and to be consistent with standard httpClient logging.

Describe alternatives you've considered I tried implementing custom Logger as suggested here https://stackoverflow.com/questions/48470090/serilog-format-sourcecontext-for-showing-only-assembly-name, but it had no effect on SourceContext of generated refit code.

Additional context Serilog 2.12.0, Serilog.AspNetCore 6.1.0 repository with repro project https://github.com/yohny/SerilogRefiRepro - when launched go to swagger/where there are 2 endpoints exposed (one making external request using httpClient, the other using refit) - try them and observe the console log

sungam3r commented 1 year ago

Serilog uses FullName

Gets the fully qualified name of the type, including its namespace but not its assembly.

, not AssemblyQualifiedName, see https://github.com/serilog/serilog/blob/7f1e791c411457eb392a9b4833a5545a90a67ba7/src/Serilog/Core/Logger.cs#L164

yohny commented 1 year ago

I added repro project at https://github.com/yohny/SerilogRefiRepro where the logging issue can be observed

sungam3r commented 1 year ago

See

https://github.com/reactiveui/refit/blob/246ee8d9989c29092fdaba6821d5b3098a5ccf9e/Refit/UniqueName.cs#L47

and

https://github.com/reactiveui/refit/blob/246ee8d9989c29092fdaba6821d5b3098a5ccf9e/Refit.HttpClientFactory/HttpClientFactoryExtensions.cs#L50

This is refit implementation of http client name. Then this name will be mapped/used as Serilog's SourceContext somewhere in internals of Serilog.Extensions.Logging package IMO. Note that you inject MEL ILogger instead of Serilog's ILogger.

@nblumhardt may help more here than I.

nblumhardt commented 1 year ago

Serilog maps MEL's logger name to SourceContext. It seems that this isn't always a type name.

In Serilog also, SourceContext is just a strign, it's not strictly defined as always being a FullName but that's the general default.

You can work around this by implementing an ILogEventEnricher that you plug in using Enrich.With(...); in the enricher, you can first retrieve the SourceContext property, trim it as required, and then update it back on the LogEvent.

Hope this helps!

yohny commented 1 year ago

ok, I see that my issue is not actually caused by Serilog lib, thanks for answers