Intermittent failure of CamelDevModeTest

[jamesnetherton]

Seems CamelMainEventBridge fires events after Quarkus is shutdown and thus the Arc container is null. Hence IllegalArgumentException is thrown here.

[INFO] Running org.apache.camel.quarkus.main.CamelDevModeTest
2020-07-09 15:38:44,916 INFO  [org.apa.cam.qua.mai.dep.CamelMainHotDeploymentProcessor] (build-15) HotDeployment files (camel.main.xml-routes):
2020-07-09 15:38:44,916 INFO  [org.apa.cam.qua.mai.dep.CamelMainHotDeploymentProcessor] (build-15) - /tmp/camel-devmode-9461026744410861234/routes.xml
2020-07-09 15:38:46,104 INFO  [org.apa.cam.qua.cor.CamelBootstrapRecorder] (Quarkus Main Thread) bootstrap runtime: org.apache.camel.quarkus.main.CamelMainRuntime
2020-07-09 15:38:46,136 INFO  [org.apa.cam.mai.BaseMainSupport] (Quarkus Main Thread) Auto-configuration summary:
2020-07-09 15:38:46,137 INFO  [org.apa.cam.mai.BaseMainSupport] (Quarkus Main Thread) 	camel.main.xmlRoutes=file:/tmp/camel-devmode-9461026744410861234/routes.xml
2020-07-09 15:38:46,139 INFO  [org.apa.cam.qua.mai.CamelMainRoutesCollector] (Quarkus Main Thread) Loading additional Camel XML routes from: file:/tmp/camel-devmode-9461026744410861234/routes.xml
2020-07-09 15:38:46,247 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-1) is starting
2020-07-09 15:38:46,249 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) StreamCaching is not in use. If using streams then its recommended to enable stream caching. See more details at http://camel.apache.org/stream-caching.html
2020-07-09 15:38:46,253 INFO  [org.apa.cam.imp.eng.InternalRouteStartupManager] (Quarkus Main Thread) Route: r1 started and consuming from: direct://start
2020-07-09 15:38:46,255 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Total 1 routes, of which 1 are started
2020-07-09 15:38:46,255 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-1) started in 0.007 seconds
2020-07-09 15:38:46,341 INFO  [io.quarkus] (Quarkus Main Thread) Quarkus 1.6.0.Final on JVM started in 2.007s. Listening on: http://0.0.0.0:8080
2020-07-09 15:38:46,341 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2020-07-09 15:38:46,341 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [camel-core, camel-direct, camel-log, camel-main, camel-policy, camel-support-common, camel-timer, camel-xml-io, cdi, resteasy, resteasy-jsonb]
2020-07-09 15:38:48,400 INFO  [io.qua.dep.dev.RuntimeUpdatesProcessor] (Timer-0) File change detected: /tmp/camel-devmode-9461026744410861234/routes.xml
2020-07-09 15:38:48,403 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-1) is shutting down
2020-07-09 15:38:48,408 INFO  [org.apa.cam.mai.MainLifecycleStrategy] (Quarkus Main Thread) CamelContext: camel-1 has been shutdown, triggering shutdown of the JVM.
2020-07-09 15:38:48,410 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-1) uptime 2.161 seconds
2020-07-09 15:38:48,410 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-1) is shutdown in 0.007 seconds
2020-07-09 15:38:48,442 INFO  [io.qua.dep.dev.RuntimeUpdatesProcessor] (vert.x-worker-thread-2) File change detected: /tmp/camel-devmode-9461026744410861234/routes.xml
2020-07-09 15:38:48,457 INFO  [io.quarkus] (Quarkus Main Thread) Quarkus stopped in 0.055s
2020-07-09 15:38:48,555 INFO  [org.apa.cam.qua.mai.dep.CamelMainHotDeploymentProcessor] (build-24) HotDeployment files (camel.main.xml-routes):
2020-07-09 15:38:48,555 INFO  [org.apa.cam.qua.mai.dep.CamelMainHotDeploymentProcessor] (build-24) - /tmp/camel-devmode-9461026744410861234/routes.xml
2020-07-09 15:38:48,828 INFO  [org.apa.cam.qua.cor.CamelBootstrapRecorder] (Quarkus Main Thread) bootstrap runtime: org.apache.camel.quarkus.main.CamelMainRuntime
2020-07-09 15:38:48,837 INFO  [org.apa.cam.mai.BaseMainSupport] (Quarkus Main Thread) Auto-configuration summary:
2020-07-09 15:38:48,837 INFO  [org.apa.cam.mai.BaseMainSupport] (Quarkus Main Thread) 	camel.main.xmlRoutes=file:/tmp/camel-devmode-9461026744410861234/routes.xml
2020-07-09 15:38:48,838 INFO  [org.apa.cam.qua.mai.CamelMainRoutesCollector] (Quarkus Main Thread) Loading additional Camel XML routes from: file:/tmp/camel-devmode-9461026744410861234/routes.xml
2020-07-09 15:38:48,840 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-2) is starting
2020-07-09 15:38:48,841 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) StreamCaching is not in use. If using streams then its recommended to enable stream caching. See more details at http://camel.apache.org/stream-caching.html
2020-07-09 15:38:48,841 INFO  [org.apa.cam.imp.eng.InternalRouteStartupManager] (Quarkus Main Thread) Route: r2 started and consuming from: direct://start
2020-07-09 15:38:48,842 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Total 1 routes, of which 1 are started
2020-07-09 15:38:48,842 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-2) started in 0.002 seconds
2020-07-09 15:38:48,856 INFO  [io.quarkus] (Quarkus Main Thread) Quarkus 1.6.0.Final on JVM started in 0.391s. Listening on: http://0.0.0.0:8080
2020-07-09 15:38:48,856 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2020-07-09 15:38:48,857 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [camel-core, camel-direct, camel-log, camel-main, camel-policy, camel-support-common, camel-timer, camel-xml-io, cdi, resteasy, resteasy-jsonb]
2020-07-09 15:38:48,857 INFO  [io.qua.dep.dev.RuntimeUpdatesProcessor] (Timer-0) Hot replace total time: 0.457s 
2020-07-09 15:38:48,857 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-2) is shutting down
2020-07-09 15:38:48,859 INFO  [org.apa.cam.mai.MainLifecycleStrategy] (Quarkus Main Thread) CamelContext: camel-2 has been shutdown, triggering shutdown of the JVM.
2020-07-09 15:38:48,859 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-2) uptime 0.019 seconds
2020-07-09 15:38:48,860 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-2) is shutdown in 0.003 seconds
2020-07-09 15:38:48,860 INFO  [io.quarkus] (Quarkus Main Thread) Quarkus stopped in 0.003s
2020-07-09 15:38:48,861 ERROR [org.apa.cam.qua.mai.CamelMainRuntime] (Thread-265) Failed to start application: java.lang.IllegalArgumentException
	at io.quarkus.arc.impl.ArcContainerImpl.unwrap(ArcContainerImpl.java:697)
	at io.quarkus.arc.impl.EventImpl.createNotifier(EventImpl.java:138)
	at java.base/java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1705)
	at io.quarkus.arc.impl.EventImpl.getNotifier(EventImpl.java:112)
	at io.quarkus.arc.impl.EventImpl.fire(EventImpl.java:69)
	at org.apache.camel.quarkus.main.CamelMainEventBridge.fireEvent(CamelMainEventBridge.java:89)
	at org.apache.camel.quarkus.main.CamelMainEventBridge.afterStop(CamelMainEventBridge.java:85)
	at org.apache.camel.main.MainSupport.afterStop(MainSupport.java:118)
	at org.apache.camel.quarkus.main.CamelMain.runEngine(CamelMain.java:138)
	at org.apache.camel.quarkus.main.CamelMainRuntime.lambda$start$0(CamelMainRuntime.java:50)
	at java.base/java.lang.Thread.run(Thread.java:834)

