Span is exported only on closeing — causes "invalid parent span IDs" warning message

[zohnannor]

As the otel spans are only exported when tracing::Span is closed and Span is closed when there's no references to it's handle in the subscriber, the scenario:

use std::{
    future::Future,
    pin::Pin,
    task::{self, Poll},
    time::Duration,
};

use opentelemetry::{
    global,
    sdk::{propagation::TraceContextPropagator, trace, Resource},
    KeyValue,
};
use opentelemetry_otlp::WithExportConfig;
use opentelemetry_semantic_conventions::resource;
use tokio::time::{Instant, Sleep};
use tracing::{metadata::LevelFilter, Span};
use tracing_subscriber::{fmt::format::FmtSpan, prelude::*};

fn init_tracing() {
    let otel_layer = tracing_opentelemetry::layer().with_tracer(
        opentelemetry_otlp::new_pipeline()
            .tracing()
            .with_exporter(
                opentelemetry_otlp::new_exporter()
                    .tonic()
                    .with_endpoint("http://localhost:7281/".clone())
                    .with_protocol(opentelemetry_otlp::Protocol::Grpc),
            )
            .with_trace_config(trace::config().with_resource(Resource::new([KeyValue::new(
                resource::SERVICE_NAME,
                env!("CARGO_PKG_NAME"),
            )])))
            .install_batch(opentelemetry::runtime::Tokio)
            .unwrap_or_else(|e| panic!("Failed to initialize `tracing`: {e}")),
    );
    global::set_text_map_propagator(TraceContextPropagator::new());

    tracing_subscriber::registry()
        .with(otel_layer)
        .with(
            tracing_subscriber::fmt::layer()
                .with_span_events(FmtSpan::FULL)
                .with_filter(LevelFilter::INFO),
        )
        .init();
}

#[tokio::main]
async fn main() {
    init_tracing();

    parent().await;

    loop {
        tokio::time::sleep(Duration::from_millis(500)).await;
    }
}

#[tracing::instrument]
async fn parent() {
    long_running();
}

fn long_running() {
    tokio::spawn(Process {
        span: Span::current(),
        sleep: Box::pin(tokio::time::sleep(Duration::from_secs(1))),
    });
}

struct Process {
    span: Span,
    sleep: Pin<Box<Sleep>>,
}

impl Future for Process {
    type Output = ();

    #[tracing::instrument(skip_all, parent = &self.span, name = "process")]
    fn poll(mut self: Pin<&mut Self>, cx: &mut task::Context<'_>) -> Poll<Self::Output> {
        match Pin::new(&mut self.sleep).poll(cx) {
            Poll::Ready(()) => {
                self.sleep
                    .as_mut()
                    .reset(Instant::now() + Duration::from_secs(1));
                Poll::Pending
            }
            p @ Poll::Pending => p,
        }
    }
}

Logs

2023-08-14T09:57:10.691680Z  INFO parent: thing: new
2023-08-14T09:57:10.691698Z  INFO parent: thing: enter
2023-08-14T09:57:10.691712Z  INFO parent: thing: exit
2023-08-14T09:57:10.691812Z  INFO parent:process: thing: new
2023-08-14T09:57:10.691840Z  INFO parent:process: thing: enter
2023-08-14T09:57:10.691859Z  INFO parent:process: thing: exit
2023-08-14T09:57:10.691892Z  INFO parent:process: thing: close time.busy=19.6µs time.idle=66.1µs
2023-08-14T09:57:11.693050Z  INFO parent:process: thing: new
2023-08-14T09:57:11.693092Z  INFO parent:process: thing: enter
2023-08-14T09:57:11.693120Z  INFO parent:process: thing: exit
2023-08-14T09:57:11.693179Z  INFO parent:process: thing: close time.busy=28.4µs time.idle=116µs
2023-08-14T09:57:12.693726Z  INFO parent:process: thing: new
2023-08-14T09:57:12.693767Z  INFO parent:process: thing: enter
2023-08-14T09:57:12.693795Z  INFO parent:process: thing: exit
2023-08-14T09:57:12.693855Z  INFO parent:process: thing: close time.busy=28.4µs time.idle=109µs
2023-08-14T09:57:13.695200Z  INFO parent:process: thing: new
2023-08-14T09:57:13.695245Z  INFO parent:process: thing: enter
2023-08-14T09:57:13.695276Z  INFO parent:process: thing: exit
2023-08-14T09:57:13.695341Z  INFO parent:process: thing: close time.busy=31.8µs time.idle=118µs
2023-08-14T09:57:14.696825Z  INFO parent:process: thing: new
2023-08-14T09:57:14.696864Z  INFO parent:process: thing: enter
2023-08-14T09:57:14.696887Z  INFO parent:process: thing: exit
2023-08-14T09:57:14.696951Z  INFO parent:process: thing: close time.busy=23.2µs time.idle=111µs
2023-08-14T09:57:15.697544Z  INFO parent:process: thing: new
2023-08-14T09:57:15.697565Z  INFO parent:process: thing: enter
2023-08-14T09:57:15.697576Z  INFO parent:process: thing: exit
2023-08-14T09:57:15.697594Z  INFO parent:process: thing: close time.busy=10.4µs time.idle=46.1µs
2023-08-14T09:57:16.698713Z  INFO parent:process: thing: new
2023-08-14T09:57:16.698747Z  INFO parent:process: thing: enter
2023-08-14T09:57:16.698769Z  INFO parent:process: thing: exit
2023-08-14T09:57:16.698820Z  INFO parent:process: thing: close time.busy=22.7µs time.idle=92.1µs
2023-08-14T09:57:17.700292Z  INFO parent:process: thing: new
2023-08-14T09:57:17.700323Z  INFO parent:process: thing: enter
2023-08-14T09:57:17.700340Z  INFO parent:process: thing: exit
2023-08-14T09:57:17.700385Z  INFO parent:process: thing: close time.busy=17.0µs time.idle=84.4µs
^C

