[bug] Lack of baggage in Logs

[NatMarchand]

Package

OpenTelemetry

Package Version

Package Name	Version
OpenTelemetry.Api	1.9.0
OpenTelemetry	1.9.0
OpenTelemetry.Exporter.Console	1.9.0

Runtime Version

net8.0

Description

We would like to enable log enrichment + compliance (from Microsoft.Extensions.* packages) on our logs and then use OpenTelemetry to export them.
We would also like to log Baggage from our incoming requests.

Steps to Reproduce

The following minimal program :

using OpenTelemetry.Logs;

var builder = WebApplication.CreateBuilder(args);
builder.Logging
    .Configure(o =>
    {
        o.ActivityTrackingOptions =
            ActivityTrackingOptions.ParentId
            | ActivityTrackingOptions.TraceId
            | ActivityTrackingOptions.SpanId
            | ActivityTrackingOptions.Baggage;
    })
    .AddOpenTelemetry(x =>
    {
        x.IncludeScopes = true;
        x.IncludeFormattedMessage = true;
        x.ParseStateValues = true;
    })
    .EnableEnrichment();
builder.Services
    .AddOpenTelemetry()
    .WithLogging(l => l.AddConsoleExporter());
using var app = builder.Build();
app.MapGet("/", (ILoggerFactory logger) =>
{
    logger.CreateLogger("Test").LogInformation("hi!");
});
app.Run();

With the following request:

var httpClient = new HttpClient();
httpClient.DefaultRequestHeaders.TryAddWithoutValidation("baggage", "userId=alice,serverNode=DF%2028,isProduction=false");
httpClient.DefaultRequestHeaders.TryAddWithoutValidation("traceparent", "00-937cf842584e81ec8f6dc240fe0f7d96-6325bed001e9baeb-01");
await httpClient.GetAsync("http://localhost:5194/");

Expected Result

The following output from ConsoleExporter:

info: Test[0]
      hi!
LogRecord.Timestamp:               2024-10-31T14:18:40.9884314Z
LogRecord.TraceId:                 937cf842584e81ec8f6dc240fe0f7d96
LogRecord.SpanId:                  f12dfbc4d63a1ce1
LogRecord.TraceFlags:              Recorded
LogRecord.CategoryName:            Test
LogRecord.Severity:                Info
LogRecord.SeverityText:            Information
LogRecord.FormattedMessage:        hi!
LogRecord.Body:                    hi!
LogRecord.Attributes (Key:Value):
    OriginalFormat (a.k.a Body): hi!
LogRecord.ScopeValues (Key:Value):
[Scope.0]:SpanId: f12dfbc4d63a1ce1
[Scope.0]:TraceId: 937cf842584e81ec8f6dc240fe0f7d96
[Scope.0]:ParentId: 6325bed001e9baeb
[Scope.1]:userId: alice
[Scope.1]:serverNode: DF 28
[Scope.1]:isProduction: false
[Scope.2]:ConnectionId: 0HN7PMRHTTD6G
[Scope.3]:RequestId: 0HN7PMRHTTD6G:00000001
[Scope.3]:RequestPath: /

Resource associated with LogRecord:
telemetry.sdk.name: opentelemetry
telemetry.sdk.language: dotnet
telemetry.sdk.version: 1.9.0
service.name: unknown_service:TestTelemetry

Actual Result

The following output from ConsoleExporter:

info: Test[0]
      hi!
LogRecord.Timestamp:               2024-10-31T14:26:36.6751436Z
LogRecord.TraceId:                 87071c31b8b00d91a2cd9816f0efcab3
LogRecord.SpanId:                  5682b09b7c7041a7
LogRecord.TraceFlags:              None
LogRecord.CategoryName:            Test
LogRecord.Severity:                Info
LogRecord.SeverityText:            Information
LogRecord.FormattedMessage:        hi!
LogRecord.Body:                    hi!
LogRecord.Attributes (Key:Value):
    OriginalFormat (a.k.a Body): hi!
LogRecord.ScopeValues (Key:Value):
[Scope.0]:SpanId: 5682b09b7c7041a7
[Scope.0]:TraceId: 87071c31b8b00d91a2cd9816f0efcab3
[Scope.0]:ParentId: 0000000000000000
[Scope.1]:ConnectionId: 0HN7PN031MRQ6
[Scope.2]:RequestId: 0HN7PN031MRQ6:00000001
[Scope.2]:RequestPath: /

Resource associated with LogRecord:
telemetry.sdk.name: opentelemetry
telemetry.sdk.language: dotnet
telemetry.sdk.version: 1.9.0
service.name: unknown_service:TestTelemetry

It's missing the baggage values :

[Scope.1]:userId: alice
[Scope.1]:serverNode: DF 28
[Scope.1]:isProduction: false

Additional Context

No response

[NatMarchand]

After a quick investigation the issue comes from this code :
https://github.com/open-telemetry/opentelemetry-dotnet/blob/6fa4492a70014ac10a752a3e9834b28e8c1dafcc/src/OpenTelemetry/Logs/LogRecordScope.cs#L42C8-L62C10

When not using enrichment/compliance, scope containing Baggage is of type Microsoft.Extensions.Logging.LoggerFactoryScopeProvider+ActivityBaggageLogScopeWrapper, Microsoft.Extensions.Logging which implements IEnumerable<KeyValuePair<string, object?>>.

However, when using enrichment/compliance, scope containing Baggage is of type Microsoft.Extensions.Logging.LoggerFactoryScopeProvider+ActivityBaggageLogScopeWrapper, Microsoft.Extensions.Telemetry which implements IEnumerable<KeyValuePair<string, string?>>
See https://github.com/dotnet/extensions/blob/e18a05582e64603a0f2e2871bcf555e476570102/src/Libraries/Microsoft.Extensions.Telemetry/Logging/Import/LoggerFactoryScopeProvider.cs#L239C9-L288C10

