shashank created CAMEL-26450:
--------------------------------
Summary: camel-telemetry - the steps after an asynchronous step
(delay, threads) get its span as parent, and spans are ended by the wrong events
Key: CAMEL-26450
URL: https://issues.apache.org/jira/browse/CAMEL-26450
Project: Camel
Issue Type: Bug
Components: camel-telemetry
Reporter: shashank
Assignee: shashank
Found with a Lean model of the span stack of {{camel-telemetry}} (the stack of
spans kept on the exchange by {{SpanStorageManagerExchange}}: begin pushes, end
pulls the top), then reproduced with {{camel-opentelemetry2}} and the
OpenTelemetry SDK.
{{TraceProcessorsInterceptStrategy.TraceProcessor.process(exchange, callback)}}
begins the span of a step and ends it in a {{finally}} *after*
{{callback.done(doneSync)}}:
{code:java}
return processor.process(exchange, doneSync -> {
try {
callback.done(doneSync);
} finally {
tracer.endProcessorSpan(exchange, processorName);
}
});
{code}
When the step calls back from another thread ({{delay}}, which is asynchronous
by default, {{threads}}, {{throttle}} with {{asyncDelayed}}, a {{bean}} that
returns a {{CompletableFuture}}, or an EIP or called route that contains such a
step), {{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 is still on top of the
exchange's span stack, so:
* the following steps get the span of the asynchronous step as parent, instead
of the route span (or the span of the enclosing EIP);
* that span lasts until the end of the route, and a failure in a later step
marks it as failed;
* around a called route ({{to("direct:sub")}} whose route has such a step) the
end events pull the wrong spans: the called route's end closes the step's span,
the send's end closes the called route's span, the caller route's end closes
the send's span, and the step's end closes the caller route's span;
* with {{recipientList}} or {{enrich}} to such routes, some spans are never
ended (camel-telemetry-dev keeps such traces in memory for ever, as it writes a
trace only when all its spans are ended).
{{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 the Exchange stack is kept to
"maintain a hierarchy relationship between the different spans created during
an Exchange execution". A step that completes synchronously is fine, because
{{callback.done}} only queues the rest of the route there.
*Reproducer* (camel-opentelemetry2, OpenTelemetry SDK 1.66,
InMemorySpanExporter):
{code:java}
from("direct:start").routeId("start")
.setHeader("a", constant("1")).id("step1")
.delay(20).id("delay") // asynchronous by default
.setHeader("c", constant("3")).id("step2")
.setHeader("d", constant("4")).id("step3");
{code}
{noformat}
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, step3)
{noformat}
*Affected versions*: since 4.17.0 (the order came with apache/camel#20529,
which made TraceProcessor asynchronous; 4.16 and older ended the span first).
On 4.17 to 4.20 only for the processors that are traced there
({{traceProcessors=true}}); since 4.21 also with the default options, as the
spans of the core processors are on by default. 4.14.x is not affected.
The Lean model proves that with the current order a route [asynchronous step;
step] gives the second step the first step's span as parent and makes the ends
close each other's spans, and that ending the span before calling
{{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.
*Proposal*: in {{TraceProcessor.process(exchange, callback)}}, end the span
first and then call {{callback.done(doneSync)}} (in a {{finally}}); end the
span only when it was begun (when {{beginProcessorSpan}} fails, the end pulled
the parent's span). {{camel-opentelemetry2}},
{{camel-micrometer-observability}} and {{camel-telemetry-dev}} use this
strategy; the scope wrappers of the first two only delegate the callback.
Priority Major: with the default options since 4.21, every route with an
asynchronous {{delay}}, {{threads}}, an asynchronous {{throttle}} or a {{bean}}
returning a {{CompletableFuture}} produces a wrong trace tree, wrong span
durations and errors on the wrong spans, and some spans are never ended.
_Filed with Claude Code on behalf of allthingssecurity._
--
This message was sent by Atlassian Jira
(v10.3.26#10030026)
