Activity.Current is not changd after calling synchronous LINQ query when Npgsql tracing is used with opentelemetry-dotnet's AddEntityFrameworkCoreInstrumentation

[foriequal0]

Steps to reproduce

using var tracerProvider = Sdk.CreateTracerProviderBuilder()
    .SetResourceBuilder(ResourceBuilder.CreateDefault().AddService("npgsql-tester"))
    .SetSampler(new AlwaysOnSampler())
    // This activates up Npgsql's tracing:
    .AddNpgsql()
    .AddEntityFrameworkCoreInstrumentation() // This causes problem with AddNpgsql
    .AddConsoleExporter()
    .Build();

using var context = new SomeDbContext();
var activityIdBefore = Activity.Current.Id;
context.SomeEntity.Any();
var activityIdAfter = Activity.Current.Id;
Assert.Equals(activityIdBefore == activityIdAfter); // Assertion fails

The issue

However, Activity.Current should not be changed after calling synchrnous LINQ query. Asynchronous version doesn't have this problem.

var activityIdBefore = Activity.Current.Id;
await context.SomeEntity.AnyAsync();
var activityIdAfter = Activity.Current.Id;
Assert.Equals(activityIdBefore == activityIdAfter);

Further technical details

Npgsql version: 6.0.7 PostgreSQL version:14.5.0 Operating system:

Other details about my project setup:

[foriequal0]

Weiredly, We haven't had this problem with Pomelo MySQL. We've just found this bug after transitioning our db to PG.

[roji]

Note to self: I can see this happening with the Npgsql EF provider, but not with bare ADO.NET Npgsql (that points towards OpenTelemetry.Instrumentation.EntityFrameworkCore). However, it also doesn't happen with the EF SqlServer provider, indicating a problem in Npgsql...

[manandre]

I also reproduced the issue with Npgsql but not with SqlServer from the same setup.

Code setup

using Microsoft.EntityFrameworkCore;
using Npgsql;
using OpenTelemetry;
using OpenTelemetry.Resources;
using OpenTelemetry.Trace;
using System.Diagnostics;
using Xunit;

// Arrange
using var ctx = new BlogContext();
//ctx.Database.EnsureDeleted();
//ctx.Database.EnsureCreated();

//// Insert a Blog
//ctx.Blogs.Add(new() { Name = "FooBlog" });
//ctx.SaveChanges();

using var tracerProvider = Sdk.CreateTracerProviderBuilder()
    .SetResourceBuilder(ResourceBuilder.CreateDefault().AddService("npgsql-tester"))
    .SetSampler(new AlwaysOnSampler())
    // This activates up Npgsql's tracing:
    .AddNpgsql()
    .AddSqlClientInstrumentation()
    .AddEntityFrameworkCoreInstrumentation() // This causes problem with AddNpgsql
    .AddConsoleExporter()
    .Build();

// Act
var activityIdBefore = Activity.Current?.Id;

var result = ctx.Blogs.Any();
//var result = await ctx.Blogs.AnyAsync();

var activityIdAfter = Activity.Current?.Id;

// Assert
Assert.Equal(activityIdBefore, activityIdAfter); // Assertion fails

public class BlogContext : DbContext
{
    public DbSet<Blog> Blogs { get; set; }

    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
        => optionsBuilder.UseNpgsql(@"Host=localhost;Username=npgsql_tests;Password=npgsql_tests;Database=foo_blog");
        //=> optionsBuilder.UseSqlServer("Server=localhost;Database=foo_blog;Trusted_Connection=True;Encrypt=False");
}

public class Blog
{
    public int Id { get; set; }
    public string Name { get; set; }
}

There is a conflict around the scope of the EF (or SqlServer) Activity and the Npgsql one.

• The EF Activity is:
  • started just before calling the ExecuteReader method on the ADO.NET provider DbCommand
  • stopped just after (i.e. without consuming the returned DbDataReader)
• The Npgsql Activity is:
  • started once the command prepared
  • updated with a received-first-response event before returning the DbDataReader from the ExecuteReader call
  • stopped when the DbDataReader is disposed

As a consequence, the (parent) EF Activity is stopped before the (child) Npgsql one which, when stopped, wrongly sets as Current the stopped EF Activity! However, I still do not explain why the same issue does not also occur with async calls...