You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@camel.apache.org by "Sergio Penkale (Jira)" <ji...@apache.org> on 2021/07/08 10:37:00 UTC
[jira] [Created] (CAMEL-16794) race condition in LoopProcessor
Sergio Penkale created CAMEL-16794:
--------------------------------------
Summary: race condition in LoopProcessor
Key: CAMEL-16794
URL: https://issues.apache.org/jira/browse/CAMEL-16794
Project: Camel
Issue Type: Bug
Components: came-core, eip
Affects Versions: 3.11.0, 3.8.0
Reporter: Sergio Penkale
I get random errors when using the Loop EIP with more than one concurrent request. It started happening from release 3.8.0.
This reproduces it:
{code:java}
from("servlet:test")
.log("test.exchangeId=${exchangeId}")
.loop(1)
.log("loop.exchangeId=${exchangeId}")
.end();
{code}
When testing with the following the client times out:
{code:java}
ab -n1000 -c 2 http://localhost:8080/camel/test{code}
Note in the logs below how thread 4 starts working on exchange {{0FBD82C2E690DA5-0000000000000018}} but then switches to exchange {{0FBD82C2E690DA5-0000000000000017}}
This is because the state is created and then scheduled in a non atomic way, so by the time it gets scheduled another thread has changed it:
{code:java}
state = new LoopState(exchange, callback);
if (exchange.isTransacted()) {
reactiveExecutor.scheduleSync(state);
} else {
reactiveExecutor.scheduleMain(state);
}
{code}
{code:java}
2021-07-08 10:04:28.717 TRACE 18495 --- [nio-8080-exec-4] o.a.c.i.engine.CamelInternalProcessor : Processing exchange for exchangeId: 0FBD82C2E690DA5-0000000000000018 -> Exchange[0FBD82C2E690DA5-0000000000000018]
2021-07-08 10:04:28.717 TRACE 18495 --- [nio-8080-exec-5] o.a.c.i.engine.CamelInternalProcessor : Processing exchange for exchangeId: 0FBD82C2E690DA5-0000000000000017 -> Exchange[0FBD82C2E690DA5-0000000000000017]
2021-07-08 10:04:28.717 TRACE 18495 --- [nio-8080-exec-4] o.a.c.i.engine.DefaultReactiveExecutor : Schedule [first=true, main=true, sync=false]: SimpleTask
2021-07-08 10:04:28.717 TRACE 18495 --- [nio-8080-exec-5] o.a.c.i.engine.DefaultReactiveExecutor : Schedule [first=true, main=true, sync=false]: SimpleTask
2021-07-08 10:04:28.717 TRACE 18495 --- [nio-8080-exec-4] o.a.c.i.engine.DefaultReactiveExecutor : Queuing reactive work: SimpleTask
2021-07-08 10:04:28.717 TRACE 18495 --- [nio-8080-exec-5] o.a.c.i.engine.DefaultReactiveExecutor : Queuing reactive work: SimpleTask
2021-07-08 10:04:28.717 TRACE 18495 --- [nio-8080-exec-4] o.a.c.i.engine.CamelInternalProcessor : Exchange processed and is continued routed asynchronously for exchangeId: 0FBD82C2E690DA5-0000000000000018 -> Exchange[0FBD82C2E690DA5-0000000000000018]
2021-07-08 10:04:28.717 TRACE 18495 --- [nio-8080-exec-5] o.a.c.i.engine.CamelInternalProcessor : Exchange processed and is continued routed asynchronously for exchangeId: 0FBD82C2E690DA5-0000000000000017 -> Exchange[0FBD82C2E690DA5-0000000000000017]
2021-07-08 10:04:28.717 TRACE 18495 --- [nio-8080-exec-4] o.a.c.i.engine.DefaultReactiveExecutor : Worker #4 running: org.apache.camel.processor.Pipeline$PipelineTask@3a83e1b8
2021-07-08 10:04:28.717 TRACE 18495 --- [nio-8080-exec-5] o.a.c.i.engine.DefaultReactiveExecutor : Worker #5 running: org.apache.camel.processor.Pipeline$PipelineTask@74d4d21
2021-07-08 10:04:28.717 TRACE 18495 --- [nio-8080-exec-5] o.a.c.i.c.CoreTypeConverterRegistry : Finding type converter to convert java.lang.String -> java.lang.Integer with value: 1
2021-07-08 10:04:28.717 TRACE 18495 --- [nio-8080-exec-4] o.a.c.i.c.CoreTypeConverterRegistry : Finding type converter to convert java.lang.String -> java.lang.Integer with value: 1
2021-07-08 10:04:28.717 TRACE 18495 --- [nio-8080-exec-5] o.a.c.i.c.CoreTypeConverterRegistry : Using bulk converter: CamelBaseBulkConverterLoader to convert [class java.lang.String=>class java.lang.Integer]
2021-07-08 10:04:28.717 TRACE 18495 --- [nio-8080-exec-4] o.a.c.i.c.CoreTypeConverterRegistry : Using bulk converter: CamelBaseBulkConverterLoader to convert [class java.lang.String=>class java.lang.Integer]
2021-07-08 10:04:28.718 TRACE 18495 --- [nio-8080-exec-4] o.a.c.i.engine.DefaultReactiveExecutor : Schedule [first=true, main=true, sync=false]: LoopState
2021-07-08 10:04:28.718 TRACE 18495 --- [nio-8080-exec-5] o.a.c.i.engine.DefaultReactiveExecutor : Schedule [first=true, main=true, sync=false]: LoopState
2021-07-08 10:04:28.718 TRACE 18495 --- [nio-8080-exec-4] o.a.c.i.engine.DefaultReactiveExecutor : Queuing reactive work: LoopState
2021-07-08 10:04:28.718 TRACE 18495 --- [nio-8080-exec-5] o.a.c.i.engine.DefaultReactiveExecutor : Queuing reactive work: LoopState
2021-07-08 10:04:28.718 TRACE 18495 --- [nio-8080-exec-4] o.a.c.i.engine.DefaultReactiveExecutor : Worker #4 running: org.apache.camel.processor.Pipeline$PipelineTask@3a83e1b8
2021-07-08 10:04:28.718 TRACE 18495 --- [nio-8080-exec-5] o.a.c.i.engine.DefaultReactiveExecutor : Worker #5 running: org.apache.camel.processor.Pipeline$PipelineTask@74d4d21
2021-07-08 10:04:28.718 DEBUG 18495 --- [nio-8080-exec-4] o.apache.camel.processor.LoopProcessor : LoopProcessor: iteration #0
2021-07-08 10:04:28.718 DEBUG 18495 --- [nio-8080-exec-5] o.apache.camel.processor.LoopProcessor : LoopProcessor: iteration #0
2021-07-08 10:04:28.718 TRACE 18495 --- [nio-8080-exec-4] o.a.c.i.engine.CamelInternalProcessor : Processing exchange for exchangeId: 0FBD82C2E690DA5-0000000000000017 -> Exchange[0FBD82C2E690DA5-0000000000000017]
2021-07-08 10:04:28.718 TRACE 18495 --- [nio-8080-exec-4] o.a.c.i.engine.DefaultReactiveExecutor : Schedule [first=true, main=true, sync=false]: SimpleTask
2021-07-08 10:04:28.718 TRACE 18495 --- [nio-8080-exec-4] o.a.c.i.engine.DefaultReactiveExecutor : Queuing reactive work: SimpleTask
2021-07-08 10:04:28.718 TRACE 18495 --- [nio-8080-exec-5] o.a.c.i.engine.CamelInternalProcessor : Processing exchange for exchangeId: 0FBD82C2E690DA5-0000000000000017 -> Exchange[0FBD82C2E690DA5-0000000000000017]
{code}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)