open-telemetry / opentelemetry-dotnet

The OpenTelemetry .NET Client
https://opentelemetry.io
Apache License 2.0
3.21k stars 759 forks source link

AspNetCore Instrumentation Missing Traces #4074

Closed gfournierflinks closed 1 year ago

gfournierflinks commented 1 year ago

Bug Report

Symptom

Describe the bug In the context where OpenTelemetry is configure to add AspNetCore Instrumentation, if another web app is making a server to server call to the traced API, a trace is not generated. See Steps to reproduce for all the details.

I followed the instructions here https://github.com/open-telemetry/opentelemetry-dotnet/blob/main/src/OpenTelemetry.Instrumentation.AspNetCore/README.md

Expected behavior All traces should be generated

Runtime environment (please complete the following information):

Reproduce

Steps to reproduce the behavior:

I join the code of a very simple API called DummyAPI (see zip files attached). The solution contains 3 projects:

The dummy API uses the following dependencies:

<PackageReference Include="OpenTelemetry.Exporter.Console" Version="1.4.0-rc.2" />
<PackageReference Include="OpenTelemetry" Version="1.4.0-rc.2" />
<PackageReference Include="OpenTelemetry.Instrumentation.AspNetCore" Version="1.0.0-rc9.11" />
<PackageReference Include="OpenTelemetry.Extensions.Hosting" Version="1.4.0-rc.2" />

The DummyAPI is configured as such in the Program.cs:

builder.Services
    .AddOpenTelemetry()
    .WithTracing(b => b
        .AddAspNetCoreInstrumentation()
        .AddConsoleExporter())
    .StartWithHost();

The only endpoint of the dummy API is a GET /WeatherForecast

The API can we called in 3 different ways :

When testing from the browser, a trace is exported to the console. When testing from the ConsoleApp, a trace is exported to the console. However, when testing with the DummyWebApp, a trace is NOT exported to the console

Inspecting the System.Diagnostics.Activity.Current when calling via the DummyWebApp, I see this:

{System.Diagnostics.Activity}
    ActivityTraceFlags: None
    Baggage: {System.Collections.Generic.KeyValuePair<string, string>[0]}
    Context: {System.Diagnostics.ActivityContext}
    DisplayName: "Microsoft.AspNetCore.Hosting.HttpRequestIn"
    Duration: {00:00:00}
    Events: {System.Diagnostics.ActivityEvent[0]}
    HasRemoteParent: false
    Id: "00-c7f13dea263bc4a7db7d11034eaef306-ff54c642c6ed7c8a-00"
    IdFormat: W3C
    IsAllDataRequested: false
    IsStopped: false
    Kind: Internal
    Links: {System.Diagnostics.ActivityLink[0]}
    OperationName: "Microsoft.AspNetCore.Hosting.HttpRequestIn"
    Parent: null
    ParentId: "00-c7f13dea263bc4a7db7d11034eaef306-605e0f3e93fbc3c9-00"
    ParentSpanId: {605e0f3e93fbc3c9}
    Recorded: false
    RootId: "c7f13dea263bc4a7db7d11034eaef306"
    Source: {System.Diagnostics.ActivitySource}
    SpanId: {ff54c642c6ed7c8a}
    StartTimeUtc: {2023-01-11 2:53:06 PM}
    Status: Unset
    StatusDescription: null
    TagObjects: {System.Collections.Generic.KeyValuePair<string, object>[0]}
    Tags: {System.Collections.Generic.KeyValuePair<string, string>[0]}
    TraceId: {c7f13dea263bc4a7db7d11034eaef306}
    TraceStateString: null
    W3CIdFlagsSet: true
    _baggage: null
    _currentChildId: 0
    _customProperties: null
    _displayName: null
    _events: null
    _id: "00-c7f13dea263bc4a7db7d11034eaef306-ff54c642c6ed7c8a-00"
    _links: null
    _parentId: "00-c7f13dea263bc4a7db7d11034eaef306-605e0f3e93fbc3c9-00"
    _parentSpanId: "605e0f3e93fbc3c9"
    _parentTraceFlags: 0
    _previousActiveActivity: null
    _rootId: "c7f13dea263bc4a7db7d11034eaef306"
    _spanId: "ff54c642c6ed7c8a"
    _state: FormatW3C
    _statusCode: Unset
    _statusDescription: null
    _tags: null
    _traceId: "c7f13dea263bc4a7db7d11034eaef306"
    _traceState: null
    _w3CIdFlags: 128

Comparing when It's called from the browser:

