[CAMEL-16794] camel-core - race condition in LoopProcessor

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 3.8.0, 3.11.0
• Fix Version/s: 3.11.1, 3.12.0
• Component/s: came-core, eip
• Estimated Complexity: Unknown
• Assignee: Unassigned
• Reporter: Sergio Penkale
• Created: 08/Jul/21 10:36
• Updated: 08/Jul/21 14:23
• Resolved: 08/Jul/21 14:23

Description

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:

from("servlet:test")
    .log("test.exchangeId=${exchangeId}")
    .loop(1)
        .log("loop.exchangeId=${exchangeId}")
.end();

When testing with the following the client times out:

ab -n1000 -c 2 http://localhost:8080/camel/test

 

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:

state = new LoopState(exchange, callback);

if (exchange.isTransacted()) {
   reactiveExecutor.scheduleSync(state);
} else {
   reactiveExecutor.scheduleMain(state);
}

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]

 

Issue Links

• links to: GitHub Pull Request #5813