[Prototype] OpenTelemetry and Tokio Tracing bridge that properly activates contexts and spans

[bantonsson]

This is a follow up ticket to discussions in #1571 about OpenTelemetry Tracing API vs Tokio-Tracing API.

The aim is to prototype a Tokio Tracing subscriber bridge with OpenTelemetry tracing/logging that will use the overlapping context scopes fix as a basis and keep the OpenTelemetry Context up to date with the Tokio Tracing notion of the active Span. This bridge will activate/deactivate the OpenTelemetry Context and Span on the threads at the proper points instead of only briefly activating the OpenTelemetry Context or Span when the Tokio Tracing Span is finished. More concretely there will be a stack that mimics the stack in Tokio Tracing that deactivates the right OpenTelemetry Context corresponding to the Tokio Tracing Span.

This will not (at least not initially) provide seamless two-way interoperability as described in Option 3 here, but instead allow the OpenTelemetry Context to travel with Tokio Tracing Spans, so that standard OpenTelemetry API calls will find the right Context and Span

The goal is to make code like this broken example work seamlessly from the OpenTelemetry point of view, allowing end user code to use OpenTelemetry API calls that will work with frameworks and libraries that are using Tokio Tracing.

I would love to get feedback on the idea and hear about other peoples experience in trying to fix the interoperability.

[cijothomas]

From CommunityMeeting on Dec 17th:

The key idea is to use tokio::tracing::subscriber to activate/deactivate OTel Context. #2378 is a requirement, but okay to manually test with the changes brought in by hand, so not a blocker for prototype.

#2438 can be still offered experimental, as this issue will fix the correlation without requiring the change from #2438

[mladedav]

I've created something that I think should work a bit better here. It still needs some polishing and fixing some of the tests but the broken example should work.

I did not test with multiple threads yet, that's probably the main thing that might not work now. Tracking open contexts is also very rudimentary and it won't handle overlapping contexts and out-of-order exits well, but I'll probably just copy whatever behavior is in #2378 sooner or later.

If someone tried playing around with it and find issues with it, that would also help.

[bantonsson]

Hey @mladedav thanks for sharing your code. I've taken a little different approach where I focus on letting the context propagate with the tokio spans and then OpenTelemetry Tracing can be a feature that can be turned on or off. It also has the same behavior as the tracing-opentelemetry code where you can modify the OpenTelemetry span, but in my version only until it is entered the first time. I'll probably have a PR in the next few days, and it would be great to discuss the differences and similarities.

[bantonsson]

I've got a working prototype here that runs all the existing tokio-rs/tracing-opentelemetry tests. It also has a new test that explicitly tests context propagation.

This prototype keeps the existing tokio-rs/tracing-opentelemetry APIs as much as possible while activating and deactivating OpenTelemetry Contexts when entering/exiting Tokio spans.

[mladedav]

I've looked through it and I gotta say it's cool that you were able to do this without changing the API too much (or maybe at all, I don't think I've noticed any breaking changes).

I'll start with some potential issues I've noticed which I think can be fixed and at the end will discuss the conceptual differences between the three versions (including the currently released tracing-opentelemetry).

One thing I noticed is that on the first enter or when a span is used as an explicit tracing parent for the first time, the span is created and the new context is saved.

This leads to the following strange behavior where the first child is not a child of the root span because the context wasn't built yet. This seems to happen, because parent_cx is actually the parent context of the span for some time and then it changes to the context of the span itself.

Broken children

    #[test]
    fn parent_context() {
        let mut tracer = TestTracer::default();
        let subscriber = tracing_subscriber::registry().with(layer().with_tracer(tracer.clone()));

        tracing::subscriber::with_default(subscriber, || {
            let root = trace_span!("root");
            let child1 = trace_span!("child-1");
            child1.set_parent(root.context());

            let _enter_root = root.enter();
            drop(_enter_root);

            let child2 = trace_span!("child-2");
            child2.set_parent(root.context());
        });

        // Let's check the spans
        let spans = tracer.spans();
        let parent = spans
            .iter()
            .find(|span| span.name == "root")
            .unwrap();
        let child1 = spans
            .iter()
            .find(|span| span.name == "child-1")
            .unwrap();
        let child2 = spans
            .iter()
            .find(|span| span.name == "child-2")
            .unwrap();
        assert_eq!(parent.parent_span_id, otel::SpanId::INVALID);
        assert_eq!(child1.parent_span_id, otel::SpanId::INVALID); // This is surprising
        assert_eq!(child2.parent_span_id, parent.span_context.span_id());
    }

I don't know how simple it would be to fix this, maybe the context can also be built on the first SpanExt::context call (the todo there seems to also imply that could just work). Maybe changing OtelData to be an enum based on whether the context has been built already and not reusing parent_cx in this way could also be an option.