2020-07-09 15:38:48,944 INFO  [org.apa.cam.qua.mai.dep.CamelMainHotDeploymentProcessor] (build-12) HotDeployment files (camel.main.xml-routes):
2020-07-09 15:38:48,944 INFO  [org.apa.cam.qua.mai.dep.CamelMainHotDeploymentProcessor] (build-12) - /tmp/camel-devmode-9461026744410861234/routes.xml
2020-07-09 15:38:49,207 INFO  [org.apa.cam.qua.cor.CamelBootstrapRecorder] (Quarkus Main Thread) bootstrap runtime: org.apache.camel.quarkus.main.CamelMainRuntime
2020-07-09 15:38:49,216 INFO  [org.apa.cam.mai.BaseMainSupport] (Quarkus Main Thread) Auto-configuration summary:
2020-07-09 15:38:49,216 INFO  [org.apa.cam.mai.BaseMainSupport] (Quarkus Main Thread) 	camel.main.xmlRoutes=file:/tmp/camel-devmode-9461026744410861234/routes.xml
2020-07-09 15:38:49,216 INFO  [org.apa.cam.qua.mai.CamelMainRoutesCollector] (Quarkus Main Thread) Loading additional Camel XML routes from: file:/tmp/camel-devmode-9461026744410861234/routes.xml
2020-07-09 15:38:49,219 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-3) is starting
2020-07-09 15:38:49,220 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) StreamCaching is not in use. If using streams then its recommended to enable stream caching. See more details at http://camel.apache.org/stream-caching.html
2020-07-09 15:38:49,221 INFO  [org.apa.cam.imp.eng.InternalRouteStartupManager] (Quarkus Main Thread) Route: r2 started and consuming from: direct://start
2020-07-09 15:38:49,222 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Total 1 routes, of which 1 are started
2020-07-09 15:38:49,222 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-3) started in 0.002 seconds
2020-07-09 15:38:49,224 INFO  [io.quarkus] (Quarkus Main Thread) Quarkus 1.6.0.Final on JVM started in 0.358s. Listening on: http://0.0.0.0:8080
2020-07-09 15:38:49,225 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2020-07-09 15:38:49,225 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [camel-core, camel-direct, camel-log, camel-main, camel-policy, camel-support-common, camel-timer, camel-xml-io, cdi, resteasy, resteasy-jsonb]
2020-07-09 15:38:49,226 INFO  [io.qua.dep.dev.RuntimeUpdatesProcessor] (vert.x-worker-thread-2) Hot replace total time: 0.785s 
2020-07-09 15:38:49,252 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-3) is shutting down
2020-07-09 15:38:49,254 INFO  [org.apa.cam.mai.MainLifecycleStrategy] (Quarkus Main Thread) CamelContext: camel-3 has been shutdown, triggering shutdown of the JVM.
2020-07-09 15:38:49,255 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-3) uptime 0.034 seconds
2020-07-09 15:38:49,255 INFO  [org.apa.cam.imp.eng.AbstractCamelContext] (Quarkus Main Thread) Apache Camel 3.4.0 (camel-3) is shutdown in 0.003 seconds
2020-07-09 15:38:49,255 INFO  [io.quarkus] (Quarkus Main Thread) Quarkus stopped in 0.003s
Exception in thread "Thread-289" java.lang.RuntimeException: java.lang.IllegalArgumentException
	at org.apache.camel.quarkus.main.CamelMainRuntime.lambda$start$0(CamelMainRuntime.java:54)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: java.lang.IllegalArgumentException
	at io.quarkus.arc.impl.ArcContainerImpl.unwrap(ArcContainerImpl.java:697)
	at io.quarkus.arc.impl.EventImpl.createNotifier(EventImpl.java:138)
	at java.base/java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1705)
	at io.quarkus.arc.impl.EventImpl.getNotifier(EventImpl.java:112)
	at io.quarkus.arc.impl.EventImpl.fire(EventImpl.java:69)
	at org.apache.camel.quarkus.main.CamelMainEventBridge.fireEvent(CamelMainEventBridge.java:89)
	at org.apache.camel.quarkus.main.CamelMainEventBridge.afterStop(CamelMainEventBridge.java:85)
	at org.apache.camel.main.MainSupport.afterStop(MainSupport.java:118)
	at org.apache.camel.quarkus.main.CamelMain.runEngine(CamelMain.java:138)
	at org.apache.camel.quarkus.main.CamelMainRuntime.lambda$start$0(CamelMainRuntime.java:50)
	... 1 more