Therefore, we're falling on the else case and it adds a weird key/value pairs with an empty key.

There are two solutions possible:

• Make Microsoft.Extensions.Logging.LoggerFactoryScopeProvider+ActivityBaggageLogScopeWrapper, Microsoft.Extensions.Telemetry implements IEnumerable<KeyValuePair<string, object?>>
• Add a else if (scope is IEnumerable<KeyValuePair<string, strubg?>> scopeEnumerable) to the conditions

[NatMarchand]

Woops, sorry, forgot to add a title.

[NatMarchand]

Opened both solution PR

[rajkumar-rangaraj]

I tested with the example at https://github.com/open-telemetry/opentelemetry-dotnet/tree/main/examples/AspNetCore. by adding a baggage. The problem does not reproduce there, and I could see the baggage being exported successfully. What versions of .NET and the OpenTelemetry SDK were used for this test?

    OriginalFormat (a.k.a Body): WeatherForecasts generated {count}: {forecasts}
LogRecord.ScopeValues (Key:Value):
[Scope.0]:SpanId: 49b76224b52da803
[Scope.0]:TraceId: 024f96b02b1c8e0c1c01df01c07d922f
[Scope.0]:ParentId: 641aef7dbb1be632
[Scope.1]:baggageKey: baggageValue
[Scope.2]:ConnectionId: 0HN7PPU9T98K2
[Scope.3]:RequestId: 0HN7PPU9T98K2:00000003
[Scope.3]:RequestPath: /WeatherForecast
[Scope.4]:ActionId: c061d120-66eb-4ca7-abe9-8222b8be4980
[Scope.4]:ActionName: Examples.AspNetCore.Controllers.WeatherForecastController.Get (Examples.AspNetCore)
[Scope.5]:Id: 4bd76fa2f7054f5daaae0a74b96b8d6e
[Scope.5]:{OriginalFormat}: {Id}

[CodeBlanch]

@rajkumar-rangaraj

There is a link above which points out the issue: https://github.com/dotnet/extensions/blob/e18a05582e64603a0f2e2871bcf555e476570102/src/Libraries/Microsoft.Extensions.Telemetry/Logging/Import/LoggerFactoryScopeProvider.cs#L239

Microsoft.Extensions.Telemetry is adding a scope which implements IEnumerable<KeyValuePair<string, string?>> instead of the expected IReadOnlyList<KeyValuePair<string, object?>> or IEnumerable<KeyValuePair<string, object?>>.

Interestingly there is one a few lines up which does it correctly: https://github.com/dotnet/extensions/blob/e18a05582e64603a0f2e2871bcf555e476570102/src/Libraries/Microsoft.Extensions.Telemetry/Logging/Import/LoggerFactoryScopeProvider.cs#L150

If you want to reproduce, do this:

using var loggerFactory = LoggerFactory.Create(builder =>
{
    builder.AddOpenTelemetry(logging =>
    {
        logging.IncludeScopes = true;
        logging.AddConsoleExporter();
    });
});

var logger = loggerFactory.CreateLogger<Program>();

using var scope1 = logger.BeginScope(new MyCustomScope1());

using var scope2 = logger.BeginScope(new MyCustomScope2());

logger.LogInformation("hello world");

internal sealed class MyCustomScope1 : IEnumerable<KeyValuePair<string, string?>>
{
    private readonly Dictionary<string, string?> values = new() { ["value1"] = "value1" };

    public IEnumerator<KeyValuePair<string, string?>> GetEnumerator()
        => this.values.GetEnumerator();

    IEnumerator IEnumerable.GetEnumerator()
        => this.GetEnumerator();
}

internal sealed class MyCustomScope2 : IReadOnlyList<KeyValuePair<string, object?>>
{
    private readonly List<KeyValuePair<string, object?>> values = new() { new("value2", "value2") };

    public int Count => this.values.Count;

    public KeyValuePair<string, object?> this[int index]
        => this.values[index];

    public IEnumerator<KeyValuePair<string, object?>> GetEnumerator()
        => this.values.GetEnumerator();

    IEnumerator IEnumerable.GetEnumerator()
        => this.GetEnumerator();
}

That being said, unclear to me whether we should do anything at all. Here is the scope handling code from Microsoft.Extensions.Logging.Console: https://github.com/dotnet/runtime/blob/9f76c05fecce569b09ec888cf21f269df5715fcd/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs#L147

It also won't handle this custom scope using KeyValuePair<string, string?>.

Wouldn't a better solution be Microsoft.Extensions.Telemetry use KeyValuePair<string, object?> instead of expecting every ILoggerProvider out there to add support for KeyValuePair<string, string?>?

There is no contract in ILogger around what can be logged (either directly or as a scope). Our SDK can't handle everything so we have to draw a line somewhere.

[NatMarchand]

Wouldn't a better solution be Microsoft.Extensions.Telemetry use KeyValuePair<string, object?> instead of expecting every ILoggerProvider out there to add support for KeyValuePair<string, string?>?
Our SDK can't handle everything so we have to draw a line somewhere.

Yes, you're right ! That's why I've opened PRs in both repos.
The only thing I fear is that one says it's the other's responsibility and the issue is stuck till the end of time (as my previous #5276)

[rajkumar-rangaraj]

@CodeBlanch Do we know why it worked with ASP.NET Core apps?

[CodeBlanch]

@rajkumar-rangaraj Oh no idea! You actually used Microsoft.Extensions.Telemetry and tried it?