[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?

[mladedav]

The main one is set_parent which is used to explicitly set opentelemetry parent context regardless of tracing parent. Notably, tracing does not support remote parents so whenever context propagation happens, this is currently used to set the remote parent after the tracing span is created.

Complementary to that there's also context to get the context of the span for propagation.

There are some more methods on the extension trait but I think these two are the most important.

[cijothomas]

Removing from 0.29 milestone. New ETA to be shared.

[hseeberger]

Nice to see you here, @bantonsson !

[mladedav]

What are the next steps here?

There are two different prototypes

• one is closer to the original tracing-opentelemetry making migration easier
• one has different usage when propagating contexts but it no longer depends on custom code in opentelemtry-rust made for tracing integration

I guess getting either merged to tracing-opentelemetry could improve the situation. Though maybe it can also just live in this repository depending on what maintainers here want. tracing-opentelemetry's maintainer doesn't have enough time to invest more into it than trying to keep up with opentelemetry-rust releases and reviewing PRs.

Basically, I'm not really sure what's the next goal after we have these prototypes.

[scottgerring]

What are the next steps here?

There are two different prototypes

* one is closer to the original `tracing-opentelemetry` making migration easier

* one has different usage when propagating contexts but it no longer depends on custom code in `opentelemtry-rust` made for `tracing` integration

I guess getting either merged to tracing-opentelemetry could improve the situation. Though maybe it can also just live in this repository depending on what maintainers here want. tracing-opentelemetry's maintainer doesn't have enough time to invest more into it than trying to keep up with opentelemetry-rust releases and reviewing PRs.

Basically, I'm not really sure what's the next goal after we have these prototypes.

Hey @mladedav I had a chat with @cijothomas and @bantonsson in the last couple days about this. Today i'll write up a "high level path to victory" and ping everyone on it to discuss, so we can try drive this forward.

[bantonsson]

• one is closer to the original tracing-opentelemetry making migration easier
• one has different usage when propagating contexts but it no longer depends on custom code in opentelemtry-rust made for tracing integration

@mladedav Sorry for the lack of progress here. I'm just getting back to this. I just want to clarify that the intent of my POC is to remove all custom code in opentelemetry-rust as well. I think this is quite possible while still being close to the original tracing-opentelemetry code.

[mladedav]

I didn't mean to put pressure on you or anything, I was genuinely not sure what should happen next so feel free to take your time.

As to the custom code, I thought the way presampling works in tracing-opentelemetry needed some accommodations to sample not yet started spans but I might be wrong.

[bantonsson]

No worries. I've been meaning to get back to this.

As to the custom code, I thought the way presampling works in tracing-opentelemetry needed some accommodations to sample not yet started spans but I might be wrong.

You are completely right, and that is why I'm starting the OpenTelemetry Span at first use so the pre-sampling shouldn't be needed.

[scottgerring]

With @bantonsson's support, I spent a bunch of time last week grokking opentelemetry-tracing, and have addressed the issues identified by @mladedav (#2420 (comment)) and evaluated the performance against the existing code base(see below) .

You can find the tests added and the changes on Björn's branch

Fixes

broken children
We now consume the SpanBuilder and materialize the OTel trace the first time SpanExt::context is called on it. This is straightforward enough to implement following the WithContext pattern to call back into the layer and trigger things.

change parent more than once using set_parent(OtelContext)
It wasn't immediately obvious to me that set_parent(OtelContext) exists, with this signature, to support passing in OTel distributed context. It should only be called once per request - to provide this context. We could make the code more complicated to let the user call it more than once, but this adds complexity and no additional value.

Span hierarchy otherwise should be established in the typical tokio-tracing fashion - either implicitly via tokio-tracing context ("I created a new span within an existing active span"), or via the tokio-tracing Span's explicit parent mechanism.

sampling_decision_respects_new_parent
This existing test forced a child span to materialize before the parent and then checked that the sampling decision from the parent was propagated. I posit that the test is incorrect - this shouldn't happen.

**

Benchmark Results

• Baseline is v0.1.x / b6701c1f971e1401d91ef7116fd4cf92c9c35989.

• no-activate' is without activate_context` set.

• new-activate is with activate_context set.

Both of these are benchmarked from Björn's fork.

I think we should mainly concern ourselves with regressions in no-activate - we expect new-activate to regress somewhat because of context activation!

• many_children: Benchmarks the overhead of creating many child spans under a single parent span.

• many_enters: Benchmarks repeatedly entering the same span many times (e.g., looped work inside a single span).

• many_events: Benchmarks adding many events inside a span

• spec_baseline: Pure OpenTelemetry SDK tracing using native opentelemetry API without tracing.

• no_data_baseline: Uses tracing with a minimal custom layer that doesn't attach or process span data.

• data_only_baseline: Uses tracing with a layer that prepares span data (e.g. creates SpanBuilder), but doesn't export it.

• full: Uses tracing_opentelemetry with full OpenTelemetry export pipeline and inactivity tracking.

• full_with_timings: Like full, but specifically configured to track span timing more accurately.

• full_without_timings: Like full, but with timing optimizations disabled (i.e. less overhead for spans).

Benchmark	Baseline avg ± std	No-activate avg ± std	No-activate Δ (%)	New-activate avg ± std	New-activate Δ (%)
otel_many_children/full	40.20 µs ± 159.80 ns	36.06 µs	-10.28%	49.77 µs	23.78%
otel_many_events/full_not_filtered	188.59 µs ± 1.52 µs	217.43 µs ± 1.63 µs	15.29%	217.04 µs ± 1.57 µs	15.09%
otel_many_enters/full_without_timings	43.25 µs ± 127.82 ns	45.53 µs ± 86.86 ns	5.28%	69.38 µs ± 185.95 ns	60.42%
otel_many_events/full_filtered	195.10 µs ± 1.17 µs	203.16 µs ± 1.09 µs	4.13%	196.32 µs ± 1.09 µs	0.63%
otel_metrics_events/metrics_events_1_attr_0	67.22 ns ± 0.29 ns	69.58 ns ± 0.53 ns	3.51%	67.96 ns ± 0.25 ns	1.10%
otel_metrics_events/metrics_events_1_attr_1	73.08 ns ± 0.30 ns	75.03 ns ± 0.32 ns	2.67%	73.91 ns ± 0.21 ns	1.14%
otel_metrics_events/metrics_events_1_attr_2	79.16 ns ± 0.36 ns	80.58 ns ± 0.23 ns	1.79%	79.99 ns ± 0.30 ns	1.05%
otel_metrics_events/metrics_events_2_attr_0	83.43 ns ± 0.38 ns	84.21 ns ± 0.38 ns	0.93%	82.90 ns ± 0.23 ns	-0.64%
otel_metrics_events/metrics_events_0_attr_0	19.08 ns ± 0.11 ns	19.13 ns ± 0.09 ns	0.26%	19.09 ns ± 0.13 ns	0.03%
otel_many_events/data_only_baseline	41.72 µs ± 219.62 ns	41.66 µs ± 166.89 ns	-0.14%	40.73 µs ± 103.85 ns	-2.38%
otel_many_events/no_data_baseline	23.20 µs ± 90.97 ns	23.13 µs ± 117.36 ns	-0.32%	22.47 µs ± 77.29 ns	-3.14%
otel_many_children/spec_baseline	7.38 µs ± 77.90 ns	7.33 µs ± 38.02 ns	-0.55%	7.24 µs ± 17.99 ns	-1.91%
otel_many_enters/spec_baseline	16.80 µs ± 55.54 ns	16.71 µs ± 28.68 ns	-0.55%	16.64 µs ± 46.94 ns	-0.96%
otel_many_children/no_data_baseline	10.01 µs ± 22.50 ns	9.92 µs ± 18.41 ns	-0.83%	9.71 µs ± 17.03 ns	-2.94%
otel_metrics_events/no_metrics_layer	7.67 ns ± 0.05 ns	7.59 ns ± 0.03 ns	-1.03%	7.71 ns ± 0.04 ns	0.50%
otel_many_enters/no_data_baseline	23.45 µs ± 102.77 ns	23.17 µs ± 65.17 ns	-1.20%	23.24 µs ± 34.22 ns	-0.90%
otel_many_enters/full_with_timings	94.90 µs ± 676.91 ns	93.42 µs ± 182.33 ns	-1.56%	105.78 µs ± 159.22 ns	11.47%
otel_many_enters/data_only_baseline	23.77 µs ± 87.72 ns	23.23 µs ± 41.56 ns	-2.25%	23.41 µs ± 33.03 ns	-1.53%
otel_many_children/data_only_baseline	17.60 µs ± 89.25 ns	16.97 µs ± 56.56 ns	-3.63%	16.96 µs ± 135.64 ns	-3.64%

Next Steps

• It would be great to get your feedback @mladedav about the changes made to address your tests!
• It will be good to have a chat with the tokio-tracing folks soon, @cijothomas

Update 15/04: Updated results table; oltel_many_children/full @bantonsson turned the perf regression into a net improvement here with context activation disabled