[ERROR] Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 6.903 s <<< FAILURE! - in org.apache.camel.quarkus.main.CamelDevModeTest
[ERROR] testRoutesDiscovery  Time elapsed: 6.867 s  <<< ERROR!
java.lang.RuntimeException: java.lang.IllegalArgumentException
Caused by: java.lang.IllegalArgumentException

[lburgazzoli]

guess we need to guard against the getEvent returning null here:

• https://github.com/apache/camel-quarkus/blob/master/extensions-core/main/runtime/src/main/java/org/apache/camel/quarkus/main/CamelMainEventBridge.java#L89
• https://github.com/apache/camel-quarkus/blob/master/extensions-core/core/runtime/src/main/java/org/apache/camel/quarkus/core/CamelManagementEventBridge.java#L41

[jamesnetherton]

Seems to be a race condition. Even with the guard it still fails occasionally. The Arc container must be getting nullified between firing the event and the Quarkus bits doing the createNotifier stuff.

[jamesnetherton]

I don't think this is fully fixed. I still see the occasional failure locally and the nightly quarkus-master sync job failed:

https://github.com/apache/camel-quarkus/runs/875865498

[ppalaga]

Do you happen to have a stack trace at hand?

[ppalaga]

One in how many failures do you see locally?

[ppalaga]

