OpenTelemetry example missing root span

[FallenWarrior2k]

Bug Report

Version

tracing-examples v0.0.0 (/redacted/tracing/examples)
│   │   └── tracing v0.1.29
│   │       ├── tracing-attributes v0.1.18 (proc-macro)
│   │       └── tracing-core v0.1.21
│   ├── tracing v0.1.29 (*)
│   └── tracing v0.1.29 (*)
├── tracing v0.2.0 (/redacted/tracing/tracing)
│   ├── tracing-attributes v0.2.0 (proc-macro) (/redacted/tracing/tracing-attributes)
│   └── tracing-core v0.2.0 (/redacted/tracing/tracing-core)
├── tracing-appender v0.2.0 (/redacted/tracing/tracing-appender)
│   └── tracing-subscriber v0.3.0 (/redacted/tracing/tracing-subscriber)
│       ├── tracing v0.2.0 (/redacted/tracing/tracing) (*)
│       ├── tracing-core v0.2.0 (/redacted/tracing/tracing-core) (*)
│       ├── tracing-log v0.2.0 (/redacted/tracing/tracing-log)
│       │   └── tracing-core v0.2.0 (/redacted/tracing/tracing-core) (*)
│       └── tracing-serde v0.2.0 (/redacted/tracing/tracing-serde)
│           └── tracing-core v0.2.0 (/redacted/tracing/tracing-core) (*)
├── tracing-attributes v0.2.0 (proc-macro) (/redacted/tracing/tracing-attributes) (*)
├── tracing-core v0.2.0 (/redacted/tracing/tracing-core) (*)
├── tracing-error v0.2.0 (/redacted/tracing/tracing-error)
│   ├── tracing v0.2.0 (/redacted/tracing/tracing) (*)
│   └── tracing-subscriber v0.3.0 (/redacted/tracing/tracing-subscriber) (*)
├── tracing-flame v0.2.0 (/redacted/tracing/tracing-flame)
│   ├── tracing v0.2.0 (/redacted/tracing/tracing) (*)
│   └── tracing-subscriber v0.3.0 (/redacted/tracing/tracing-subscriber) (*)
├── tracing-futures v0.3.0 (/redacted/tracing/tracing-futures)
│   └── tracing v0.2.0 (/redacted/tracing/tracing) (*)
├── tracing-journald v0.2.0 (/redacted/tracing/tracing-journald)
│   ├── tracing-core v0.2.0 (/redacted/tracing/tracing-core) (*)
│   └── tracing-subscriber v0.3.0 (/redacted/tracing/tracing-subscriber) (*)
├── tracing-log v0.2.0 (/redacted/tracing/tracing-log) (*)
├── tracing-opentelemetry v0.15.0 (/redacted/tracing/tracing-opentelemetry)
│   ├── tracing v0.2.0 (/redacted/tracing/tracing) (*)
│   ├── tracing-core v0.2.0 (/redacted/tracing/tracing-core) (*)
│   ├── tracing-log v0.2.0 (/redacted/tracing/tracing-log) (*)
│   └── tracing-subscriber v0.3.0 (/redacted/tracing/tracing-subscriber) (*)
├── tracing-serde v0.2.0 (/redacted/tracing/tracing-serde) (*)
├── tracing-subscriber v0.3.0 (/redacted/tracing/tracing-subscriber) (*)
└── tracing-tower v0.1.0 (/redacted/tracing/tracing-tower)
    ├── tracing v0.2.0 (/redacted/tracing/tracing) (*)
    └── tracing-futures v0.3.0 (/redacted/tracing/tracing-futures) (*)

Current Git HEAD: 500021c

Platform

Linux redacted 5.12.18-1-ck-haswell #1 SMP PREEMPT Mon, 19 Jul 2021 10:10:38 +0000 x86_64 GNU/Linux

Crates

tracing-opentelemetry, examples

Description

When trying the example in the tracing-opentelemetry README, the span data that arrives in Jaeger is missing the root app_start span.

In an attempt to make sure it wasn't my fault, I tried both stable and nightly rustc, as well as the latest tag for Jaeger and various numbered releases. However, I don't really have any experience with OpenTelemetry in general, so I don't really know what else I might be doing wrong.

To check if this was maybe a Jaeger issue, I replaced the Jaeger exporter with a pretty-print stdout exporter to inspect the data generated, and got this:

