[
https://issues.apache.org/jira/browse/CAMEL-26450?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Work on CAMEL-26450 started by shashank.
----------------------------------------
> 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
> Priority: Major
>
> 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)
