CAMEL-18661: Make span current and clear scope properly for async processing #8713

lmolkova · 2022-11-11T22:55:03Z

Fixesr https://issues.apache.org/jira/browse/CAMEL-18661

~~!Looking for input on the overall approach!~~

This change enables current span propagation to underlying libraries and end-user-code (for OpenTelemetry):
for all spans created by Camel, it calls into span.makeCurrent()

However, OpenTelemetry (and other tracing tools) rely on ThreadLocal to propagate context. They do it carefully for Executors, Reactor, etc, so it works in async scenarios too.

Instrumentations have to close scope returned by span.makeCurrent() on the same thread where it was created to avoid leaking context (by leaving current span on current thread).

This is easy to guarantee with sync operations in Camel - ExchangeStarted/Sending and ExchangeCompleted/Sent events (where spans start and end) are called on the same thread.

However, for async operations, they are called on different threads.

This change also adds a new event - ExchangeAsyncStarted (naming needs more work), that notifies that Processor.process call has ended, i.e. async operation has started. Tracers would end the scope (but not span) when this event is sent.

Alternative approach:

add a dependency on camel-tracing to camel-base-engine and call into ActiveSpanManager directly:

try(AutoCloseable scope = ActiveSpanManager.makeSpanCurrent(exchange)) {
    sync = processor.process(exchange, async);
}

This would be easier to maintain and would more or less guarantee that scope is disposed on the same thread, however, dependency on tracing might not be desirable.

Traces with this change

(tick/testme spans come from Camel and were previously not correlated with ServiceBus spans coming from Azure SDK)

github-actions · 2022-11-11T22:55:18Z

🌟 Thank you for your contribution to the Apache Camel project! 🌟

⚠️ Please note that the changes on this PR may be tested automatically.

If necessary Apache Camel Committers may access logs and test results in the job summaries!

lmolkova · 2022-11-11T22:56:10Z

General question: is there a good place/way to wrap callback executions (user or 3rd party library) with something like

try(AutoCloseable scope = ActiveSpanManager.makeSpanCurrent(exchange)) {
    sync = processor.process(exchange, async);
}

github-actions · 2022-11-14T12:52:47Z

Components tested:

Total	Tested	Failed ❌	Passed ✅
2	2	2	1

davsclaus · 2022-11-26T09:26:38Z

Sorry for not giving this PR attention - however we have been buys (as usual).

Observability with open-telemtry and micrometer is important and thanks for helping with this.

oscerd · 2022-11-26T09:32:14Z

I'm sorry, too. It was on my to-do list to review this and I forgot about it

lmolkova · 2022-11-28T18:40:13Z

@davsclaus @oscerd thank you! Once you folks have time to take a look, please let me know what approach you'd like me to pursue nd I'm happy to work on it further.

lmolkova · 2022-12-06T20:22:43Z

@davsclaus @oscerd friendly ping to take a look. I'd be happy to continue working on it based on your initial feedback.

oscerd

I just found one typo. For placing the camel-tracing dependency in the camel-core-engine, I'm against polluting the core with a tracing component. This will probably create a circular dependency in the maven reactor. So we should find a different way.

core/camel-api/src/main/java/org/apache/camel/AsyncCallback.java

davsclaus · 2022-12-08T17:02:22Z

add a dependency on camel-tracing to camel-base-engine and call into ActiveSpanManager directly:

This is not possible, camel-base should be 100% independent on camel itself only.

davsclaus · 2022-12-08T17:05:40Z

Its actually the opposite

var res = producer.process(exchange, ac);

if the returned value == true then it was a sync call and its done

if the returned value == false, then its async call, and currently processing by another thread (done when the callback is triggered)

lmolkova · 2022-12-10T21:43:47Z

@davsclaus @oscerd thank you for the feedback. I've implemented the current approach with the extra event and added tests. Can you please take another look?

bvahdat · 2022-12-11T09:58:34Z

