Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

EF Core and SqlClient instrumentation enabled at the same time produce wrong spans #1764

Open
virtes opened this issue Oct 31, 2023 · 5 comments · May be fixed by #2280
Open

EF Core and SqlClient instrumentation enabled at the same time produce wrong spans #1764

virtes opened this issue Oct 31, 2023 · 5 comments · May be fixed by #2280
Assignees
@zivaninstana
Labels
bug Something isn't working comp:instrumentation.entityframeworkcore Things related to OpenTelemetry.Instrumentation.EntityFrameworkCore comp:instrumentation.sqlclient Things related to OpenTelemetry.Instrumentation.SqlClient

Comments

@virtes
Copy link

virtes commented Oct 31, 2023 •
edited
Loading

Bug Report

List of all OpenTelemetry NuGet
packages and version that you are
using (e.g. OpenTelemetry 1.0.2):

  • OpenTelemetry - 1.7.0-alpha.1
  • OpenTelemetry.Exporter.Console - 1.7.0-alpha.1
  • OpenTelemetry.Exporter.OpenTelemetryProtocol - 1.7.0-alpha.1
  • OpenTelemetry.Instrumentation.EntityFrameworkCore - 1.0.0-beta.8
  • OpenTelemetry.Instrumentation.SqlClient - 1.6.0-beta.2

Runtime version (e.g. net462, net48, netcoreapp3.1, net6.0 etc. You can
find this information from the *.csproj file):

  • net6.0
  • net7.0

Symptom

Using AddSqlClientInstrumentation and AddEntityFrameworkCoreInstrumentation at the same time leads to miss parent span.

What is the expected behavior?

Exports two spans:

  1. EF Core span
  2. SQL Client span, with EF Core span as parent

What is the actual behavior?

  1. EF Core span is missed in the output
  2. SQL Client span, with EF Core span as parent

Output from console exporter - I have only SQL Client span, which has ParentSpanId of EF Core span.

Activity.TraceId:            916f8741531547a078d9966039e4f905
Activity.SpanId:             96a036d8982f1155
Activity.TraceFlags:         Recorded
Activity.ParentSpanId:       8580d5d7086bf8c8
Activity.ActivitySourceName: OpenTelemetry.Instrumentation.SqlClient
Activity.DisplayName:        lsnext_domain
Activity.Kind:               Client
Activity.StartTime:          2023-10-31T13:33:26.4747510Z
Activity.Duration:           00:00:13.8057920
Activity.Tags:
    db.system: mssql
    db.name: lsnext_domain
    peer.service: srv2.local,1433
    db.statement_type: Text
Resource associated with Activity:
    service.name: some-service-name
    service.instance.id: d597a313-eeed-4e9e-a32c-79bb4a1538e8
    telemetry.sdk.name: opentelemetry
    telemetry.sdk.language: dotnet
    telemetry.sdk.version: 1.7.0-alpha.1

We can see both expected spans using Enrich methods (pay attention to Id and ParentSpanId), so I guess that both spans are exist and looks like the first one just doesnt stop:
image
image

Reproduce

using Microsoft.EntityFrameworkCore;
using OpenTelemetry;
using OpenTelemetry.Resources;
using OpenTelemetry.Trace;

using var tracerProvider = Sdk.CreateTracerProviderBuilder()
    .ConfigureResource(r => r.AddService("some-service-name"))
    .AddSqlClientInstrumentation()
    .AddEntityFrameworkCoreInstrumentation()
    .AddConsoleExporter()
    .Build();

var dbContextOptions = new DbContextOptionsBuilder<SomeDbContext>()
    .UseSqlServer("localhost").Options;
{
    await using var dbContext = new SomeDbContext(dbContextOptions);
    await dbContext.Database.ExecuteSqlAsync($"select 1");
}

await Task.Delay(2000);
Console.ReadKey();

public class SomeDbContext : DbContext
{
    public SomeDbContext(DbContextOptions<SomeDbContext> options) : base(options)
    {
    }
}
<Project Sdk="Microsoft.NET.Sdk">

    <PropertyGroup>
        <OutputType>Exe</OutputType>
        <TargetFramework>net7.0</TargetFramework>
        <ImplicitUsings>enable</ImplicitUsings>
        <Nullable>disable</Nullable>
    </PropertyGroup>

    <ItemGroup>
      <PackageReference Include="Microsoft.EntityFrameworkCore" Version="7.0.13" />
      <PackageReference Include="Microsoft.EntityFrameworkCore.SqlServer" Version="7.0.13" />
      <PackageReference Include="OpenTelemetry" Version="1.7.0-alpha.1" />
      <PackageReference Include="OpenTelemetry.Exporter.Console" Version="1.7.0-alpha.1" />
      <PackageReference Include="OpenTelemetry.Exporter.OpenTelemetryProtocol" Version="1.7.0-alpha.1" />
      <PackageReference Include="OpenTelemetry.Instrumentation.EntityFrameworkCore" Version="1.0.0-beta.8" />
      <PackageReference Include="OpenTelemetry.Instrumentation.SqlClient" Version="1.6.0-beta.2" />
    </ItemGroup>

