OpenTracing ITracer API results in broken and multiple traces when using the AspNetCore instrumentation

[Blackbaud-LeoWanderer]

Bug Report

List of NuGet packages and
version that you are using:

• OpenTelemetry.Exporter.OpenTelemetryProtocol 1.1.0
• OpenTelemetry.Extensions.Hosting 1.0.0-rc7
• OpenTelemetry.Instrumentation.AspNetCore 1.0.0-rc7
• OpenTelemetry.Shims.OpenTracing 1.0.0-rc7

Runtime version: netcoreapp3.1.

Symptom

Using the AspNetCore instrumentation and the OpenTracing shim results in multiple traces created per HTTP request when using IScope instantiated through the ITracer.BuildSpan("Span name").StartActive() method with using blocks or statements since the trace context is not properly preserved.

What is the expected behavior?

When making a HTTP request a single trace must be created and spans must follow a hierarchy matching the created IScopes.

What is the actual behavior?

1. The initial scope on the HTTP request matches to the HttpRequestIn span and the current activity
2. Calling ITracer.BuildSpan("Span name").StartActive() from that initial scope does not create a new span an any tags created get attached to the HttpRequestIn span and data is overridden
3. When the scope of the using finishes, the current activity is set to null and a further call to ITracer.BuildSpan("Span name").StartActive() creates a new trace
4. Nested spans created using ITracer.BuildSpan("Span name").StartActive() do get correctly attached unless the parent is the HttpRequestIn

Reproduce

Create a new dotnet project using the command dotnet new webapi and install the above mentioned dependencies copying this code block to the *.csproj file created:

<PackageReference Include="OpenTelemetry.Exporter.OpenTelemetryProtocol" Version="1.1.0" />
<PackageReference Include="OpenTelemetry.Extensions.Hosting" Version="1.0.0-rc7" />
<PackageReference Include="OpenTelemetry.Instrumentation.AspNetCore" Version="1.0.0-rc7" />
<PackageReference Include="OpenTelemetry.Shims.OpenTracing" Version="1.0.0-rc7" />

Then go to the Startup.cs file and add the following code to the ConfigureServices method:

var propagator = new CompositeTextMapPropagator(new TextMapPropagator[]
{
    new B3Propagator(),
    new TraceContextPropagator(),
    new BaggagePropagator()
});
Sdk.SetDefaultTextMapPropagator(propagator);

const string serviceName = "service1";
const string sourceName = "system";

var endpoint = Configuration.GetValue<string>("Endpoint");
var headers = Configuration.GetValue<string>("Headers");

services
    .AddOpenTelemetryTracing(builder =>
        builder
            .SetSampler(new AlwaysOnSampler())
            .SetResourceBuilder(ResourceBuilder.CreateDefault().AddService(serviceName))
            .AddSource(sourceName)
            .AddAspNetCoreInstrumentation()
            .AddOtlpExporter(options =>
            {
                options.Endpoint = new Uri(endpoint);
                options.Headers = headers;
            }))
    .AddSingleton<ITracer>(provider =>
    {
        var traceProvider = provider.GetRequiredService<TracerProvider>();
        var tracer = traceProvider.GetTracer(sourceName);
        return new TracerShim(tracer, Propagators.DefaultTextMapPropagator);
    });

Now go to the WeatherForecastController.cs file in the Controllers folder and replace the class declaration for the following code:

[ApiController]
[Route("[controller]")]
public class WeatherForecastController : ControllerBase
{
    private static readonly string[] Summaries = new[]
    {
        "Freezing", "Bracing", "Chilly", "Cool", "Mild", "Warm", "Balmy", "Hot", "Sweltering", "Scorching"
    };

    private readonly ILogger<WeatherForecastController> _logger;
    private readonly ITracer _tracer;

    public WeatherForecastController(ILogger<WeatherForecastController> logger, ITracer tracer)
    {
        _logger = logger;
        _tracer = tracer;
    }

    [HttpGet]
    public IEnumerable<WeatherForecast> Get()
    {
        var rng = new Random();
        return Enumerable.Range(1, 5)
            .Select(index => GetRandomForecast(rng, index))
            .ToArray();
    }

    private WeatherForecast GetRandomForecast(Random rng, int index)
    {
        using var methodScope = _tracer.BuildSpan($"Random forecast for index={index}").StartActive();
        methodScope.Span.SetTag("Started", true);

        using (var databaseScope = _tracer.BuildSpan($"Calling some external resource").StartActive())
        {
            databaseScope.Span.SetTag("Database", "Demo");
        }

        WeatherForecast result;

        using (var computationScope = _tracer.BuildSpan($"Computing forecast for index={index}").StartActive())
        {
            var date = DateTime.Now.AddDays(index);
            var temperatureC = rng.Next(-20, 55);
            var summary = Summaries[rng.Next(Summaries.Length)];

            computationScope.Span.SetTag("Date", date.ToShortDateString());
            computationScope.Span.SetTag("Temperature", temperatureC);
            computationScope.Span.SetTag("Summary", summary);

            result = new WeatherForecast
            {
                Date = date,
                TemperatureC = temperatureC,
                Summary = summary
            };
        }

        methodScope.Span.SetTag("Completed", true);

        return result;
    }
}

Finally go to your appsettings.json file and set the values for the Endpoint and Headers key with your preferred trace visualization tool. I use Honeycomb's free tier for simplicity with these values:

"Endpoint": "https://api.honeycomb.io:443",
"Headers": "x-honeycomb-team=<your Honeycomb key here>,x-honeycomb-dataset=tracing",

Run the application, open a browser and call the Get method in the WeatherForecastController class by following the URL https://localhost:5001/WeatherForecast. Observe the traces created in your Honeycomb dataset (or any other trace visualization tool).

Additional Context

While debugging I took some notes:

• the fact that the first call to the ITracer.BuildSpan("Span name").StartActive() gets attached to the current activity is linked to this code here
• using ITracer.BuildSpan("Span name").AddReference(References.ChildOf, _tracer.ActiveSpan.Context).StartActive() the first time does create a child span of the HttpRequestIn span, but if the using scope finishes the activity is set to null too and the context does not propagate to "sibling using blocks"
• the AspNetCore creates a sibling activity based on this, can this be the reason the correct context is not restored?

[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.

[github-actions]

Closed as inactive. Feel free to reopen if this issue is still a concern.