I tried running the example, but when I post data to service like this:
curl -X POST -d "--id e70c0565 --dhInitialize"
localhost:8080/camel/dialcommand/ ; curl -X POST -d "--id e70c0565
--dhKill" localhost:8080/camel/dialcommand
If fails with:
{"timestamp":"2023-08-30T16:12:25.880+00:00","status":500,"error":"Internal
Server
Error","path":"/camel/dialcommand/"}{"timestamp":"2023-08-30T16:12:25.909+00:00","status":500,"error":"Internal
Server Error","path":"/camel/dialcommand"}
Full logs: https://pastebin.com/gApaHLvn
Kind regards
On Wed, Aug 30, 2023 at 5:48 PM Otavio Rodolfo Piske <angusyo...@gmail.com>
wrote:
> Thanks Tim. That way is fine for me.
>
> Kind regards
>
> On Tue, Aug 29, 2023 at 10:14 PM Tim Janusz <tjan...@guidewire.com> wrote:
>
>> Otavio,
>>
>> I was able to create a small spring boot web application that demonstrates
>> the issue..
>>
>> Hopefully you can check it out and see what could be possibly wrong.. This
>> app is super slimmed down version of what our real application does but it
>> demonstrates the same issue.
>>
>> I created it in my public github account (see below). Not sure what's the
>> proper way to do this honestly.
>>
>> https://github.com/tjanusz-personal/camelseda/tree/main
>>
>> Hopefully this helps! Thanks in advance for any input you could provide.
>> This issue has us stumped!
>>
>>
>> On Mon, Aug 28, 2023 at 5:19 PM Tim Janusz <tjan...@guidewire.com> wrote:
>>
>> > 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
>> >>
>> >
>>
>
>
> --
> Otavio R. Piske
> http://orpiske.net
>
--
Otavio R. Piske
http://orpiske.net
