open-telemetry/opentelemetry-dotnet

[bug] OpenTelemetryLogger searches {OriginalFormat} attribute only at last position.

Open

#5,983 opened on 2024年11月16日

GitHub で見る
 (2 comments) (0 reactions) (0 assignees)C# (889 forks)auto 404
bughelp wantedpkg:OpenTelemetry

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

コントリビューターガイド