Registering instrumentation libraries more than once adds duplicate Activity listeners

[johncrim]

Component

OpenTelemetry.Instrumentation.AspNetCore
OpenTelemetry.Instrumentation.Http
(and possibly more)

Package Version

Package Name	Version
OpenTelemetry.Api	1.9.0
OpenTelemetry	1.9.0
OpenTelemetry.Instrumentation.AspNetCore	1.9.0
OpenTelemetry.Instrumentation.Http	1.8.1

Runtime Version

net8.0;net7.0;net6.0

Description

When an instrumentation library is added more than once, it results in duplicate Activity listeners, in which case:

1. Instrumentation is computed and added more than once
2. Filters and Enrich callbacks are called more than once

This is true at least for OpenTelemetry.Instrumentation.AspNetCore and for OpenTelemetry.Instrumentation.Http - it may be true for other instrumentation libraries as well.

It's probably unnecessary for me to explain this, but most of the otel setup is idempotent, and most .NET framework setup is idempotent. Also, given that calls to builder.AddAspNetCoreInstrumentation() are included in eg builder.UseAzureMonitor(), any calls to customize the AspNetCore instrumentation, like:

services.AddOpenTelemetry()
            .UseAzureMonitor(null)
            .AddAspNetCoreInstrumentation(options =>
               {
                   options.Filter = context => ...
                   options.EnrichWithHttpRequest = (activity, request) => ...
               })

will result in duplicate listeners, duplicate instrumentation, and duplicate callbacks for each request.

Steps to Reproduce

This test runs in OpenTelemetry.Instrumentation.AspNetCore.Tests :

namespace OpenTelemetry.Instrumentation.AspNetCore.Tests;

[Collection("AspNetCore")]
public class SetupTests
    : IClassFixture<WebApplicationFactory<Program>>
{
    private readonly WebApplicationFactory<Program> factory;

    public SetupTests(WebApplicationFactory<Program> factory)
    {
        this.factory = factory;
    }

    [Fact]
    public async Task AddAspNetCoreInstrumentation_IsIdempotent()
    {
        var exportedItems = new List<Activity>();
        int filterCalls = 0;
        int enrichRequestCalls = 0;

        using (var client = this.factory
                   .WithWebHostBuilder(builder =>
                   {
                       builder.ConfigureTestServices((IServiceCollection services) =>
                       {
                           services.AddOpenTelemetry()
                               .WithTracing(builder => builder
                                   .AddAspNetCoreInstrumentation(options =>
                                   {
                                       options.Filter = context =>
                                       {
                                           filterCalls++;
                                           return true;
                                       };
                                       options.EnrichWithHttpRequest = (activity, request) =>
                                       {
                                           enrichRequestCalls++;
                                       };
                                   })
                                   .AddAspNetCoreInstrumentation() // 2nd call on purpose to validate idempotency
                                   .AddInMemoryExporter(exportedItems));
                       });
                       builder.ConfigureLogging(loggingBuilder => loggingBuilder.ClearProviders());
                   })
                   .CreateClient())
        {
            using var response = await client.GetAsync(new Uri("/api/values"));
        }

        SpinWait.SpinUntil(() => exportedItems.Count == 1, TimeSpan.FromSeconds(1));

        Assert.Equal(1, filterCalls);
        Assert.Equal(1, enrichRequestCalls);
    }
}

Note that measuring the number of filter and callback calls is an easy and accessible way to determine how many Activity listeners are running. The test fails b/c there 2 calls each to filter and enrich for the single request.

Expected Result

Calling .AddAspNetCoreInstrumentation() and .AddHttpClientInstrumentation() in multiple places during startup results in effectively a single instance of the instrumentation, and a single Activity listener for each Activity source that is instrumented.

Actual Result

1 additional Activity listener for each time .AddAspNetCoreInstrumentation() and .AddHttpClientInstrumentation() are called.

Additional Context

The part of .AddAspNetCoreInstrumentation() that causes the problem is:

        return builder.AddInstrumentation(sp =>
        {
            var options = sp.GetRequiredService<IOptionsMonitor<AspNetCoreTraceInstrumentationOptions>>().Get(name);

            return new AspNetCoreInstrumentation(
                new HttpInListener(options));
        });

https://github.com/open-telemetry/opentelemetry-dotnet-contrib/blob/6f3ae2dd61a3fa8e520b1eb626d6de2873bab9f0/src/OpenTelemetry.Instrumentation.AspNetCore/AspNetCoreInstrumentationTracerProviderBuilderExtensions.cs#L75C1-L81C12

Which always creates and adds a new listener.

I don't think builder.AddInstrumentation() can be made idempotent on the instrumentation type without breaking some valid use-cases. Potentially object equality could be used to determine equivalency; or another option is to add a builder.TryAddInstrumentation() method that only creates the instrumentation if the instrumentation type hasn't already been instantiated.

[YayBurritos]

Possibly happening with OpenTelemetry.Instrumentation.StackExchangeRedis (we're using v1.0.0-rc9.14) as well.

Need to do more debugging, but have definitely noticed duplicate trace spans for a given call to Redis. Our app has multiple ConnectionMultiplexers for different purposes that are all instrumented with a call to AddRedisInstrumentation.

But we haven't noticed duplicate spans for other instrumentations so far (just Redis).

[johncrim]

Hi @YayBurritos - in the cases that I reported, the duplicate listeners don't result in duplicate spans, because the Activities are created/started/stopped by AspNetCore or HttpClient - instead all of the instrumentation logic is just running more than once, and if any of that logic is not idempotent (including filters or enrichers) then that's a bigger problem than happens by default.

If the Activity were created/started/stopped by the instrumentation library, then that could result in duplicate spans, and the root cause would be this same bug.

[vishweshbankwar]

@johncrim - Is the purpose for calling .AddAspNetCoreInstrumentation() multiple times is to just configure the options?

Options can also configured as below:

builder.Services.Configure<AspNetCoreTraceInstrumentationOptions>(options =>
{
    options.RecordException = true;
    ...
    ...
});

[johncrim]

@vishweshbankwar - The reason it's called more than once is to ensure that AspNetCoreInstrumentation is included. Configuring in multiple locations is a secondary requirement.

I'm aware that you can configure options using Configure<Options>, and if I only needed to configure options (and had another way to guarantee that AspNetCoreInstrumentation was added) that would be sufficient.

But that doesn't work b/c we have different setup code in different places that each need to ensure that AspNetCoreInstrumentation is registered. For example, if I'm adding request telemetry filters and request enrichers in a library, I need to ensure that AspNetCoreInstrumentation is included (b/c otherwise the filters won't be called). But the app itself also needs to call .UseAzureMonitor(), which also calls .AddAspNetCoreInstrumentation() a second time.

But also - this is a bug - the API violates expectations.

[YayBurritos]

@johncrim : Just following up on this. I created this enhancement request related to our OpenTelemetry.Instrumentation.StackExchangeRedis issue: #1997.

May not be related to your issue here (or even helpful), but wanted to pass it along. Thanks!