I am running i=0; while mvn clean test; do echo "success $i"; i=$((i+1)); done and I am at success 25 without any failure.

[jamesnetherton]

Seems it's the same issue.

Caused by: java.lang.IllegalArgumentException
	at io.quarkus.arc.impl.ArcContainerImpl.unwrap(ArcContainerImpl.java:697)

One in how many failures do you see locally?

I just ran the build and it failed on the first try. The same thing happened yesterday.

Like I said in our chat on Monday, Quarkus shutdown tasks are executed in reverse order to which they were added. The Arc shutdown task is added after Camel's, so it runs first. I'm not sure whether the current solution of awaiting camel shutdown actually helps much, because the Arc container shutdown will already be in progress (I think).

[ppalaga]

Just to make sure: the name of the thread throwing the exception is camel-main?

[jamesnetherton]

Just to make sure: the name of the thread throwing the exception is camel-main?

Yes - seems so.

[lburgazzoli]

we can disable firing the shutdown events till we have a clear solution, there is still an option to register an handler that does not depend on CDI so if that's really needed, we have a workaround

[ppalaga]

The Arc shutdown task is added after Camel's, so it runs first.

There are two shutdown tasks added by io.quarkus.arc.runtime.ArcRecorder:

1. One that calls Arc.shutdown()
2. And one that calls LifecycleEventRunner.fireShutdownEvent()

I can see the following (IMO correct) ordering of the tasks on shutdown:

• LifecycleEventRunner.fireShutdownEvent()
• our CamelRuntime.stop()
• Arc.shutdown()

[ppalaga]

I think I know what is the problem. My fix is flawed. Calling CamelMain.ShutdownStrategy.await(long, TimeUnit) does not wait for finishing CamelMain.[beforeStart()|start()|afterStart()]. Let me think of a better fix.

[lburgazzoli]

@ppalaga as beforeStart()|start()|afterStart() are invoked synchronously as part of Runtime.start(), then it should be completed when the Runtime.start() is completed, isn't it ?

[ppalaga]

Sorry, I meant CamelMain.[beforeStop()|stop()|afterStop()]