Hi @lmolkova

Thanks for your contribution and support to look into this issue. Looking into build.log, this is the reason why it has failed:

[ERROR] Failed to execute goal org.apache.maven.plugins:maven-compiler-plugin:3.10.1:testCompile (default-testCompile) on project camel-tracing: Compilation failure: Compilation failure: 
[ERROR] /home/runner/work/camel/camel/components/camel-tracing/src/test/java/org/apache/camel/tracing/ActiveSpanManagerTest.java:[45,23] error: cannot find symbol
[ERROR]   symbol:   method isCurrent()
[ERROR]   location: variable span of type SpanAdapter
[ERROR] /home/runner/work/camel/camel/components/camel-tracing/src/test/java/org/apache/camel/tracing/ActiveSpanManagerTest.java:[49,24] error: cannot find symbol
[ERROR]   symbol:   method isCurrent()
[ERROR]   location: variable span of type SpanAdapter
[ERROR] -> [Help 1]
org.apache.maven.lifecycle.LifecycleExecutionException: Failed to execute goal org.apache.maven.plugins:maven-compiler-plugin:3.10.1:testCompile (default-testCompile) on project camel-tracing: Compilation failure
	at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute2(MojoExecutor.java:375)
	at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute(MojoExecutor.java:351)
	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:215)
	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:171)
	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:163)
	at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117)
	at org.mvndaemon.mvnd.builder.SmartBuilderImpl.buildProject(SmartBuilderImpl.java:178)
	at org.mvndaemon.mvnd.builder.SmartBuilderImpl$ProjectBuildTask.run(SmartBuilderImpl.java:198)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: org.apache.maven.plugin.compiler.CompilationFailureException: Compilation failure
	at org.apache.maven.plugin.compiler.AbstractCompilerMojo.execute(AbstractCompilerMojo.java:1310)
	at org.apache.maven.plugin.compiler.TestCompilerMojo.execute(TestCompilerMojo.java:183)
	at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
	at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute2(MojoExecutor.java:370)
	... 12 common frames omitted

Please note that you don't have access to the pipeline's generated build.log but I think you should be able to reproduce it locally.

davsclaus · 2022-12-12T10:48:46Z

Using the event notifier to emit a "async processing" event is tricky as there are potentially more places this can happens in the core routing engine. However they all bubble up to the base-engine in the CamelInternalProcessor, especially for spans that would call external systems via "SendProcessor".

lmolkova · 2022-12-12T19:49:27Z

@bvahdat thank you! it should be fixed now.

@davsclaus I removed notifications from everywhere except CamelInternalProcessor and yes, everything seems to be working.

Do you have in mind any scenarios I can run to validate to make sure I didn't miss something? I tried to cover what I can think of in CurrentSpanTests.

davsclaus · 2022-12-13T16:21:48Z

@lmolkova have you tested your latest code with the AWS servicebus to see if the diagram/span looks correct

lmolkova · 2022-12-13T17:27:37Z

@davsclaus, yes, I did (with Azure ServiceBus ) and yes, it works fine and looks the same as in the description.

github-actions · 2022-12-13T17:40:07Z

Components tested:

Total	Tested	Failed ❌	Passed ✅
9	9	1	9

github-actions · 2022-12-13T19:22:49Z

Components tested:

Total	Tested	Failed ❌	Passed ✅
9	9	1	9

davsclaus

need to fix tests

davsclaus · 2022-12-15T09:23:37Z

It happens when its the JDK fork-join pool that are in use

pool-17-thread-4 -> Valid context: false
pool-17-thread-8 -> Valid context: false
pool-17-thread-2 -> Valid context: false
pool-17-thread-9 -> Valid context: false
pool-17-thread-1 -> Valid context: false
Camel (camel-8) thread #11 - Delay -> Valid context: false
ForkJoinPool.commonPool-worker-5 -> Valid context: true

