Thanks so much..
Give me a little time and I'll create a smaller app to demonstrate what
we're seeing..
I'll reply once I have something available.
On Mon, Aug 28, 2023 at 4:30 PM Otavio Rodolfo Piske <angusyo...@gmail.com>
wrote:
> Hi, I'd like to investigate ... but for that I need a full reproducer. Can
> you provide* one, please?
>
> * Either as a test in the Camel Core code base or one that I can quickly
> clone and run.
>
> Thanks
>
> On Thu, Aug 24, 2023 at 6:54 PM Tim Janusz <tjan...@guidewire.com> wrote:
>
> > Hi all,
> >
> > We're currently trying to upgrade our Camel from 3.20.2, spring boot
> 2.7.12
> > running on Java 11 to spring.boot.version=3.1.2 and camel.version=4.0.0
> > running on Java 17.
> >
> > We are seeing weird behaviour in one of our applications where our SEDA
> > component just 'hangs' after a specific set of interactions involving
> > dynamically adding/removing routes via the dynamicRouter feature.
> >
> > Some notes:
> > - We use SEDA component (where things seem to hang)
> > - flow is basically:
> > initialize camel,
> > process msg1 to create dynamic route and process message on it,
> > process msg2 which deletes route,
> > process msg3 which re-creates route and processes it,
> > process msg4 which deletes route,
> > process msg5 which re-creates route and HANGS at this point
> > - Basically the 2nd time we delete the route and re-create again (which
> > has the same name as before) is when we see the 'hang' for processing
> > (super weird)
> > - This only happens in version 4.x same code works fine in 3.x
> >
> > We're really wondering what could've changed between version 3.x and 4.x
> > that causes this now to hang?
> >
> > I've included some sudo code below with log snippets to help clarify
> >
> > Our main RouteBuilder creates these two
> > from("servlet:dialcommand")
> > .routeId("dialCommandServletRoute")
> > .convertBodyTo(String::class.java)
> > .to("seda:dialcommandqueue?timeout=$commandTimeout")
> > .removeHeader("args")
> >
> >
> >
> >
> from("seda:dialcommandqueue?concurrentConsumers=$concurrentConsumerCount&timeout=$commandTimeout")
> > .setExchangePattern(ExchangePattern.InOut)
> > .routeId("dialcommandprocess")
> > .dynamicRouter { it: Exchange -> dialDynamicRouting(it) }
> >
> > Our dynamic router logic is like this:
> > fun dialDynamicRouting(exchange: Exchange): String? {
> >
> > // when we need to kill a route
> > is KillRoute -> {
> > context.routeController.stopRoute(routeId)
> > context.removeRoute(routeId)
> >
> > exchange.`in`.body = success("OK", exchange.`in`.getHeader("id",
> > String::class.java))
> > return null
> >
> > // when we add a new route dynamically
> > val dialCommandRoute = createDialCommandRoute(routeId, contextId,
> > contextKey, concurrency)
> > // add to camel context
> > context.addRoutes(dialCommandRoute)
> > context.getRoute(routeId).properties["contextId"] = contextId
> > return dialCommandRoute.from
> >
> > The "createDialCommandRoute" logic dynamic router created uses this type
> of
> > code
> > from(from)
> > .routeId(routeId)
> > .process {
> > val message = it.`in`
> > val body = message.body
> > if (body is DialCommand<*>) {
> > body.id = message.getHeader("id", String::class.java) ?:
> > body.standardOptions.id ?: body.id
> > body.configureLogContext()
> > }
> > }.id("[$routeId] prepare command object")
> > .log(LoggingLevel.INFO, "[\${headers.id}] \${body.procName}")
> > .process { it: Exchange -> it.`in`.body = run(it) }
> > }
> >
> > With DEBUG level logging enabled we can see where it hangs is basically
> > right between when it would normally
> > process items off that newly created route.
> >
> > Log Sample 1: Example logs of a valid run where it creates the new route
> > and start processing it
> > 2023-08-22 INFO 54168 --- [ialcommandqueue]
> > c.g.dm.automation.etl.route.Operator : Route
> dialCommandRoute-6fddd8cf
> > does not exist. This command (RecoverUnfinishedOperations) will create
> the
> > route.
> > 2023-08-22 INFO 54168 --- [ialcommandqueue]
> > c.g.dm.automation.etl.route.Operator : Creating route:
> > dialCommandRoute-6fddd8cf
> > 2023-08-22 DEBUG 54168 --- [ialcommandqueue]
> > o.a.c.impl.engine.AbstractCamelContext :
> > seda://dialcommand:6fddd8cf?concurrentConsumers=8&timeout=0 converted to
> > endpoint: seda://dialcommand:6fddd8cf?concurrentConsumers=8&timeout=0 by
> > component: org.apache.camel.component.seda.SedaComponent@4a23350
> > 2023-08-22 DEBUG 54168 --- [ialcommandqueue]
> > o.a.c.i.e.InternalRouteStartupManager : Warming up route id:
> > dialCommandRoute-6fddd8cf having autoStartup=true
> > 2023-08-22 DEBUG 54168 --- [ialcommandqueue]
> > o.a.c.i.e.InternalRouteStartupManager : Route:
> dialCommandRoute-6fddd8cf
> > >>> Route[seda://dialcommand:6fddd8cf?concurrentConsumers=8&timeout=0 ->
> > null]
> > 2023-08-22 DEBUG 54168 --- [ialcommandqueue]
> > o.a.c.i.e.InternalRouteStartupManager : Starting consumer (order:
> 1004)
> > on route: dialCommandRoute-6fddd8cf
> > 2023-08-22 DEBUG 54168 --- [ialcommandqueue]
> > o.a.c.i.e.BaseExecutorServiceManager : Created new ThreadPool for
> > source:
> > Consumer[seda://dialcommand:6fddd8cf?concurrentConsumers=8&timeout=0]
> with
> > name: seda://dialcommand:6fddd8cf?concurrentConsumers=8&timeout=0. ->
> > org.apache.camel.util.concurrent.RejectableThreadPoolExecutor@10881933
> > [Running,
> > pool size = 0, active threads = 0, queued tasks = 0, completed tasks =
> > 0][seda://dialcommand:6fddd8cf?concurrentConsumers=8&timeout=0]
> > 2023-08-22 DEBUG 54168 --- [ialcommandqueue]
> > o.a.c.i.e.InternalRouteStartupManager : Route:
> dialCommandRoute-6fddd8cf
> > started and consuming from: seda://dialcommand:6fddd8cf
> >
> > -- NOTE: this is where we see it now runs our route's process method on
> > different thread
> > 2023-08-22 INFO 54168 --- [ e70c0565-main] dialCommandRoute-6fddd8cf
> > : [e70c0565] dhRecoverUnfinishedOperations
> > 2023-08-22 INFO 54168 --- [ e70c0565-main]
> > c.g.d.a.etl.cli.command.DialCommand : Beginning
> > dhRecoverUnfinishedOperations
> > 2023-08-22 INFO 54168 --- [ e70c0565-main]
> > c.g.d.a.etl.cli.command.DialCommand : Completed
> > dhRecoverUnfinishedOperations
> > 2023-08-22 INFO 54168 --- [ialcommandqueue] dialcommandprocess
> > : [e70c0565] {"id":"e70c0565","status":"OK"}
> >
> > Log Sample 2: Example logs snippet of where it creates the new route but
> > just hangs on us after creation is complete
> > 2023-08-22 INFO 54168 --- [ialcommandqueue]
> > c.g.dm.automation.etl.route.Operator : Route
> dialCommandRoute-6fddd8cf
> > does not exist. This command (RecoverUnfinishedOperations) will create
> the
> > route.
> > 2023-08-22 INFO 54168 --- [ialcommandqueue]
> > c.g.dm.automation.etl.route.Operator : Creating route:
> > dialCommandRoute-6fddd8cf
> > 2023-08-22 DEBUG 54168 --- [ialcommandqueue]
> > o.a.c.impl.engine.AbstractCamelContext :
> > seda://dialcommand:6fddd8cf?concurrentConsumers=8&timeout=0 converted to
> > endpoint: seda://dialcommand:6fddd8cf?concurrentConsumers=8&timeout=0 by
> > component: org.apache.camel.component.seda.SedaComponent@4a23350
> > 2023-08-22 DEBUG 54168 --- [ialcommandqueue]
> > o.a.c.i.e.InternalRouteStartupManager : Warming up route id:
> > dialCommandRoute-6fddd8cf having autoStartup=true
> > 2023-08-22 DEBUG 54168 --- [ialcommandqueue]
> > o.a.c.i.e.InternalRouteStartupManager : Route:
> dialCommandRoute-6fddd8cf
> > >>> Route[seda://dialcommand:6fddd8cf?concurrentConsumers=8&timeout=0 ->
> > null]
> > 2023-08-22 DEBUG 54168 --- [ialcommandqueue]
> > o.a.c.i.e.InternalRouteStartupManager : Starting consumer (order:
> 1005)
> > on route: dialCommandRoute-6fddd8cf
> > 2023-08-22 DEBUG 54168 --- [ialcommandqueue]
> > o.a.c.i.e.BaseExecutorServiceManager : Created new ThreadPool for
> > source:
> > Consumer[seda://dialcommand:6fddd8cf?concurrentConsumers=8&timeout=0]
> with
> > name: seda://dialcommand:6fddd8cf?concurrentConsumers=8&timeout=0. ->
> > org.apache.camel.util.concurrent.RejectableThreadPoolExecutor@5c41c3f8
> > [Running,
> > pool size = 0, active threads = 0, queued tasks = 0, completed tasks =
> > 0][seda://dialcommand:6fddd8cf?concurrentConsumers=8&timeout=0]
> > 2023-08-22 DEBUG 54168 --- [ialcommandqueue]
> > o.a.c.i.e.InternalRouteStartupManager : Route:
> dialCommandRoute-6fddd8cf
> > started and consuming from: seda://dialcommand:6fddd8cf
> > -- NOTE here is where we'd normally see the route thread be running like
> > above but we don't and it just hangs at this point!
> > [ e70c0565-main] dialCommandRoute-6fddd8cf : [e70c0565]
> > dhRecoverUnfinishedOperations (THIS LOG NEVER HAPPENS!!)
> >
> > Additionally, we can also tell that our routes/endpoints are being
> > created/destroyed correctly if we log out context route/endpoint info
> > seda://dialcommandqueue?timeout=0,
> > seda://dialcommandqueue?concurrentConsumers=20&timeout=0,
> > seda://dialcommand:9591ba9e?concurrentConsumers=8&timeout=0 (NEW ENDPOINT
> > EXAMPLE)
> > servlet://dialcommand, direct://defaultCommand
> >
> > Lastly, when it hangs we can see that the SEDA component thinks its up
> and
> > running
> > INFO 59169 --- [ialcommandqueue] c.g.dm.automation.etl.route.Operator
> :
> > ### SEDA info: currQueueSize: 0, endPointSize: 1000, queueSize: 0,
> > queue.remainCapacity: 1000, stoppingOrStopped: false, suspended: false,
> > isRunAllowed: true, isStarted: true, status: Started
> >
> > We're totally stumped at this point as to what could be causing this
> issue?
> >
>
>
> --
> Otavio R. Piske
> http://orpiske.net
>
