[Camel] "BundleContext is no longer valid" error after restarting/reinstalling Camel+Kura quickstart bundle

[hekonsek]

2016-04-21 11:55:30,034 [Camel (camel-4) thread #16 - timer://xmltopic] WARN  o.a.c.c.t.TimerConsumer - Error processing exchange. Exchange[ID-raspberrypi-46944-1461238784533-3-136][Message: org.eclipse.kura.message.KuraPayload@7812fb]. Caused by: [org.apache.camel.ResolveEndpointFailedException - Failed to resolve endpoint: seda://myapp:xmltopic due to: Cannot auto create component: seda]
org.apache.camel.ResolveEndpointFailedException: Failed to resolve endpoint: seda://myapp:xmltopic due to: Cannot auto create component: seda
    at org.apache.camel.impl.DefaultCamelContext.getEndpoint(DefaultCamelContext.java:587)
    at org.apache.camel.impl.DefaultProducerTemplate.resolveMandatoryEndpoint(DefaultProducerTemplate.java:453)
    at org.apache.camel.impl.DefaultProducerTemplate.sendBodyAndHeaders(DefaultProducerTemplate.java:229)
    at org.eclipse.kura.camel.camelcloud.CamelCloudClient.doPublish(CamelCloudClient.java:181)
    at org.eclipse.kura.camel.camelcloud.CamelCloudClient.publish(CamelCloudClient.java:90)
    at org.eclipse.kura.camel.cloud.KuraCloudProducer.process(KuraCloudProducer.java:75)
    at org.apache.camel.util.AsyncProcessorConverterHelper$ProcessorToAsyncProcessorBridge.process(AsyncProcessorConverterHelper.java:61)
    at org.apache.camel.processor.SendProcessor.process(SendProcessor.java:141)
    at org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:77)
    at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:460)
    at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:190)
    at org.apache.camel.processor.Pipeline.process(Pipeline.java:121)
    at org.apache.camel.processor.Pipeline.process(Pipeline.java:83)
    at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:190)
    at org.apache.camel.component.timer.TimerConsumer.sendTimerExchange(TimerConsumer.java:165)
    at org.apache.camel.component.timer.TimerConsumer$1.run(TimerConsumer.java:73)
    at java.util.TimerThread.mainLoop(Timer.java:555)
    at java.util.TimerThread.run(Timer.java:505)
Caused by: org.apache.camel.RuntimeCamelException: Cannot auto create component: seda
    at org.apache.camel.impl.DefaultCamelContext.getComponent(DefaultCamelContext.java:409)
    at org.apache.camel.impl.DefaultCamelContext.getComponent(DefaultCamelContext.java:385)
    at org.apache.camel.impl.DefaultCamelContext.getEndpoint(DefaultCamelContext.java:557)
    ... 17 more
Caused by: java.lang.IllegalStateException: BundleContext is no longer valid
    at org.eclipse.osgi.framework.internal.core.BundleContextImpl.checkValid(BundleContextImpl.java:931)
    at org.eclipse.osgi.framework.internal.core.BundleContextImpl.getServiceReferences(BundleContextImpl.java:498)
    at org.apache.camel.core.osgi.OsgiComponentResolver.getComponent(OsgiComponentResolver.java:70)
    at org.apache.camel.core.osgi.OsgiComponentResolver.resolveComponent(OsgiComponentResolver.java:64)
    at org.apache.camel.impl.DefaultCamelContext.getComponent(DefaultCamelContext.java:398)
    ... 19 more

[hekonsek]

Hi @cdealti

I install our quickstart:

install file:///home/pi/rhiot-kura-camel-1.0.0-SNAPSHOT.jar
start 73

Then I uninstall it:

uninstall 73

Now Camel waits for 5 minutes to give inflight messages chance to be processed. After 5 minutes quickstart bundle is stopped and uninstalled. So far so good :) .

Now I install the same bundle again:

install file:///home/pi/rhiot-kura-camel-1.0.0-SNAPSHOT.jar
start 74

But then I see the exception from the issue description. It looks more like a Equinox issue, then Camel issue for me. Camel seems just to be reporting the fact that bundle I'm starting has invalid context. But I think that Equinox/Kura causes the bundle to be invalid.

What do you think?

[hekonsek]

Can it be somehow related to SRC lifecycle? Any thoughts?

[kartben]