Which is a JDK pool you use via

private static final Executor DELAYED = CompletableFuture.delayedExecutor(100L, TimeUnit.MILLISECONDS);

lmolkova · 2022-12-15T18:03:27Z

thanks a lot, @davsclaus ! I was able to reproduce testContextDoesNotLeak locally with Java 11 (does not repro with 17 I used before) and working on fixing it. I'll try my best to fix it today.

davsclaus · 2022-12-15T18:17:09Z

Thanks for looking into this. Yeah I only tried with JDK11, as I use that primary due to Camel v3 is still Java 11 based.

Could be that the JDK ForJoin pool behaves differently or something?

bvahdat · 2022-12-15T20:02:38Z

@lmolkova by any chance, could you please rebase on top of the main branch when you are done?

davsclaus · 2022-12-15T20:09:14Z

Yeah in the mean time we have upgraded: upgrade opentelemetry to the version 1.21.0

lmolkova · 2022-12-15T23:21:40Z

@bvahdat sure, I rebased!

I believe (again) that I fixed tests. There were two issues:

We still need to clean the context in SendProcessor: since we have multiple nested spans, we need to clean scope after them. I think I found all the new event-related tests.
Test was not correct: sometimes aggregation can be scheduled on the same thread on which outer span is still active - it's ok and if we had OTel executor instrumentation enabled, it'd populate this context on other threads too. Added check and description to the test. This behavior was different on Java 11 and Java 17 and affected Java 11 much more. It's stable now on both versions.

github-actions · 2022-12-16T06:32:23Z

Components tested:

Total	Tested	Failed ❌	Passed ✅
3	3	1	3

github-actions · 2022-12-16T08:22:22Z

Components tested:

Total	Tested	Failed ❌	Passed ✅
3	3	0	4

trask · 2022-12-16T15:03:53Z

thanks @lmolkova and camel team!!

lmolkova · 2022-12-16T17:10:09Z

Thank you all!

oscerd · 2022-12-16T17:27:33Z

Opentelemetry support is important. We would like to improve it in the future. This is a really good work. Thanks to everyone involved.

