1 year ago
#69132
Stef
Spring Boot Apache Camel 3.14.0 does not start all beans after ContextRefreshed event
UPDATE: Camel is restarting the context due to a Spring ContextRefreshed event directly at application starta but not all route beans are started. See update below. I've updated the question title.
Spring Boot Camel is shutting down directly after start. I'm using the latest Spring Boot v.2.6.2 and Camel 3.14.0. I've the follwing property set to let Camel run "forever":
camel.springboot.main-run-controller = true
I've a simple xml route that triggers a timer that sends a dummy message to two Java routes using "direct:email" and "direct:sms". Directly after start of the application, a shutdown is initiated. The strange thing is that if I set a break point at one of my Java routes and continue after Camel has been started it works. Probably because the ContextRefreshedEvent has been handled...?
The shutdown seems to be initiated by a ContextRefreshed event
CamelSpringBootApplicationListener.onApplicationEvent(ContextRefreshedEvent event)
which leads to
DefaultModel.addRouteDefinitions(Collection<RouteDefinition> routeDefinitions)
which basically removes the started routes
...
removeRouteDefinitions(list);
for (RouteDefinition r : list) {
for (ModelLifecycleStrategy s : modelLifecycleStrategies) {
s.onAddRouteDefinition(r);
}
this.routeDefinitions.add(r);
}
if (shouldStartRoutes()) {
getCamelContext().adapt(ModelCamelContext.class).startRouteDefinitions(list);
}
and then it tries to start them again. In the mean time, my timer route is trigged and tries to send a message to another route which somehow doesn't exist.
From the log output:
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Started service: Consumer[timer://test-notify?period=2000]
2022-01-19 10:24:15.812 DEBUG 603884 --- [TaskExecutor-14] o.a.c.i.e.InternalRouteStartupManager : Route: timer-notify started and consuming from: timer://test-notify
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.ChildServiceSupport : Starting service: org.apache.camel.impl.engine.RouteService@383f6f10
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: null already started
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: null already started
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: transform1 already started
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: Channel[transform1] already started
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: direct://email already started
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: Channel[direct://email] already started
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: direct://sms already started
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: Channel[direct://sms] already started
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Building service: Route[timer://test-notify?period=2000 -> null]
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Built service: Route[timer://test-notify?period=2000 -> null]
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Initializing service: Route[timer://test-notify?period=2000 -> null]
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Initialized service: Route[timer://test-notify?period=2000 -> null]
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Starting service: Route[timer://test-notify?period=2000 -> null]
2022-01-19 10:24:15.812 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Started service: Route[timer://test-notify?period=2000 -> null]
2022-01-19 10:24:15.813 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.ChildServiceSupport : Service: org.apache.camel.impl.engine.RouteService@383f6f10 started
2022-01-19 10:24:15.813 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.ChildServiceSupport : Service: org.apache.camel.impl.engine.RouteService@383f6f10 already started
2022-01-19 10:24:15.813 DEBUG 603884 --- [TaskExecutor-14] org.apache.camel.main.RoutesConfigurer : Adding routes into CamelContext from RoutesBuilder: Routes: []
2022-01-19 10:24:15.813 DEBUG 603884 --- [TaskExecutor-14] o.a.c.impl.engine.AbstractCamelContext : Adding routes from builder: Routes: []
### ContextRefreshedEvent event comes here
2022-01-19 10:24:15.833 DEBUG 603884 --- [TaskExecutor-14] o.a.c.i.engine.DefaultShutdownStrategy : Starting to graceful shutdown 1 routes (timeout 15 seconds)
2022-01-19 10:24:15.835 DEBUG 603884 --- [TaskExecutor-14] o.a.c.i.e.BaseExecutorServiceManager : Created new ThreadPool for source: org.apache.camel.impl.engine.DefaultShutdownStrategy@2aca8bae with name: ShutdownTask. -> org.apache.camel.util.concurrent.RejectableThreadPoolExecutor@51c23fbb[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0][ShutdownTask]
2022-01-19 10:24:15.837 TRACE 603884 --- [TaskExecutor-14] o.a.c.u.concurrent.CamelThreadFactory : Created thread[Camel (camel-1) thread #2 - ShutdownTask] -> Thread[Camel (camel-1) thread #2 - ShutdownTask,5,main]
2022-01-19 10:24:15.837 DEBUG 603884 --- [ - ShutdownTask] o.a.c.i.engine.DefaultShutdownStrategy : There are 1 routes to shutdown
2022-01-19 10:24:15.837 TRACE 603884 --- [ - ShutdownTask] o.a.c.i.engine.DefaultShutdownStrategy : Shutting down route: timer-notify with options [Default,CompleteCurrentTaskOnly]
2022-01-19 10:24:15.837 TRACE 603884 --- [ - ShutdownTask] o.a.c.i.engine.DefaultShutdownStrategy : Suspending: Consumer[timer://test-notify?period=2000]
2022-01-19 10:24:15.837 TRACE 603884 --- [ - ShutdownTask] o.a.camel.support.service.ServiceHelper : Suspending service Consumer[timer://test-notify?period=2000]
2022-01-19 10:24:15.837 TRACE 603884 --- [ - ShutdownTask] o.a.camel.support.service.BaseService : Suspending service: Consumer[timer://test-notify?period=2000]
2022-01-19 10:24:15.837 TRACE 603884 --- [ - ShutdownTask] o.a.camel.support.service.BaseService : Suspended service: Consumer[timer://test-notify?period=2000]
2022-01-19 10:24:15.837 TRACE 603884 --- [ - ShutdownTask] o.a.c.i.engine.DefaultShutdownStrategy : Suspend complete for: Consumer[timer://test-notify?period=2000]
2022-01-19 10:24:15.838 DEBUG 603884 --- [ - ShutdownTask] o.a.c.i.engine.DefaultShutdownStrategy : Route: timer-notify suspended and shutdown deferred, was consuming from: timer://test-notify
### All routes are shutdown here, log lines removed
2022-01-19 10:24:15.841 INFO 603884 --- [TaskExecutor-14] o.a.c.impl.engine.AbstractCamelContext : Shutdown timer-notify (timer://test-notify)
2022-01-19 10:24:15.841 DEBUG 603884 --- [TaskExecutor-14] o.a.c.impl.engine.AbstractCamelContext : Removing: timer://test-notify?period=2000 which was only in use by route: timer-notify
2022-01-19 10:24:15.842 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: timer://test-notify?period=2000 already stopped
2022-01-19 10:24:15.842 DEBUG 603884 --- [TaskExecutor-14] o.a.c.impl.engine.AbstractCamelContext : Removing: direct://email which was only in use by route: timer-notify
2022-01-19 10:24:15.842 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Stopping service: direct://email
2022-01-19 10:24:15.842 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Stopped: direct://email service
2022-01-19 10:24:15.842 DEBUG 603884 --- [TaskExecutor-14] o.a.c.impl.engine.AbstractCamelContext : Removing: direct://sms which was only in use by route: timer-notify
2022-01-19 10:24:15.842 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Stopping service: direct://sms
2022-01-19 10:24:15.842 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Stopped: direct://sms service
### All routes are then started again, , log lines removed
### The timer is then triggered
2022-01-19 10:24:16.527 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: transform2 already started
2022-01-19 10:24:16.527 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: Channel[transform2] already started
2022-01-19 10:24:16.527 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: direct://email already started
2022-01-19 10:24:16.527 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: Channel[direct://email] already started
2022-01-19 10:24:16.527 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: direct://sms already started
2022-01-19 10:24:16.527 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Service: Channel[direct://sms] already started
2022-01-19 10:24:16.527 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Building service: Route[timer://test-notify?period=2000 -> null]
2022-01-19 10:24:16.527 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Built service: Route[timer://test-notify?period=2000 -> null]
2022-01-19 10:24:16.527 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Initializing service: Route[timer://test-notify?period=2000 -> null]
2022-01-19 10:24:16.527 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Initialized service: Route[timer://test-notify?period=2000 -> null]
2022-01-19 10:24:16.527 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Starting service: Route[timer://test-notify?period=2000 -> null]
2022-01-19 10:24:16.527 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.service.BaseService : Started service: Route[timer://test-notify?period=2000 -> null]
2022-01-19 10:24:16.527 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.ChildServiceSupport : Service: org.apache.camel.impl.engine.RouteService@5365b4d8 started
2022-01-19 10:24:16.527 TRACE 603884 --- [TaskExecutor-14] o.a.camel.support.ChildServiceSupport : Service: org.apache.camel.impl.engine.RouteService@5365b4d8 already started
### and finally
2022-01-19 10:24:17.539 TRACE 603884 --- [r://test-notify] o.a.camel.component.timer.TimerConsumer : Timer test-notify is firing #1 count
2022-01-19 10:24:17.541 TRACE 603884 --- [r://test-notify] o.a.camel.impl.engine.DefaultUnitOfWork : UnitOfWork beforeRoute: timer-notify for ExchangeId: 9014144BACE024E-0000000000000000 with Exchange[9014144BACE024E-0000000000000000]
2022-01-19 10:24:17.541 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.CamelInternalProcessor : Processing exchange for exchangeId: 9014144BACE024E-0000000000000000 -> Exchange[9014144BACE024E-0000000000000000]
2022-01-19 10:24:17.542 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.DefaultReactiveExecutor : Schedule [first=true, main=true, sync=false]: org.apache.camel.processor.Pipeline$PipelineTask@53ca7ede
2022-01-19 10:24:17.542 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.DefaultReactiveExecutor : Worker #1 running: org.apache.camel.processor.Pipeline$PipelineTask@53ca7ede
2022-01-19 10:24:17.542 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.CamelInternalProcessor : Processing exchange for exchangeId: 9014144BACE024E-0000000000000000 -> Exchange[9014144BACE024E-0000000000000000]
2022-01-19 10:24:17.543 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.DefaultReactiveExecutor : Schedule [first=true, main=true, sync=false]: SimpleTask
2022-01-19 10:24:17.543 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.DefaultReactiveExecutor : Queuing reactive work: SimpleTask
2022-01-19 10:24:17.543 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.CamelInternalProcessor : Exchange processed and is continued routed asynchronously for exchangeId: 9014144BACE024E-0000000000000000 -> Exchange[9014144BACE024E-0000000000000000]
2022-01-19 10:24:17.543 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.DefaultReactiveExecutor : Worker #1 running: SimpleTask
2022-01-19 10:24:17.543 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.DefaultReactiveExecutor : Schedule [first=false, main=false, sync=false]: org.apache.camel.impl.engine.CamelInternalProcessor$AsyncAfterTask@7451f6ad
2022-01-19 10:24:17.543 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.DefaultReactiveExecutor : Queuing reactive work: org.apache.camel.impl.engine.CamelInternalProcessor$AsyncAfterTask@7451f6ad
2022-01-19 10:24:17.543 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.DefaultReactiveExecutor : Worker #1 running: org.apache.camel.impl.engine.CamelInternalProcessor$AsyncAfterTask@7451f6ad
2022-01-19 10:24:17.543 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.DefaultReactiveExecutor : Schedule [first=false, main=false, sync=false]: org.apache.camel.processor.Pipeline$PipelineTask@53ca7ede
2022-01-19 10:24:17.543 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.DefaultReactiveExecutor : Queuing reactive work: org.apache.camel.processor.Pipeline$PipelineTask@53ca7ede
2022-01-19 10:24:17.543 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.DefaultReactiveExecutor : Worker #1 running: org.apache.camel.processor.Pipeline$PipelineTask@53ca7ede
2022-01-19 10:24:17.544 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.CamelInternalProcessor : Processing exchange for exchangeId: 9014144BACE024E-0000000000000000 -> Exchange[9014144BACE024E-0000000000000000]
2022-01-19 10:24:17.544 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.DefaultReactiveExecutor : Schedule [first=true, main=true, sync=false]: SimpleTask
2022-01-19 10:24:17.544 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.DefaultReactiveExecutor : Queuing reactive work: SimpleTask
2022-01-19 10:24:17.544 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.CamelInternalProcessor : Exchange processed and is continued routed asynchronously for exchangeId: 9014144BACE024E-0000000000000000 -> Exchange[9014144BACE024E-0000000000000000]
2022-01-19 10:24:17.544 TRACE 603884 --- [r://test-notify] o.a.c.i.engine.DefaultReactiveExecutor : Worker #1 running: SimpleTask
2022-01-19 10:24:17.544 DEBUG 603884 --- [r://test-notify] o.apache.camel.processor.SendProcessor : >>>> direct://email Exchange[9014144BACE024E-0000000000000000]
2022-01-19 10:24:47.557 TRACE 603884 --- [r://test-notify] o.a.c.p.e.RedeliveryErrorHandler : This exchange is not handled or continued so its marked as failed: Exchange[9014144BACE024E-0000000000000000]
2022-01-19 10:24:47.563 ERROR 603884 --- [r://test-notify] o.a.c.p.e.DefaultErrorHandler : Failed delivery for (MessageId: 9014144BACE024E-0000000000000000 on ExchangeId: 9014144BACE024E-0000000000000000). Exhausted after delivery attempt: 1 caught: org.apache.camel.component.direct.DirectConsumerNotAvailableException: No consumers available on endpoint: direct://email. Exchange[9014144BACE024E-0000000000000000]
Message History (complete message history is disabled)
---------------------------------------------------------------------------------------------------------------------------------------
RouteId ProcessorId Processor Elapsed (ms)
[timer-notify ] [timer-notify ] [from[timer://test-notify?period=2000] ] [ 30019]
...
[timer-notify ] [to3 ] [direct:email ] [ 0]
Stacktrace
---------------------------------------------------------------------------------------------------------------------------------------
org.apache.camel.component.direct.DirectConsumerNotAvailableException: No consumers available on endpoint: direct://email. Exchange[9014144BACE024E-0000000000000000]
at org.apache.camel.component.direct.DirectProducer.process(DirectProducer.java:82) ~[camel-direct-3.14.0.jar:3.14.0]
at org.apache.camel.processor.SendProcessor.process(SendProcessor.java:172) ~[camel-core-processor-3.14.0.jar:3.14.0]
UPDATED:
After some testing I found out that the route created by a Spring bean (extended RouteBuilder) is not started UNLESS I also add a delay in the configure method. I did that in a DummyRoute so I have two Spring beans DummyRoute and NotifyRoute. The route-email and route-sms routes are XML files located in the classpath.
Working route 'route-notify' with the DummyRoute delay from the log:
Started Application in 19.312 seconds (JVM running for 22.366)
DummyRoute configure called
Routes startup (total:0 started:0)
Apache Camel 3.14.0 (camel-1) started in 292ms (build:144ms init:125ms start:2
Route: route1 started and consuming from: timer://dummy-timer
NotifyRoute configuration initiated
Route: route-notify started and consuming from: direct://notify
Route: route-email started and consuming from: file:...
Starting to graceful shutdown 1 routes (timeout 15 seconds)
Route: route-email shutdown complete, was consuming from: file:...
Graceful shutdown of 1 routes completed in 4ms
Stopped route-email (file:...
Shutdown route-email (file:...
Route: route-email started and consuming from: file:...
Route: route-sms started and consuming from: file:...
Starting to graceful shutdown 1 routes (timeout 15 seconds)
Route: route-sms shutdown complete, was consuming from: file:...
Graceful shutdown of 1 routes completed in 1ms
Stopped route-sms (file:...)
Shutdown route-sms (file:...)
Route: route-sms started and consuming from: file:...
Not working route 'route-notify' without the DummyRoute delay from the log:
Started Application in 23.566 seconds (JVM running for 27.73
NotifyRoute configuration initiated
Routes startup (total:0 started:0)
Apache Camel 3.14.0 (camel-1) started in 363ms (build:171ms
Route: route-email started and consuming from: file:...
Starting to graceful shutdown 1 routes (timeout 15 seconds)
Route: route-email shutdown complete, was consuming from: fi
Graceful shutdown of 1 routes completed in 17ms
Stopped route-email (file:...
Shutdown route-email (file:...
Route: route-email started and consuming from: file:...
Route: route-sms started and consuming from: file:...
Starting to graceful shutdown 1 routes (timeout 15 seconds)
Route: route-sms shutdown complete, was consuming from: file
Graceful shutdown of 1 routes completed in 1ms
Stopped route-sms (file:...
Shutdown route-sms (file:...
Route: route-sms started and consuming from: file:...
The difference can also be seen at shutdown of the application:
Working case, with the DummyRoute:
Application shutdown requested.
Apache Camel 3.14.0 (camel-1) shutting down (timeout:15s)
Starting to graceful shutdown 4 routes (timeout 15 seconds)
Route: route-sms shutdown complete, was consuming from: file:
Route: route-email shutdown complete, was consuming from: fil
Route: route-notify shutdown complete, was consuming from: di
Route: route1 shutdown complete, was consuming from: timer://
Graceful shutdown of 4 routes completed in 1ms
Routes stopped (total:4 stopped:4)
Stopped route-sms (file:...
Stopped route-email (file:...
Stopped route-notify (direct://notify)
Stopped route1 (timer://dummy-timer)
Apache Camel 3.14.0 (camel-1) shutdown in 18ms (uptime:1m31s)
Not working case, without the DummyRoute:
Application shutdown requested.
Apache Camel 3.14.0 (camel-1) shutting down (timeout:15s)
Starting to graceful shutdown 2 routes (timeout 15 seconds)
Route: route-sms shutdown complete, was consuming from: file:/
Route: route-email shutdown complete, was consuming from: file
Graceful shutdown of 2 routes completed in 1ms
Routes stopped (total:2 stopped:2)
Stopped route-sms (file:...
Stopped route-email (file:...
Shutting down while there are still 1 inflight exchanges.
Apache Camel 3.14.0 (camel-1) shutdown in 23ms (uptime:2m53s)
The DummyRoute is defined as:
@Component
public class DummyRoute extends RouteBuilder {
@Override
public void configure() throws Exception {
log.info("DummyRoute configure called");
Thread.sleep(2000);
from("timer:dummy-timer?period=36000")
.log("==> Timer call")
.end();
}
}
spring-boot
apache-camel
0 Answers
Your Answer