allthingssecurity opened a new pull request, #28806: URL: https://github.com/apache/camel/pull/28806
# Description [CAMEL-26450](https://issues.apache.org/jira/browse/CAMEL-26450) `TraceProcessorsInterceptStrategy` (camel-telemetry; used by camel-opentelemetry2, camel-micrometer-observability and camel-telemetry-dev) begins the span of a step before the step, and ended it in a `finally` after `callback.done(doneSync)`. When the step calls back from another thread, `callback.done` runs the rest of the route inside that call (`DefaultReactiveExecutor` runs the queued work at once on a thread that is not already running reactive work). The span of the step was then still on top of the exchange's span stack (`SpanStorageManagerExchange`, where an end pulls the top) while the next steps ran: - the following steps got the span of the asynchronous step as parent, instead of the route span (or the span of the enclosing EIP); - that span lasted until the end of the route, and a failure in a later step marked it as failed; - around a called route (`to("direct:called")` whose route has such a step) the end events pulled the wrong spans: the called route's end closed the step's span, the send's end closed the called route's span, the caller route's end closed the send's span, and the step's end closed the caller route's span; - with `recipientList` or `enrich` to such routes, some spans were never ended. camel-telemetry-dev writes a trace only when all its spans are ended, so it kept those traces in memory. Steps that call back from another thread: `delay` (asynchronous by default), `threads`, `throttle` with `asyncDelayed`, a `bean` that returns a `CompletableFuture`, and any EIP or called route that contains one. A step that completes on the caller's thread was not affected (there `callback.done` only queues the rest of the route), and neither were EIPs that call back on their own thread after an asynchronous send, such as a parallel split. With camel-opentelemetry2 and the OpenTelemetry SDK, for `setHeader` (step1), `delay(20)`, `setHeader` (step2), `setHeader` (step3): ``` delay().syncDelayed() delay() (asynchronous) step1 parent=start step1 parent=start delay parent=start 30 ms step2 parent=delay-delay step2 parent=start step3 parent=delay-delay step3 parent=start delay parent=start 30 ms, ends after step2 and step3 ``` `design/tracing.adoc`, "Tracing structure": "For each event spanning the execution of the Route, then, it will be created a separate Span, which goal is to capture each component or step execution"; and "Tracing storage" keeps the Exchange stack, of which the context section says it "is also taking care to maintain a hierarchy relationship between the different spans created during an Exchange execution". The tree example on the camel-telemetry-dev page shows `delay1-delay` and the next step `log2-log` as siblings, as with this change. This is a regression since 4.17: apache/camel#20529 (December 2025) made `TraceProcessor` asynchronous and put the end after `callback.done`; before, the span ended when the step was done. On 4.17 to 4.20 it shows only for the processors traced there (`traceProcessors=true`); since 4.21 also with the default options, as the spans of the core processors are on by default. Changes: - `TraceProcessor.process(exchange, callback)` ends the span first and then calls `callback.done(doneSync)`, in a `finally` so the callback is called also when ending the span throws an `Error`. - A failure to end the span is still set on the exchange, as before (now before the route continues). - The span is ended only when it was begun. When `beginProcessorSpan` failed, the end pulled the span on top of the stack, which was the parent's span (the route span), so the next steps got the template's span as parent. - 4.24 upgrade guide: the trace tree changes, the asynchronous step's span is shorter, a later failure no longer marks it as failed, and `onException` steps and custom spans after it are no longer nested under it. There is no option to keep the 4.17 tree, as it is the tree of 4.16 and older again. Tests: - camel-telemetry `AsyncProcessorSpanTest` (MockTracer), 8 tests: asynchronous `delay`, `threads`, a `bean` returning a `CompletableFuture`, a `delay` inside a `choice`, a called route with a `delay`, a `recipientList` to two routes with a `delay` (every span ended), and a failure after a `delay` (only the failing step's span has the error). Each checks the parents and that every span is ended; the step cases also check that the asynchronous step's span ends before the next step starts. These 7 fail with the `TraceProcessorsInterceptStrategy` of main. `delay().syncDelayed()` is a control that passes on main as well. - camel-telemetry `ProcessorSpanBeginFailureTest`, 1 test: span creation fails for one step (the failure is continued by an `onException`); the next step is a child of the route span. Fails on main. - camel-opentelemetry2 `AsyncProcessorSpanTest` (OpenTelemetry SDK, `InMemorySpanExporter`), 3 tests: `delay`, `threads`, and the `syncDelayed` control. The first 2 fail on main. - camel-telemetry-dev and camel-micrometer-observability `AsyncProcessorSpanTest`, 1 test each (a `delay` and two steps, with the core processor spans on). Both fail on main. - The new test classes 20 times in one JVM: camel-telemetry (both classes together) 180 tests, camel-opentelemetry2 60, camel-telemetry-dev 20, camel-micrometer-observability 20, 0 failures. - Module tests with the change: camel-telemetry 180, camel-opentelemetry2 41, camel-telemetry-dev 14, camel-micrometer-observability 20, 0 failures (offline build, with the locally available versions of the OpenTelemetry log4j appender and micrometer-tracing test dependencies). The formatter and import-sort plugins ran. How it was found: a Lean model of the span stack of an exchange (push on begin, pull of the top on end), with the order of end and `callback.done` as in the code. It gives the counterexample `[asynchronous step; step]` (the second step gets the first step's span as parent, and with a called route the ends close each other's spans), and proves that ending the span before `callback.done` gives every step the route span as parent and closes every span by its own end, for every route and every mix of synchronous and asynchronous steps. The case was then reproduced with camel-opentelemetry2 and the OpenTelemetry SDK, and reduced to the tests above. A property check over random routes (nested split, multicast, filter, loop, doTry/doCatch, wireTap, routing slip, recipient list and called routes, with asynchronous `delay` and `threads` steps) with a recording tracer: with this change and the companion one, 0 of 1250 routes have a span ended by another step's end or left open (four seeds; the last two also with enrich, asynchronous throttle, dynamic router, idempotent consumer and toD); with the code of main, 131 of 150. Not changed: - `TraceProcessorsOtelInterceptStrategy` (camel-opentelemetry2) and `TraceProcessorsMicrometerObsInterceptStrategy` (camel-micrometer-observability) only make the span current around the call and pass the callback through; they need no change. - The deprecated camel-tracing strategies wrap only the blocking `process(Exchange)` path and are not affected. - camel-mdc's `MDCProcessorsInterceptStrategy` restores the previous MDC in the same kind of `finally` after `callback.done`, so after an asynchronous step the consumer thread keeps the exchange's MDC. That is a separate, minor issue; I will file a follow-up JIRA for it (CAMEL-22839 is about thread-local consistency in general). - The sync `process(Exchange)` path still lets a begin or end failure fail the step, as before. - Routing slips and dynamic routers to routes with such steps also need the camel-core fix of CAMEL-26451, proposed together with this one (the routing slip fires the sent event of a step only after the following steps, so its snapshot copies keep a send span on the stack); with both, every span of such routes is ended by its own end. - A failure to end the span of an asynchronous step now fails the exchange before the next step (it is set on the exchange before the route continues); before, the rest of the route ran and the exception was set afterwards. Ending a span fails only when a span decorator or the tracing library throws. Backport: 4.18.x, 4.22.x and 4.23.x have the same code (on 4.18.x only with `traceProcessors=true`). The trace tree changes for users, so main only unless a backport is wanted; 4.14.x is not affected. # Target - [x] I checked that the commit is targeting the correct branch (Camel 4 uses the `main` branch) # Tracking - [x] If this is a large change, bug fix, or code improvement, I checked there is a [JIRA issue](https://issues.apache.org/jira/browse/CAMEL-26450) filed for the change (usually before you start working on it): [CAMEL-26450](https://issues.apache.org/jira/browse/CAMEL-26450). # Apache Camel coding standards and style - [x] I checked that each commit in the pull request has a meaningful subject line and body. - [ ] I have run `mvn clean install -DskipTests` locally from root folder and I have committed all auto-generated changes. (I built the core modules, camel-telemetry, camel-telemetry-dev, camel-opentelemetry2 and camel-micrometer-observability and ran their tests, including the formatter and import-sort plugins. I did not run the full root build.) # AI-assisted contributions - [x] If this PR includes AI-generated code, commits have proper co-authorship attribution (e.g., `Co-authored-by` trailers) and the PR description identifies the AI tool used. This PR was prepared with Claude Code (Claude Opus 5.5). The commit carries a `Co-Authored-By` trailer. _Claude Code on behalf of allthingssecurity_ 🤖 Generated with [Claude Code](https://claude.com/claude-code) -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
