[bug] OpenTelemetryLogger searches {OriginalFormat} attribute only at last position.
#5,983 opened on 2024年11月16日
Repository metrics
- Stars
- (3,725 stars)
- PR merge metrics
- (PR metrics pending)
説明
Package
OpenTelemetry
Package Version
| Package Name | Version |
|---|---|
| OpenTelemetry | 1.10.0 |
| OpenTelemetry.Exporter.Console | 1.10.0 |
| Microsoft.Extensions.Telemetry.Abstractions | 9.0.0 |
Runtime Version
net9.0
Description
There is a private TryGetOriginalFormatFromAttributes method in OpenTelemetryLogger class that tries to search {OriginalFormat} attribute only at last element of the list. I guess this decision was made to reflect behavior of built-in Microsoft Logger and for performance reasons.
But there are logging implementations that can write this attribute at other positions.
For example, we can face a problem when using modern logging source generator approach and add reference to Microsoft.Extensions.Telemetry.Abstractions nuget package. This official MS package contains it's own logging generator, that writes {OriginalFormat} attribute at the first element of list. Example of generated code:
state.TagArray[1] = new("Property", property);
state.TagArray[0] = new("{OriginalFormat}", "Log event with {Property}"); // <--- Generator writes attribute at first element
As the result, OpenTelemetryLogger can't find attribute and choose wrong code path to fill Body and FormattedMessage properties of LogRecord.
Is it a bug, or something like an expected behavior? Guess there can be other implementations that don't respect the rule "{OriginalFormat} should always be last attribute". So searching only at last position feels like too strict. If perf is critical and we can't enumerate whole list, maybe searching also at first position could be a good compromise?
Steps to Reproduce
using Microsoft.Extensions.Logging;
using OpenTelemetry.Logs;
var factory = LoggerFactory.Create(builder =>
{
builder.AddOpenTelemetry(options =>
{
options.IncludeFormattedMessage = true;
options.AddConsoleExporter();
});
});
var logger = factory.CreateLogger<Program>();
logger.LogEvent(42);
internal static partial class LoggerEvents
{
[LoggerMessage(0, LogLevel.Information, "Log event with {Property}")]
public static partial void LogEvent(this ILogger logger, int property);
}
Expected Result
(Some output omitted for simplicity).
I expect to see message template in LogRecord.Body:
LogRecord.FormattedMessage: Log event with 42
LogRecord.Body: Log event with {Property} <--------
LogRecord.Attributes (Key:Value):
Property: 42
OriginalFormat (a.k.a Body): Log event with {Property}
Actual Result
(Some output omitted for simplicity).
I see formatted message in LogRecord.Body because OpenTelemetryLogger didn't find attribute at last position and chose wrong path to fill properties of LogRecord.
LogRecord.FormattedMessage: Log event with 42
LogRecord.Body: Log event with 42 <--------
LogRecord.Attributes (Key:Value):
OriginalFormat (a.k.a Body): Log event with {Property}
Property: 42
Additional Context
No response