where we use the parent span for a some kind of long-running background process,
results in a "broken" trace view in Grafana/Jaeger:

Here we can see, that all the process spans are shoved under some "unknown"
parent span. Which is not particularly useful: I am now forced to search the
specific events in this long waterfall of spans, instead of getting straight to
the span of interest via the search.

The desired outcome would be something like this:

Diff to force the wanted behavior

index 367d31a..1302613 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -56,27 +56,27 @@ async fn main() {
     }
 }

-#[tracing::instrument]
+// #[tracing::instrument]
 async fn parent() {
     long_running();
 }

 fn long_running() {
     tokio::spawn(Process {
-        span: Span::current(),
+        // span: Span::current(),
         sleep: Box::pin(tokio::time::sleep(Duration::from_secs(1))),
     });
 }

 struct Process {
-    span: Span,
+    // span: Span,
     sleep: Pin<Box<Sleep>>,
 }

 impl Future for Process {
     type Output = ();

-    #[tracing::instrument(skip_all, parent = &self.span, name = "process")]
+    #[tracing::instrument(skip_all, parent = &tracing::info_span!("parent"), name = "process")]
     fn poll(mut self: Pin<&mut Self>, cx: &mut task::Context<'_>) -> Poll<Self::Output> {
         match Pin::new(&mut self.sleep).poll(cx) {
             Poll::Ready(()) => {

Logs

2023-08-14T10:01:11.569158Z  INFO parent: thing: new
2023-08-14T10:01:11.569175Z  INFO parent: thing: enter
2023-08-14T10:01:11.569189Z  INFO parent: thing: exit
2023-08-14T10:01:11.569219Z  INFO parent: thing: close time.busy=14.7µs time.idle=54.6µs
2023-08-14T10:01:11.569337Z  INFO parent: thing: new
2023-08-14T10:01:11.569388Z  INFO parent:process: thing: new
2023-08-14T10:01:11.569408Z  INFO parent:process: thing: enter
2023-08-14T10:01:11.569430Z  INFO parent:process: thing: exit
2023-08-14T10:01:11.569478Z  INFO parent:process: thing: close time.busy=22.1µs time.idle=68.0µs
2023-08-14T10:01:11.569513Z  INFO parent: thing: close time.busy=0.00ns time.idle=184µs
2023-08-14T10:01:12.569992Z  INFO parent: thing: new
2023-08-14T10:01:12.570053Z  INFO parent:process: thing: new
2023-08-14T10:01:12.570072Z  INFO parent:process: thing: enter
2023-08-14T10:01:12.570092Z  INFO parent:process: thing: exit
2023-08-14T10:01:12.570144Z  INFO parent:process: thing: close time.busy=19.5µs time.idle=71.5µs
2023-08-14T10:01:12.570177Z  INFO parent: thing: close time.busy=0.00ns time.idle=200µs
2023-08-14T10:01:13.571670Z  INFO parent: thing: new
2023-08-14T10:01:13.571727Z  INFO parent:process: thing: new
2023-08-14T10:01:13.571747Z  INFO parent:process: thing: enter
2023-08-14T10:01:13.571769Z  INFO parent:process: thing: exit
2023-08-14T10:01:13.571819Z  INFO parent:process: thing: close time.busy=21.8µs time.idle=70.1µs
2023-08-14T10:01:13.571856Z  INFO parent: thing: close time.busy=0.00ns time.idle=194µs
2023-08-14T10:01:14.573184Z  INFO parent: thing: new
2023-08-14T10:01:14.573240Z  INFO parent:process: thing: new
2023-08-14T10:01:14.573259Z  INFO parent:process: thing: enter
2023-08-14T10:01:14.573280Z  INFO parent:process: thing: exit
2023-08-14T10:01:14.573334Z  INFO parent:process: thing: close time.busy=21.5µs time.idle=73.0µs
2023-08-14T10:01:14.573368Z  INFO parent: thing: close time.busy=0.00ns time.idle=191µs
2023-08-14T10:01:15.574777Z  INFO parent: thing: new
2023-08-14T10:01:15.574833Z  INFO parent:process: thing: new
2023-08-14T10:01:15.574852Z  INFO parent:process: thing: enter
2023-08-14T10:01:15.574874Z  INFO parent:process: thing: exit
2023-08-14T10:01:15.574941Z  INFO parent:process: thing: close time.busy=21.5µs time.idle=85.9µs
2023-08-14T10:01:15.574978Z  INFO parent: thing: close time.busy=0.00ns time.idle=209µs
^C

Now, the parent spans are closed exported on each process span end,
producing the new distinct spans (shown in the table).

I think this means that spans have to be exported on each exit, not a close.
This is undesired due to performance considerations, I understand. But is there
a way to get parent to behave like in the second example?

[mladedav]

Hi, the second picture does not work for me, so I'm not quite sure what's there.

In any case, in opentelemetry, you can close the span only once and it is considered to have run the whole time from start to end. So if you export the parent span on exit, you couldn't enter it again.

The broken view in your first example is I believe exactly because the example code runs an endless loop. In real life, this would happen if you looked at spans while their parent is still running. Once the parent would finish, the view would be fixed. I don't think this can be worked around in opentelemetry, I believe there is no support for updating spans or sending partial spans.