Async calls and nested span events

[ramgdev]

I am seeing an issue with getting spans to show up correctly. Here is what I am doing (sorry if this is confusing).

• Create context1
• Call async functionA with_context(context1)
• Create spanA from inside functionA and add event1
• Create context2 from inside functionA and call with_span(spanA)
• Call async functionB with_context(context2)
• Create spanB from inside functionB and add event2
• At the end of functionB, add event3 on Context::current.span()
• At the end of functionA, add event4 on Context::current.span()

When I look at the data in the UI (Jaeger), the spans are nested correctly. But there are two problems with the events. 1) I don't see event4 anywhere. 2) event3 is showing up under spanA instead of spanB.

[lalitb]

With "At the end of functionB" do you mean after exiting the functionB, or just before exiting the functionB?

Sorry if it was supposed to be obvious, and I am the only one confused :)

[ramgdev]

just before exiting. Basically, each function creates a span and adds 2 events to produce the following

SpanA
  event1: functionA started
  event4: functionA ended
  SpanB
     event2: functionB started
     event3: functionB ended

[lalitb]

@ramgdev this shouldn't happen. Do you have the sample code to demonstrate the issue?

[ramgdev]

@lalitb here is a sample code that shows this problem.

trace.rs.zip

I see the order of functions called correctly

function_a called
function_b called
function_c called
function_d called

But the spans show wrong/missing events

[lalitb]

@ramgdev Thanks for sharing the sample code. Looking into the example, the output is as expected. If we look into the function_b, which is called asynchronously from function_a with an explicit context context_a:

pub async fn function_b() -> Result<()> {
    println!("function_b called");
    let tracer = global::tracer("mytracer");
    let parent_context = opentelemetry::Context::current();
    let mut span = tracer
        .span_builder("span_B".to_owned())
        .with_kind(SpanKind::Server)
        .start_with_context(&tracer, &parent_context);
    span.add_event("event_2".to_string(), vec![]);
    let context_b = opentelemetry::Context::default().with_span(span);
    match opentelemetry::trace::FutureExt::with_context(function_c(), context_b).await {
        Ok(()) => {
            let current_context = opentelemetry::Context::current();
            current_context
                .span()
                .add_event("event_3".to_string(), vec![]);
            Ok(())
        }
        Err(err) => Err(err),
    }
}

This function:

• Retrieves the current context (which is context_a due to the explicit context passing).
• Creates a span named span_B.
• Adds an event named event_2 to span_B.
• Creates a new context context_b with span_B and passes it to function_c(). function_c asynchronously executes with context_b as active context.
• After execution of function_c, event_3 is added to span in the currently active context. Please note that the context_a is currently active context, so this event gets added to span_A.

If you wanted to add event_3 to Span_B, either directly use that span instance, or make context_b active in the scope of function_b.

Similar is the reason for event_4. The currently active context in function_a doesn't have any span attached, so this event is not recorded.

[ramgdev]

Thanks for the explanation! Just a clarification.

If you wanted to add event_3 to Span_B, either directly use that span instance, or make context_b active in the scope of function_b.

Isn't this line supposed to make context_b as the current context in the scope for function_b OR is there another way to do it?
let context_b = opentelemetry::Context::default().with_span(span);

[ramgdev]

Got it working now. thanks.
trace.rs.zip