Duplicate Log Attribute Keys

[c4brei]

Question

Use Github Discussions.

Currently when using Logging attributes in Scope and LogMessage I observed, that the dotnet exporter exports every attribute not just the latest occurrence.

using (logger.BeginScope(new[] { new KeyValuePair<string, object>("fooAttr", "abc - scope0") }))    // scope 0
using (logger.BeginScope(new[] { new KeyValuePair<string, object>("fooAttr", "def - scope1") }))    // scope 1
{
    logger.LogInformation("Hello Log Message: '{fooAttr}' '{barAttr}'", "ghi - log msg", "barAttrValue");
}

In this example fooAttr is added 3 times to the attribute list

Output of ConsoleLogExporter:

LogRecord.Timestamp:               2023-03-22T12:44:02.5096056Z
LogRecord.CategoryName:            Program
LogRecord.LogLevel:                Information
LogRecord.FormattedMessage:        Hello Log Message: 'ghi - log msg' 'barAttrValue'
LogRecord.StateValues (Key:Value):
    fooAttr: ghi - log msg
    barAttr: barAttrValue
    OriginalFormat (a.k.a Body): Hello Log Message: '{fooAttr}' '{barAttr}'
LogRecord.ScopeValues (Key:Value):
[Scope.0]:fooAttr: abc - scope0
[Scope.1]:fooAttr: def - scope1

OpenTelemetry Collector receives list with duplicate attribute keys:

Timestamp: 2023-03-22 12:44:02.5096056 +0000 UTC
SeverityText: Information
SeverityNumber: Info(9)
Body: Str(Hello Log Message: 'ghi - log msg' 'barAttrValue')
Attributes:
     -> dotnet.ilogger.category: Str(Program)
     -> fooAttr: Str(ghi - log msg)
     -> barAttr: Str(barAttrValue)
     -> {OriginalFormat}: Str(Hello Log Message: '{fooAttr}' '{barAttr}')
     -> fooAttr: Str(abc - scope0)
     -> fooAttr: Str(def - scope1)
Trace ID:
Span ID:
Flags: 0

This could be an unintentional side effect from the removal of the scope depth prefix (#3843).
It seems that during serialization, first all attributes from the log message then all attributes from the scopes are serialized (beginning with the oldest scope). But no deduplication is done during this process.

The specification describes Log-Attributes to be a 'map<string, any>' where attribute keys are unique (data-model.md). Currently the actual output seems to be only a serialized list.

Is this behavior intended and the specification incomplete or is this behavior a Bug?

Additional Context

Depending on a receiving backend tool the attribute list may be interpreted differently. I.e. in Loki only the last occurrence of an attribute is parsed -> fooAttr is def - scope1 instead of ghi - log msg

Reproduce

Using net6.0 and the following OpenTelemetry NuGet-Packages

    <PackageReference Include="Microsoft.Extensions.Logging" Version="7.0.0" />
    <PackageReference Include="OpenTelemetry.Exporter.Console" Version="1.4.0" />
    <PackageReference Include="OpenTelemetry.Exporter.OpenTelemetryProtocol" Version="1.4.0" />
    <PackageReference Include="OpenTelemetry.Exporter.OpenTelemetryProtocol.Logs" Version="1.4.0-rc.4" />

// See https://aka.ms/new-console-template for more information

using Microsoft.Extensions.Logging;
using OpenTelemetry.Exporter;
using OpenTelemetry.Logs;

using var loggerFactory = LoggerFactory.Create(builder =>
{
    builder.AddOpenTelemetry(options =>
    {
        options.AddConsoleExporter();
        options.AddOtlpExporter(o =>
        {
            o.Protocol = OtlpExportProtocol.Grpc;
            o.HttpClientFactory = () =>
            {
                var client = new HttpClient();

                return client;
            };
            o.Endpoint = new Uri("http://localhost:4317/v1/logs");
        });
        options.IncludeScopes = true;
        options.ParseStateValues = true;
        options.IncludeFormattedMessage = true;
    });
});

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

using (logger.BeginScope(new[] { new KeyValuePair<string, object>("fooAttr", "abc - scope0") }))    // scope 0
using (logger.BeginScope(new[] { new KeyValuePair<string, object>("fooAttr", "def - scope1") }))    // scope 1
{
    logger.LogInformation("Hello Log Message: '{fooAttr}' '{barAttr}'", "ghi - log msg", "barAttrValue");
}

[cijothomas]

Deduplication is going to be expensive. The OTLP proto does not validate (its basically List and not a Map), so the onus is on the upstream to avoid duplicates.

1. As a user prevent duplicates.
2. OTel sdk OR OTLP Exporter can likely provide an opt-in mechanism to dedup for users who cannot ensure 1 and can accept the perf penality.

It is not an oversight, this was considered in the PR itself https://github.com/open-telemetry/opentelemetry-dotnet/pull/3843/files#diff-e28eaa16d5ac47130740a2783c474f316e9a1699aa3ada3a537951246e7cf517R172

Also, scopes is not the only way one can have duplicates. Logger.LogInfo("hello from {fruit} {fruit} {fruit}", "apple", "banana", "mango"); can also cause duplicates.

[cijothomas]

@c4brei btw, excellent write up with clear description and repro steps!

[cijothomas]

Tagged it for the OTLP Log Exporter stable release milestone. We could end up with not doing anything (and just ask users to not produce duplicate attributes), or provide opt-in mechanism to dedup.

[c4brei]

Thank you for the quick answer :)

The mentioned option to deduplicate Attributes would be very helpful.
The resulting Mapping errors from duplicates in backend tools (i.e. the mentioned Loki case) can be hard to notice when the attribute value itself is difficult to read (e.g. guid).

In a larger project it will be difficult to enforce or remind everyone to use attributes with care.
Especially since attribute creation can be hidden and retroactively altered just by adding a scope, with the same attribute name, earlier in the call chain, thus it is easy to introduce a mistake.
You would have to go up/down the call chain to check for duplicate attribute names.

[c4brei]

Some additional ideas that might be helpful when this topic comes around for the stable release

Adjust attribute serialization order

• first serialize scopes (oldest to youngest)
• then attributes from LogMessage
• so the last attribute in the list should always be the most recent one that was defined

Option to disable export of Attributes defined in a LogMessage

• so that logger.LogInformation("Some fruit '{fruit}'", "banana"); behaves like logger.LogInformation($"Some fruit '{fruitObj.name}'");
• this could prevent accidental creation of duplicate attributes
• and prevent some performance decrease of string interpolation

[cijothomas]

so that logger.LogInformation("Some fruit '{fruit}'", "banana"); behaves like logger.LogInformation($"Some fruit '{fruitObj.name}'");

This defeats the purpose of structured logging by putting everything into a string, so this should be discouraged.!

[github-actions]

This issue was marked stale due to lack of activity and will be closed in 7 days. Commenting will instruct the bot to automatically remove the label. This bot runs once per day.