{System.Diagnostics.Activity}
    ActivityTraceFlags: Recorded
    Baggage: {System.Collections.Generic.KeyValuePair<string, string>[0]}
    Context: {System.Diagnostics.ActivityContext}
    DisplayName: "WeatherForecast"
    Duration: {00:00:00}
    Events: {System.Diagnostics.ActivityEvent[0]}
    HasRemoteParent: false
    Id: "00-3fb2d4dbeae6997cbf22fb1421dc77cb-80ced282746c5c42-01"
    IdFormat: W3C
    IsAllDataRequested: true
    IsStopped: false
    Kind: Server
    Links: {System.Diagnostics.ActivityLink[0]}
    OperationName: "Microsoft.AspNetCore.Hosting.HttpRequestIn"
    Parent: null
    ParentId: null
    ParentSpanId: {0000000000000000}
    Recorded: true
    RootId: "3fb2d4dbeae6997cbf22fb1421dc77cb"
    Source: {System.Diagnostics.ActivitySource}
    SpanId: {80ced282746c5c42}
    StartTimeUtc: {2023-01-11 2:54:48 PM}
    Status: Unset
    StatusDescription: null
    TagObjects: {net.host.name:localhost, net.host.port:7077, http.method:GET, http.scheme:https, http.target:/WeatherForecast, http.url:https://localhost:7077/WeatherForecast, http.flavor:2.0, http.user_agent:Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/108.0.0.0 Safari/537.36, http.route:WeatherForecast}
    Tags: {System.Diagnostics.Activity.TagsLinkedList.<EnumerateStringValues>d__16}
    TraceId: {3fb2d4dbeae6997cbf22fb1421dc77cb}
    TraceStateString: null
    W3CIdFlagsSet: true
    _baggage: null
    _currentChildId: 0
    _customProperties: null
    _displayName: "WeatherForecast"
    _events: null
    _id: "00-3fb2d4dbeae6997cbf22fb1421dc77cb-80ced282746c5c42-01"
    _links: null
    _parentId: null
    _parentSpanId: null
    _parentTraceFlags: 0
    _previousActiveActivity: null
    _rootId: "3fb2d4dbeae6997cbf22fb1421dc77cb"
    _spanId: "80ced282746c5c42"
    _state: FormatW3C
    _statusCode: Unset
    _statusDescription: null
    _tags: {net.host.name:localhost, net.host.port:7077, http.method:GET, http.scheme:https, http.target:/WeatherForecast, http.url:https://localhost:7077/WeatherForecast, http.flavor:2.0, http.user_agent:Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/108.0.0.0 Safari/537.36, http.route:WeatherForecast}
    _traceId: "3fb2d4dbeae6997cbf22fb1421dc77cb"
    _traceState: null
    _w3CIdFlags: 129

In the case of calling the DummyAPI via the DummyWebApp, the System.Diagnostics.Activity.Source doesn't seem to be set properly:

System.Diagnostics.ActivitySource
{
    Name: ""
    Version: ""
    _listeners: {System.Diagnostics.SynchronizedList<System.Diagnostics.ActivityListener>
}

Compared to when the DummyAPI is called via the browser:

System.Diagnostics.ActivitySource
{
    Name: "OpenTelemetry.Instrumentation.AspNetCore"
    Version: "1.0.0.0"
    _listeners: {System.Diagnostics.SynchronizedList<System.Diagnostics.ActivityListener>
}

Am I missing something? DummyAPI.zip

Kielek commented 1 year ago

By default ASP.NET Core is using tracecontext propagator to inject/extract information about span context. Your DummyWebApp does not have any any telemetry listener, but AspNetCore Activities are created and marked as non-registered. That information is propagated by http headers in the request to the DummyAPI.

What is more OpenTelemetry by default is using new ParentBasedSampler(new AlwaysOnSampler()). That means if you do not have parent based information - sample always. If you have it, respect sampling decision from the parent.

It can be overriten by in your DummyAPI package.

builder.Services
    .AddOpenTelemetry()
    .WithTracing(b => b
        .SetSampler(new AlwaysOnSampler())
        .AddAspNetCoreInstrumentation()
        .AddConsoleExporter())
    .StartWithHost();

After changes, call from DummyWebApp to DummyAPI (Activity.ParentSpanId is recorded) Activity.TraceId: 7aae8aede8340bdb938494b67f3b8f90 Activity.SpanId: 0bbf4f827511a35b Activity.TraceFlags: Recorded Activity.ParentSpanId: 3552debb27e61051 Activity.ActivitySourceName: OpenTelemetry.Instrumentation.AspNetCore Activity.DisplayName: WeatherForecast Activity.Kind: Server Activity.StartTime: 2023-01-12T06:15:56.8224144Z Activity.Duration: 00:00:00.0235171 Activity.Tags: net.host.name: localhost net.host.port: 7077 http.method: GET http.scheme: https http.target: /WeatherForecast http.url: https://localhost:7077/WeatherForecast http.flavor: 1.1 http.route: WeatherForecast http.status_code: 200 Resource associated with Activity: service.name: unknown_service:DummyAPI

After changes, call from broswer/console app to DummyAPI (Activity.ParentSpanId is not available) Activity.TraceId: 98ba9b17b1aac2c344ad49615fe8db95 Activity.SpanId: 7978f2606e469f39 Activity.TraceFlags: Recorded Activity.ActivitySourceName: OpenTelemetry.Instrumentation.AspNetCore Activity.DisplayName: WeatherForecast Activity.Kind: Server Activity.StartTime: 2023-01-12T06:16:00.8129651Z Activity.Duration: 00:00:00.0212744 Activity.Tags: net.host.name: localhost net.host.port: 7077 http.method: GET http.scheme: https http.target: /WeatherForecast http.url: https://localhost:7077/WeatherForecast http.flavor: 2.0 http.user_agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36 http.route: WeatherForecast http.status_code: 200 Resource associated with Activity: service.name: unknown_service:DummyAPI

I would say, that it is not a bug, rather a feature.

gfournierflinks commented 1 year ago

It works well with .SetSampler(new AlwaysOnSampler())

Thanks!