I don't think the problem is with the bundle you are starting, but rather
the previous bundle (#73 in your case). An invalid bundle context
exception is pretty much always a sign that you have some java code
manipulating a stale BundleContext reference.

On Wed, Apr 27, 2016 at 9:47 AM, Henryk Konsek notifications@github.com
wrote:

Can it be somehow related to SRC lifecycle? Anu thoughts?

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub
#125 (comment)

[kartben]

I would check in the log whether the previous CamelRouter component
properly deactivated. My guess is the error is due to the previous timer
still "ticking" within the previous CamelContext.

On Wed, Apr 27, 2016 at 11:31 AM, Benjamin Cabé kartben@gmail.com wrote:

I don't think the problem is with the bundle you are starting, but rather
the previous bundle (#73 in your case). An invalid bundle context
exception is pretty much always a sign that you have some java code
manipulating a stale BundleContext reference.

On Wed, Apr 27, 2016 at 9:47 AM, Henryk Konsek notifications@github.com
wrote:

Can it be somehow related to SRC lifecycle? Anu thoughts?

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub
#125 (comment)

[cdealti]

@hekonsek as @kartben suggested I'd take a look to the unistall of the previous bundle.
For example there is a WARN message in kura.log (see below). Is this expected?

2016-05-09 12:57:10,600 [Thread-20] INFO  o.e.k.c.c.ConfigurableComponentTracker - Removed ConfigurableComponent io.rhiot.quickstarts.kura.camel.GatewayRouter
2016-05-09 12:57:10,608 [Thread-20] INFO  o.a.c.c.o.OsgiDefaultCamelContext - Apache Camel 2.16.0 (CamelContext: camel-1) is shutting down
2016-05-09 12:57:10,616 [Thread-20] INFO  o.a.c.i.DefaultShutdownStrategy - Starting to graceful shutdown 4 routes (timeout 300 seconds)
2016-05-09 12:57:11,241 [Camel (camel-1) thread #4 - ShutdownTask] INFO  o.a.c.i.DefaultShutdownStrategy - Route: myapp:topic shutdown complete, was consuming from: Endpoint[seda://myapp:topic]
2016-05-09 12:57:11,246 [Camel (camel-1) thread #4 - ShutdownTask] INFO  o.a.c.i.DefaultShutdownStrategy - Route: route3 shutdown complete, was consuming from: Endpoint[timer://xmltopic]
2016-05-09 12:58:37,927 [HouseKeeperTask] INFO  o.e.k.c.d.s.HouseKeeperTask - HouseKeeperTask started.
2016-05-09 12:58:37,928 [HouseKeeperTask] INFO  o.e.k.c.d.s.HouseKeeperTask - HouseKeeperTask: Check store...
2016-05-09 12:58:37,936 [HouseKeeperTask] INFO  o.e.k.c.d.s.HouseKeeperTask - HouseKeeperTask: Delete confirmed messages...
2016-05-09 12:58:37,950 [HouseKeeperTask] INFO  o.e.k.c.d.s.HouseKeeperTask - HouseKeeperTask ended.
2016-05-09 13:02:10,632 [Thread-20] WARN  o.a.c.i.DefaultShutdownStrategy - Timeout occurred during graceful shutdown. Forcing the routes to be shutdown now. Notice: some resources may still be running as graceful shutdown did not complete successfully.
2016-05-09 13:02:10,642 [Thread-20] INFO  o.a.c.i.DefaultShutdownStrategy - Graceful shutdown of 4 routes completed in 300 seconds
2016-05-09 13:02:10,729 [Thread-20] INFO  o.a.c.c.o.OsgiDefaultCamelContext - Apache Camel 2.16.0 (CamelContext: camel-1) uptime 18 minutes
2016-05-09 13:02:10,731 [Thread-20] INFO  o.a.c.c.o.OsgiDefaultCamelContext - Apache Camel 2.16.0 (CamelContext: camel-1) is shutdown in 5 minutes
2016-05-09 13:02:10,732 [Camel (camel-1) thread #4 - ShutdownTask] INFO  o.a.c.i.DefaultShutdownStrategy - Starting to graceful shutdown 1 routes (timeout 300 seconds)
2016-05-09 13:02:10,735 [Camel (camel-1) thread #4 - ShutdownTask] WARN  o.a.c.i.DefaultShutdownStrategy - Timeout occurred during graceful shutdown. Forcing the routes to be shutdown now. Notice: some resources may still be running as graceful shutdown did not complete successfully.
2016-05-09 13:02:10,736 [Camel (camel-1) thread #4 - ShutdownTask] INFO  o.a.c.i.DefaultShutdownStrategy - Graceful shutdown of 1 routes completed in 0 seconds
2016-05-09 13:02:10,738 [Camel (camel-1) thread #4 - ShutdownTask] INFO  o.a.c.c.o.OsgiDefaultCamelContext - Route: myapp:topic is stopped, was consuming from: Endpoint[seda://myapp:topic]
2016-05-09 13:02:10,741 [Camel (camel-1) thread #4 - ShutdownTask] INFO  o.a.c.c.o.OsgiDefaultCamelContext - Route: myapp:topic is shutdown and removed, was consuming from: Endpoint[seda://myapp:topic]
2016-05-09 13:02:10,743 [Camel (camel-1) thread #4 - ShutdownTask] INFO  o.a.c.i.DefaultShutdownStrategy - Route: route2 shutdown complete, was consuming from: Endpoint[kura-cloud://myapp/topic]
2016-05-09 13:02:10,745 [Camel (camel-1) thread #4 - ShutdownTask] INFO  o.a.c.i.DefaultShutdownStrategy - Route: route1 shutdown complete, was consuming from: Endpoint[timer://heartbeat]

[cdealti]

@hekonsek I've also tried various uninstall/install of the other camel bundles without success.
In one of these attempts the quickstart DS component remained in the Unstatisfied state due to some strange classloading problem. There must be something nasty here, I've never encountered this problem before.

Is there any cleanup needed by the quickstart component on deactivate?

[cdealti]

@hekonsek Any progress on this?

[hekonsek]

You mean bundles like camel-core? Or camel-core-osgi? There is not cleanup needed, so that would be strange. I will work on this again after PTO.

[ctron]

This seems like a deadlock situation to me which is in the end "resolved" by running into a timeout. Maybe not properly cleaning up by that.

The CamelCloudClient is unsubscribing from topics and for this executing a call on the CamelContext inside a thread the executor of the cloudClientExecutor executor service. Which belongs to the CamelContext.

The other thread is the service itself, calling into the CamelContext, closing it, which is then closing all services, the executor service being one of those services, since it is shut down by using shutdown, waiting for all tasks (including the unsubscribe from above) to complete.

I think it should be sufficient to not use an executor service from Camel, but to simply maintain a plain ExecutorService from newSingleThreadExecutor(), disposing it during the release call.

[hekonsek]

Fixed by Jens pull request.