…cessing (apache#8713) * Prototype: make span current and clear scope * cleanup * tests and fixes * cleanup and tests * cleanup * fix build * Remove unnecessary notifications * fix tests * oops * Fix tests on Java 11 * checkstyle

github-actions bot added components core labels Nov 11, 2022

oscerd requested changes Dec 7, 2022

View reviewed changes

core/camel-api/src/main/java/org/apache/camel/AsyncCallback.java Outdated Show resolved Hide resolved

lmolkova force-pushed the otel-current-span branch from 66ff694 to 78389af Compare December 10, 2022 20:13

lmolkova marked this pull request as ready for review December 10, 2022 21:42

lmolkova changed the title ~~Prototype: make span current and clear scope~~ Make span current and clear scope properly for async processing Dec 10, 2022

lmolkova force-pushed the otel-current-span branch 2 times, most recently from 40ddebf to afa146b Compare December 10, 2022 21:52

oscerd approved these changes Dec 11, 2022

View reviewed changes

bvahdat changed the title ~~Make span current and clear scope properly for async processing~~ CAMEL-18661: Make span current and clear scope properly for async processing Dec 12, 2022

lmolkova force-pushed the otel-current-span branch 2 times, most recently from dc45e19 to 8989daf Compare December 12, 2022 19:53

davsclaus approved these changes Dec 13, 2022

View reviewed changes

davsclaus requested changes Dec 15, 2022

View reviewed changes

lmolkova added 10 commits December 15, 2022 15:10

Prototype: make span current and clear scope

716d593

cleanup

d01f4bf

tests and fixes

f94b7d3

cleanup and tests

505e0bc

cleanup

ded9912

fix build

cd3d8c9

Remove unnecessary notifications

3b99fa6

fix tests

8b58fa3

oops

3a60def

Fix tests on Java 11

93c9d81

lmolkova force-pushed the otel-current-span branch from 77d0d64 to 93c9d81 Compare December 15, 2022 23:13

checkstyle

64d4fab

davsclaus approved these changes Dec 16, 2022

View reviewed changes

oscerd approved these changes Dec 16, 2022

View reviewed changes

davsclaus merged commit 002c9ca into apache:main Dec 16, 2022

bvahdat mentioned this pull request Dec 16, 2022

CAMEL-18661: clean-ups #8911

Merged

lmolkova mentioned this pull request Dec 20, 2022

Tracing: fix flaky test and add scope checks before closing #8934

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

CAMEL-18661: Make span current and clear scope properly for async processing #8713

CAMEL-18661: Make span current and clear scope properly for async processing #8713

lmolkova commented Nov 11, 2022 •

edited

github-actions bot commented Nov 11, 2022

lmolkova commented Nov 11, 2022

github-actions bot commented Nov 14, 2022

davsclaus commented Nov 26, 2022

oscerd commented Nov 26, 2022

lmolkova commented Nov 28, 2022

lmolkova commented Dec 6, 2022

oscerd left a comment

davsclaus commented Dec 8, 2022

davsclaus commented Dec 8, 2022 •

edited

lmolkova commented Dec 10, 2022

bvahdat commented Dec 11, 2022

davsclaus commented Dec 12, 2022

lmolkova commented Dec 12, 2022

davsclaus commented Dec 13, 2022

lmolkova commented Dec 13, 2022

github-actions bot commented Dec 13, 2022

github-actions bot commented Dec 13, 2022

davsclaus left a comment

davsclaus commented Dec 15, 2022 •

edited

lmolkova commented Dec 15, 2022

davsclaus commented Dec 15, 2022

bvahdat commented Dec 15, 2022

davsclaus commented Dec 15, 2022

lmolkova commented Dec 15, 2022

github-actions bot commented Dec 16, 2022

github-actions bot commented Dec 16, 2022

trask commented Dec 16, 2022

lmolkova commented Dec 16, 2022

oscerd commented Dec 16, 2022

CAMEL-18661: Make span current and clear scope properly for async processing #8713

CAMEL-18661: Make span current and clear scope properly for async processing #8713

Conversation

lmolkova commented Nov 11, 2022 • edited

github-actions bot commented Nov 11, 2022

lmolkova commented Nov 11, 2022

github-actions bot commented Nov 14, 2022

Components tested:

davsclaus commented Nov 26, 2022

oscerd commented Nov 26, 2022

lmolkova commented Nov 28, 2022

lmolkova commented Dec 6, 2022

oscerd left a comment

Choose a reason for hiding this comment

davsclaus commented Dec 8, 2022

davsclaus commented Dec 8, 2022 • edited

lmolkova commented Dec 10, 2022

bvahdat commented Dec 11, 2022

davsclaus commented Dec 12, 2022

lmolkova commented Dec 12, 2022

davsclaus commented Dec 13, 2022

lmolkova commented Dec 13, 2022

github-actions bot commented Dec 13, 2022

Components tested:

github-actions bot commented Dec 13, 2022

Components tested:

davsclaus left a comment

Choose a reason for hiding this comment

davsclaus commented Dec 15, 2022 • edited

lmolkova commented Dec 15, 2022

davsclaus commented Dec 15, 2022

bvahdat commented Dec 15, 2022

davsclaus commented Dec 15, 2022

lmolkova commented Dec 15, 2022

github-actions bot commented Dec 16, 2022

Components tested:

github-actions bot commented Dec 16, 2022

Components tested:

trask commented Dec 16, 2022

lmolkova commented Dec 16, 2022

oscerd commented Dec 16, 2022

lmolkova commented Nov 11, 2022 •

edited

davsclaus commented Dec 8, 2022 •

edited

davsclaus commented Dec 15, 2022 •

edited