asp.net.netopen-telemetrydistributed-tracing

why Console print spans in reverse order?


namespace WeatherForecastSimpleTracing
{
    public class Program
    {
        public static void Main(string[] args)
        {
            var builder = WebApplication.CreateBuilder(args);

            builder.Services.AddControllers();

            builder.Services
                .AddOpenTelemetry()
                .WithTracing(builder => builder
                    .AddAspNetCoreInstrumentation()
                    .AddHttpClientInstrumentation()
                    .AddConsoleExporter()  // <-----------------------
                    .AddSource("Tracing.NET")
                 );
            // ...
        }
    }
}



// in the WeatherForecastController
private static readonly ActivitySource _activitySource = new("Tracing.NET");
// ...
[HttpGet("OutgoingHttp")]
public async Task OutgoingHttpRequest()
{
     using var activity = _activitySource.StartActivity("AnotherOne");

     var client = new HttpClient();

     var response = await client.GetAsync("https://code-maze.com");
     response.EnsureSuccessStatusCode();
}

so when I run the app and hit the endpoint, the console output is:

...
Activity.TraceId:            37285f6aa3b5b2cd9bee843c581e9368
Activity.SpanId:             fd793a06db01a828
Activity.TraceFlags:         Recorded
Activity.ParentSpanId:       d0017112214dc65f  // <---------------
Activity.DisplayName:        AnotherOne
Activity.Kind:               Internal
Activity.StartTime:          2025-05-16T12:59:10.4698506Z
Activity.Duration:           00:00:01.2607058
Instrumentation scope (ActivitySource):
    Name: Tracing.NET
Resource associated with Activity:
    telemetry.sdk.name: opentelemetry
    telemetry.sdk.language: dotnet
    telemetry.sdk.version: 1.12.0
    service.name: unknown_service:WeatherForecastSimpleTracing

Activity.TraceId:            37285f6aa3b5b2cd9bee843c581e9368
Activity.SpanId:             d0017112214dc65f   // <---------------
Activity.TraceFlags:         Recorded
Activity.DisplayName:        GET WeatherForecast/OutgoingHttp
Activity.Kind:               Server
Activity.StartTime:          2025-05-16T12:59:10.4533497Z
Activity.Duration:           00:00:01.2822832
Activity.Tags:
    server.address: localhost
    server.port: 5164
    http.request.method: GET
    url.scheme: http
    url.path: /weatherforecast/OutgoingHttp
    network.protocol.version: 1.1
    user_agent.original: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Safari/537.36
    http.route: WeatherForecast/OutgoingHttp
    http.response.status_code: 200
Instrumentation scope (ActivitySource):
    Name: Microsoft.AspNetCore
Resource associated with Activity:
    telemetry.sdk.name: opentelemetry
    telemetry.sdk.language: dotnet
    telemetry.sdk.version: 1.12.0
    service.name: unknown_service:WeatherForecastSimpleTracing

we can clear see that "GET WeatherForecast/OutgoingHttp"(ActivitySource:Microsoft.AspNetCore) span is the parent span of my custom "Tracing.NET" ActivitySource span, but why the child span is printed before parent span, shouldn't it be parent span be printed before child span, is it a bug in the ConsoleExporter?


Solution

  • Although the logging appears to show them the wrong way round, it really isn't.

    I think you've assumed that they should be logged in order of start time but the logging is done after the requests have completed.

    Logged activity 1:

    Activity.StartTime: 2025-05-16T12:59:10.4698506Z
    Activity.Duration: 00:00:01.2607058

    This would give an end time of 2025-05-16T12:59:11.7305564

    Logged activity 2:

    Activity.StartTime: 2025-05-16T12:59:10.4533497Z Activity.Duration: 00:00:01.2822832

    This would give an end time of 2025-05-16T12:59:11.7356329

    As you can see, although the parent span starts first, it doesn't complete until after the child span.