There's also other interaction like when the context is built, then recording fields doesn't work anymore

Broken record

    #[test]
    fn record_after() {
        let mut tracer = TestTracer::default();
        let subscriber = tracing_subscriber::registry().with(layer().with_tracer(tracer.clone()));

        tracing::subscriber::with_default(subscriber, || {
            let root = trace_span!("root", before = "before", after = "before");

            root.record("before", "after");
            let _enter_root = root.enter();
            drop(_enter_root);
            root.record("after", "after");
        });

        // Let's check the spans
        let spans = tracer.spans();
        let parent = spans.iter().find(|span| span.name == "root").unwrap();
        assert_eq!(parent.parent_span_id, otel::SpanId::INVALID);
        assert!(
            parent
                .attributes
                .iter()
                .filter(|kv| kv.key.as_str() == "before")
                .any(|kv| kv.value.as_str() == "after")
        );
        // This fails
        assert!(
            parent
                .attributes
                .iter()
                .filter(|kv| kv.key.as_str() == "after")
                .any(|kv| kv.value.as_str() == "after")
        );
    }

I think this should be easy to fix since this can simply work the same way as OpenTelemetrySpanExt::set_attribute.

Another example of this different behavior can be seen here, where set_parent itself surprisingly starts changing the span itself instead of its parent:

Details

    #[test]
    fn parent_context_2() {
        let mut tracer = TestTracer::default();
        let subscriber = tracing_subscriber::registry().with(layer().with_tracer(tracer.clone()));

        tracing::subscriber::with_default(subscriber, || {
            let root = trace_span!("root");
            _ = root.enter();
            let child1 = trace_span!("child-1");

            child1.set_parent(root.context());
            trace_span!(parent: &child1, "child-2");

            child1.set_parent(root.context());
            trace_span!(parent: &child1, "child-3");

        });

        // Let's check the spans
        let spans = tracer.spans();
        let root = spans
            .iter()
            .find(|span| span.name == "root")
            .unwrap();
        let child1 = spans
            .iter()
            .find(|span| span.name == "child-1")
            .unwrap();
        let child2 = spans
            .iter()
            .find(|span| span.name == "child-2")
            .unwrap();
        let child3 = spans
            .iter()
            .find(|span| span.name == "child-3")
            .unwrap();
        assert_eq!(root.parent_span_id, otel::SpanId::INVALID);
        assert_eq!(child1.parent_span_id, root.span_context.span_id());
        assert_eq!(child2.parent_span_id, child1.span_context.span_id());
        assert_eq!(child3.parent_span_id, root.span_context.span_id()); // This is surprising, the parent should be `child1`
    }

Also, LayerTracer seems to me to be completely unnecessary, it can just be replaced with otel::Tracer everywhere where it is used.

---

On a more general note, the design I went with is in big part because I also tried to not allow users to change parent relationships after constructing a given span. The OpenTelemetry spec says that should be immutable and I think that the whole idea of calling set_parent is the main complication both the original implementation and your version have to deal with.

I think this was one of the reasons the old implementation built the span only after on_close has been called since then we can be sure parent will not change. This runs to the context propagation problem.

This implementation builds the span earlier, but that leads to change in behavior of spans at a point which may be hard to track. Currently it would be either first enter, first usage as an explicit parent, soon possibly also first call to .context(). After that some functionality changes, especially calls to set_parent, which can still be called but it leads to unexpected results (and arguably cannot do the expected result of changing the parent of an already started span). I wonder of silently doing nothing rather than updating parent_cx would be better here.

My version just got rid of this method completely for the price of completely changing the way (remote) explicit otel parents are set, which is more restrictive and completely changes the API, but I still think that that's the right way to go in the long term.

[bantonsson]

Thank you @mladedav for this very thorough analysis and testing of my POC. I'm going to go through your examples ASAP and see what can be done.

As for where we should go with the API, my aim was to see if it would be possible to do this with minimal differences to the current tracing-opentelemetry API to be able to reuse the integration work that has already been done. Building and maintaining integrations with different frameworks is no small task.

[cijothomas]

@bantonsson @mladedav When you are referring to "API" what component are you referring to? It is not clear to me which APIs are being referred to here.
In OTel world, "Tracing API" is just the facade part, similar to Tokio's tracing.

[mladedav]

I was (and I assume @bantonsson was) referring to the API surface of tracing-opentelemetry.

[cijothomas]

I was (and I assume @bantonsson was) referring to the API surface of tracing-opentelemetry.

Oh okay! Thanks for clarifying. I wasn't aware that it exposed any API other than what is already covered by tracing itself....Can you share couple examples?