SpanData {
    span_context: SpanContext {
        trace_id: TraceId(
            115753407323867453817286726237859500592,
        ),
        span_id: SpanId(
            2412041107076759396,
        ),
        trace_flags: TraceFlags(
            1,
        ),
        is_remote: false,
        trace_state: TraceState(
            None,
        ),
    },
    parent_span_id: SpanId(
        17737724336709010573,
    ),
    span_kind: Internal,
    name: "expensive_step_1",
    start_time: SystemTime {
        tv_sec: 1637678113,
        tv_nsec: 747121770,
    },
    end_time: SystemTime {
        tv_sec: 1637678113,
        tv_nsec: 772231941,
    },
    attributes: EvictedHashMap {
        map: {
            Key(
                "code.filepath",
            ): String(
                "examples/examples/opentelemetry.rs",
            ),
            Key(
                "code.namespace",
            ): String(
                "opentelemetry",
            ),
            Key(
                "busy_ns",
            ): I64(
                25085322,
            ),
            Key(
                "code.lineno",
            ): I64(
                9,
            ),
            Key(
                "idle_ns",
            ): I64(
                16055,
            ),
        },
        evict_list: [
            Key(
                "idle_ns",
            ),
            Key(
                "busy_ns",
            ),
            Key(
                "code.lineno",
            ),
            Key(
                "code.namespace",
            ),
            Key(
                "code.filepath",
            ),
        ],
        max_len: 128,
        dropped_count: 0,
    },
    events: EvictedQueue {
        queue: None,
        max_len: 128,
        dropped_count: 0,
    },
    links: EvictedQueue {
        queue: None,
        max_len: 128,
        dropped_count: 0,
    },
    status_code: Unset,
    status_message: "",
    resource: Some(
        Resource {
            attrs: {
                Key(
                    "service.name",
                ): String(
                    "unknown_service",
                ),
            },
        },
    ),
    instrumentation_lib: InstrumentationLibrary {
        name: "opentelemetry",
        version: Some(
            "0.16.0",
        ),
    },
}
SpanData {
    span_context: SpanContext {
        trace_id: TraceId(
            115753407323867453817286726237859500592,
        ),
        span_id: SpanId(
            2595018740449750974,
        ),
        trace_flags: TraceFlags(
            1,
        ),
        is_remote: false,
        trace_state: TraceState(
            None,
        ),
    },
    parent_span_id: SpanId(
        17737724336709010573,
    ),
    span_kind: Internal,
    name: "expensive_step_2",
    start_time: SystemTime {
        tv_sec: 1637678113,
        tv_nsec: 772347981,
    },
    end_time: SystemTime {
        tv_sec: 1637678113,
        tv_nsec: 797478496,
    },
    attributes: EvictedHashMap {
        map: {
            Key(
                "code.namespace",
            ): String(
                "opentelemetry",
            ),
            Key(
                "busy_ns",
            ): I64(
                25095343,
            ),
            Key(
                "code.lineno",
            ): I64(
                11,
            ),
            Key(
                "idle_ns",
            ): I64(
                29452,
            ),
            Key(
                "code.filepath",
            ): String(
                "examples/examples/opentelemetry.rs",
            ),
        },
        evict_list: [
            Key(
                "idle_ns",
            ),
            Key(
                "busy_ns",
            ),
            Key(
                "code.lineno",
            ),
            Key(
                "code.namespace",
            ),
            Key(
                "code.filepath",
            ),
        ],
        max_len: 128,
        dropped_count: 0,
    },
    events: EvictedQueue {
        queue: None,
        max_len: 128,
        dropped_count: 0,
    },
    links: EvictedQueue {
        queue: None,
        max_len: 128,
        dropped_count: 0,
    },
    status_code: Unset,
    status_message: "",
    resource: Some(
        Resource {
            attrs: {
                Key(
                    "service.name",
                ): String(
                    "unknown_service",
                ),
            },
        },
    ),
    instrumentation_lib: InstrumentationLibrary {
        name: "opentelemetry",
        version: Some(
            "0.16.0",
        ),
    },
}
SpanData {
    span_context: SpanContext {
        trace_id: TraceId(
            115753407323867453817286726237859500592,
        ),
        span_id: SpanId(
            17737724336709010573,
        ),
        trace_flags: TraceFlags(
            1,
        ),
        is_remote: false,
        trace_state: TraceState(
            None,
        ),
    },
    parent_span_id: SpanId(
        11558622527446292642,
    ),
    span_kind: Internal,
    name: "expensive_work",
    start_time: SystemTime {
        tv_sec: 1637678113,
        tv_nsec: 747087811,
    },
    end_time: SystemTime {
        tv_sec: 1637678113,
        tv_nsec: 797546890,
    },
    attributes: EvictedHashMap {
        map: {
            Key(
                "code.namespace",
            ): String(
                "opentelemetry",
            ),
            Key(
                "code.filepath",
            ): String(
                "examples/examples/opentelemetry.rs",
            ),
            Key(
                "busy_ns",
            ): I64(
                50422609,
            ),
            Key(
                "idle_ns",
            ): I64(
                28263,
            ),
            Key(
                "code.lineno",
            ): I64(
                6,
            ),
        },
        evict_list: [
            Key(
                "idle_ns",
            ),
            Key(
                "busy_ns",
            ),
            Key(
                "code.lineno",
            ),
            Key(
                "code.namespace",
            ),
            Key(
                "code.filepath",
            ),
        ],
        max_len: 128,
        dropped_count: 0,
    },
    events: EvictedQueue {
        queue: None,
        max_len: 128,
        dropped_count: 0,
    },
    links: EvictedQueue {
        queue: None,
        max_len: 128,
        dropped_count: 0,
    },
    status_code: Unset,
    status_message: "",
    resource: Some(
        Resource {
            attrs: {
                Key(
                    "service.name",
                ): String(
                    "unknown_service",
                ),
            },
        },
    ),
    instrumentation_lib: InstrumentationLibrary {
        name: "opentelemetry",
        version: Some(
            "0.16.0",
        ),
    },
}
SpanData {
    span_context: SpanContext {
        trace_id: TraceId(
            115753407323867453817286726237859500592,
        ),
        span_id: SpanId(
            10281780557043495479,
        ),
        trace_flags: TraceFlags(
            1,
        ),
        is_remote: false,
        trace_state: TraceState(
            None,
        ),
    },
    parent_span_id: SpanId(
        11558622527446292642,
    ),
    span_kind: Internal,
    name: "faster_work",
    start_time: SystemTime {
        tv_sec: 1637678113,
        tv_nsec: 797597727,
    },
    end_time: SystemTime {
        tv_sec: 1637678113,
        tv_nsec: 807705519,
    },
    attributes: EvictedHashMap {
        map: {
            Key(
                "idle_ns",
            ): I64(
                37764,
            ),
            Key(
                "code.lineno",
            ): I64(
                39,
            ),
            Key(
                "code.filepath",
            ): String(
                "examples/examples/opentelemetry.rs",
            ),
            Key(
                "busy_ns",
            ): I64(
                10066041,
            ),
            Key(
                "code.namespace",
            ): String(
                "opentelemetry",
            ),
        },
        evict_list: [
            Key(
                "idle_ns",
            ),
            Key(
                "busy_ns",
            ),
            Key(
                "code.lineno",
            ),
            Key(
                "code.namespace",
            ),
            Key(
                "code.filepath",
            ),
        ],
        max_len: 128,
        dropped_count: 0,
    },
    events: EvictedQueue {
        queue: None,
        max_len: 128,
        dropped_count: 0,
    },
    links: EvictedQueue {
        queue: None,
        max_len: 128,
        dropped_count: 0,
    },
    status_code: Unset,
    status_message: "",
    resource: Some(
        Resource {
            attrs: {
                Key(
                    "service.name",
                ): String(
                    "unknown_service",
                ),
            },
        },
    ),
    instrumentation_lib: InstrumentationLibrary {
        name: "opentelemetry",
        version: Some(
            "0.16.0",
        ),
    },
}

As you can see, the root app_start span is missing from the output.

[noonien]

Have you managed to solve this issue?

[Arqu]

Having the same issue, root span is never emitted to the collector.

[duarten]

I have the same issue: it works fine when using otel's stdout exporter, but the root span is missing when using an opentelemetry_otlp exporter (which suggests an issue on the otel exporter).

[davidbarsky]

This is somewhat resolved by #2110—the core issue is that the root span in the example is closed after the collector shuts down due to drop rules.

[FallenWarrior2k]

It seems so. However, this feels like a very sneaky pitfall that one might not consider in a scenario where the root span is opened on application start-up, and should perhaps be mentioned in the documentation. I'm willing to close this issue either way; just putting the idea out there.