</Project>

Additional Context

  • Other exporters have the same behavior (tested on OpenTelemetry.Exporter.OpenTelemetryProtocol 1.6.0)
@virtes virtes added the bug Something isn't working label Oct 31, 2023
@cijothomas
Copy link
Member

Moving to the contrib repo as EF instrumentation is hosted there?

@virtes Do you have more idea on the underlying issue and possible fixes? There isn't a marked owner for EF instrumentation, so if you/others can help investigate and provide fix, that'd be super helpful!

@virtes
Copy link
Author

virtes commented Nov 1, 2023 •
edited
Loading

@cijothomas I'm not sure, that the problem is caused by EF instrumentation.

As I understood, the underlying problem is that EntityFrameworkDiagnosticListener and SqlClientDiagnosticListener are called in parallel so stopping the SqlClient activity doesnt reflect actual current activity in EF listener and this causes the EF instrumentation to use obsolete activity. It turns out that the child SqlClient span is used here, but the EF activity is expected here, so the activity doesnt stop and could not be exported

If I misunderstood anything, please correct me

@mbakalov
Copy link

I will take a look at this one! cc @cijothomas

@markphillips100
Copy link

I've just experienced this issue. Any progress been made?

My package versions are:

    <PackageVersion Include="OpenTelemetry.Exporter.Console" Version="[1.7.0, 2.0.0)" />
    <PackageVersion Include="OpenTelemetry.Exporter.OpenTelemetryProtocol" Version="[1.7.0, 2.0.0)" />
    <PackageVersion Include="OpenTelemetry.Extensions.Hosting" Version="[1.7.0, 2.0.0)" />
    <PackageVersion Include="OpenTelemetry.Instrumentation.AspNetCore" Version="[1.7.0, 2.0.0)" />
    <PackageVersion Include="OpenTelemetry.Instrumentation.EntityFrameworkCore" Version="1.0.0-beta.9" />
    <PackageVersion Include="OpenTelemetry.Instrumentation.Http" Version="[1.7.0, 2.0.0)" />
    <PackageVersion Include="OpenTelemetry.Instrumentation.SqlClient" Version="1.6.0-beta.3" />

@vishweshbankwar vishweshbankwar transferred this issue from open-telemetry/opentelemetry-dotnet May 14, 2024
@Kielek Kielek added comp:instrumentation.entityframeworkcore Things related to OpenTelemetry.Instrumentation.EntityFrameworkCore comp:instrumentation.sqlclient Things related to OpenTelemetry.Instrumentation.SqlClient labels May 17, 2024
@zivaninstana
Copy link
Contributor

zivaninstana commented Oct 30, 2024 •
edited
Loading

I did a little investigation.
Problem is here:

opentelemetry-dotnet-contrib/src/OpenTelemetry.Instrumentation.EntityFrameworkCore/Implementation/EntityFrameworkDiagnosticListener.cs

Line 269 in 2ca95ad

if (activity.Source != SqlClientActivitySource)

Better say problem is sequence of events.
Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted happens before than Microsoft.Data.SqlClient.WriteCommandAfter
Because of that SQLClient span is still active and because of the condition I mentioned above we are skipping to stop EF activity on Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted event and that event of course never repeat again.

How EF span is not closed cannot be reported but yes it is still parent of SQL span.

Do we have any practice how to solve such problems? Problem here can be wrong order of events from sources. We have two different libraries so we cannot say who fire event in good moment. It also can be wrong order of processing on OTEL side,
which I think is less likely.

@zivaninstana zivaninstana linked a pull request Oct 31, 2024 that will close this issue
Open
4 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@zivaninstana zivaninstana

Labels
bug Something isn't working comp:instrumentation.entityframeworkcore Things related to OpenTelemetry.Instrumentation.EntityFrameworkCore comp:instrumentation.sqlclient Things related to OpenTelemetry.Instrumentation.SqlClient
Projects
None yet
Milestone
No milestone
6 participants
@cijothomas @Kielek @markphillips100 @virtes @mbakalov @zivaninstana