shashank created CAMEL-26451:
--------------------------------
Summary: camel-core - Routing Slip / Dynamic Router: a step's
ExchangeSentEvent is fired after the following steps
Key: CAMEL-26451
URL: https://issues.apache.org/jira/browse/CAMEL-26451
Project: Camel
Issue Type: Bug
Components: camel-core
Reporter: shashank
Assignee: shashank
Found with a Lean model of the span stack of camel-telemetry, extended to the
snapshot copies of the Routing Slip, then reproduced on camel-core with a plain
event notifier.
When a step of a routing slip or dynamic router completes asynchronously
(nearly every step under the default error handler, as the error handler of
each step schedules its work; a step is synchronous only with
{{noErrorHandler}}, inside a {{doTry}} or under a transaction error handler,
with a synchronous producer), the callback of the step in
{{RoutingSlip.processExchange}} takes the snapshot copy for the next step, runs
all the remaining steps, copies the result back onto the exchange, and only
then calls the callback of the producer cache, which fires the step's
{{ExchangeSentEvent}} and releases its producer. The synchronous path fires the
sent event before the next step.
With {{routingSlip(constant("direct:step1,direct:step2"))}}, step1 taking about
10 ms and step2 about 300 ms, an event notifier sees:
{noformat}
main: sending step1, sending step2, sent step2 (300 ms), sent step1 (310
ms)
expected: sending step1, sent step1 (10 ms), sending step2, sent step2 (300 ms)
{noformat}
(the same for {{dynamicRouter}} and with {{cacheSize=-1}}; {{recipientList}}
and {{to}} give the expected order). So:
* the {{timeTaken}} of the sent event of a step covers all the following steps;
* the sent event of the first step sees the message and the failure after the
last step (it runs on the exchange itself, onto which the result is copied), so
it is reported as failed when a later step failed;
* the consumers of the sent events report wrong data: the exchange event
notifier timers of camel-micrometer and camel-opentelemetry-metrics (time and
{{failed}} tag), camel-jfr's send events (kept on a stack in the exchange, so
mispaired), the deprecated camel-tracing;
* the producer of a step is released only when the whole routing slip is done;
* with camel-telemetry (camel-opentelemetry2, camel-micrometer-observability,
camel-telemetry-dev; together with CAMEL-26450, the camel-telemetry fix for the
spans of asynchronous steps), the snapshot for the next step is taken while the
send span of the previous step is still on the span stack, which is then copied
back onto the exchange: the end events of the routing slip and of its route
pull the wrong spans, and the outermost span (such as the send of a
{{ProducerTemplate}}) is never ended, so the trace is not complete
(camel-telemetry-dev keeps such a trace in memory, as it writes a trace only
when all its spans are ended).
The Lean model shows that taking the snapshot before the step's sent event
leaves the step's span on the exchange's stack after the routing slip, and
proves that firing the sent event first gives the exchange back the stack it
had before the routing slip, for any number of steps.
*Proposal*: in {{RoutingSlip.processExchange}}, let the step's callback call
the producer cache callback right away (sent event, producer released), and
continue the routing slip with the remaining steps in the callback that the
producer cache calls afterwards ({{doInAsyncProducer}}'s callback), as the
synchronous path does. {{DynamicRouter}} extends {{RoutingSlip}} and gets the
same fix.
Affected: all 4.x lines (the same code on camel-4.14.x and camel-4.18.x).
_Filed with Claude Code on behalf of allthingssecurity._
--
This message was sent by Atlassian Jira
(v10.3.26#10030026)
