Error while loading components of bundle - Invalid BundleContext

[jstrom]

Hi,

I'm running karaf 2.2.6 on Linux, with a number of bundles utilizing SCR. The bundle in question provides a SCR component (non-factory, immediate=true, config designate set). The bundle is loaded from the deploy/ directory by fileinstall.
Today I dropped a new version of this bundle in the deploy directory, with the same filename. The reaction I expected (and which has been working fine earlier in same setup) was that the existing component instance was deactivated, and a new instance from the new bundle to be activated.
This was partly what happened.. The old component was first deactivated fine, and the new component was initated fine. However, right after the activate() method had done its deed, the following appeared in the log:

2012-04-23 11:21:29,751 | ERROR | usr/karaf/deploy | scr                              | ?                                   ? | 45 - org.apache.felix.scr - 1.6.0 | Error while loading components of bundle our-bundle-name/98
java.lang.IllegalStateException: Invalid BundleContext.
        at org.apache.felix.framework.BundleContextImpl.checkValidity(BundleContextImpl.java:365)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.framework.BundleContextImpl.getService(BundleContextImpl.java:315)[org.apache.felix.framework-3.0.9.jar:]
        at org.osgi.util.tracker.ServiceTracker.addingService(ServiceTracker.java:442)[45:org.apache.felix.scr:1.6.0]
        at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:896)[45:org.apache.felix.scr:1.6.0]
        at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:261)[45:org.apache.felix.scr:1.6.0]
        at org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:184)[45:org.apache.felix.scr:1.6.0]
        at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:339)[45:org.apache.felix.scr:1.6.0]
        at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:273)[45:org.apache.felix.scr:1.6.0]
        at org.apache.felix.scr.impl.BundleComponentActivator.<init>(BundleComponentActivator.java:101)[45:org.apache.felix.scr:1.6.0]
        at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:285)[45:org.apache.felix.scr:1.6.0]
        at org.apache.felix.scr.impl.Activator.bundleChanged(Activator.java:203)[45:org.apache.felix.scr:1.6.0]
        at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:807)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:729)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:610)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:3761)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.framework.Felix.startBundle(Felix.java:1787)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.framework.BundleImpl.start(BundleImpl.java:918)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1232)[6:org.apache.felix.fileinstall:3.2.0]

The component seems to have been started properly though. However, now I tried to do a console osgi:restart on this bundle, just to see if this was an temporary race-problem or similar. The restart yielded the following:

2012-04-23 11:25:00,787 | ERROR | Thread-1332      | our-bundle-name       | ?                                   ? | 98 - our-bundle-name - 1.2.1.0 | [com.our.bundle.component.Class] Cannot register Component
java.lang.IllegalStateException: Invalid BundleContext.
        at org.apache.felix.framework.BundleContextImpl.checkValidity(BundleContextImpl.java:365)
        at org.apache.felix.framework.BundleContextImpl.getBundle(BundleContextImpl.java:92)
        at org.apache.felix.scr.impl.ComponentRegistry.checkComponentName(ComponentRegistry.java:276)
        at org.apache.felix.scr.impl.BundleComponentActivator.loadDescriptor(BundleComponentActivator.java:238)
        at org.apache.felix.scr.impl.BundleComponentActivator.initialize(BundleComponentActivator.java:147)
        at org.apache.felix.scr.impl.BundleComponentActivator.<init>(BundleComponentActivator.java:111)
        at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:285)
        at org.apache.felix.scr.impl.Activator.bundleChanged(Activator.java:203)
        at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:807)
        at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:729)
        at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:610)
        at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:3761)
        at org.apache.felix.framework.Felix.startBundle(Felix.java:1787)
        at org.apache.felix.framework.BundleImpl.start(BundleImpl.java:918)
        at org.apache.felix.framework.BundleImpl.start(BundleImpl.java:905)
        at org.apache.karaf.shell.osgi.RestartBundle.doExecute(RestartBundle.java:31)
        at org.apache.karaf.shell.osgi.BundlesCommand.doExecute(BundlesCommand.java:37)
        at org.apache.karaf.shell.console.OsgiCommandSupport.execute(OsgiCommandSupport.java:38)
        at org.apache.felix.gogo.commands.basic.AbstractCommand.execute(AbstractCommand.java:35)
        at org.apache.felix.gogo.runtime.CommandProxy.execute(CommandProxy.java:78)
        at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:474)
        at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:400)
        at org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)
        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:183)
        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:120)
        at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:89)
        at org.apache.karaf.shell.console.jline.Console.run(Console.java:166)
        at java.lang.Thread.run(Unknown Source)[:1.6.0_29]
        at org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$4.doRun(ShellFactoryImpl.java:142)[14:org.apache.karaf.shell.ssh:2.2.6]
        at org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$4$1.run(ShellFactoryImpl.java:133)
        at java.security.AccessController.doPrivileged(Native Method)[:1.6.0_29]
        at javax.security.auth.Subject.doAs(Unknown Source)[:1.6.0_29]
        at org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$4.run(ShellFactoryImpl.java:131)[14:org.apache.karaf.shell.ssh:2.2.6]

No deactivate of the previous component was seen. However, the activator method of the component was still called. This failed though, since the old component instance had not been torn down properly (the component works with some parts which can only run one at at time in a JRE).

So, it seems like the component started partially the first time, at least the activate() method did it's work. After that though, something failed, and the component was not registered as started (?). Thus when I restarted the bundle later, it did not have anything to stop() before.
I've tried a few other things after this, removing the bundle file, removing the associated configuration file for the component, but nothing seems to kill this run-away component instance.

So, currently my component is running in this instance, without any control possible.. I cannot stop it, and thus not start a new.. At least not without restarting the whole karaf instance. Which I think is required by now, since it has started to fail with java.lang.NoClassDefFoundError errors.. Probably due to classloader issues after bundle restart/removal I guess?

Anyone seen anything similar? Any way to fix this without restarting the whole karaf instance? I'll have to do that this time anyway to get it back to working condition, but would be good to know if it happens again in the future.

Thank you
Johan

[jstrom]

Hi again,

I just got the same problem when doing the same update in a child-instance (we're running the same bundle in multiple instances). Same scenario, the file was replaced with a never version- Somewhat different stack trace though:

2012-04-23 12:21:33,678 | ERROR | elixPackageAdmin | our-package-name       | ?                                   ? | 68 - our-package-name - 1.2.1.0 | [com.our.bundle.component.Class] Cannot register Component
java.lang.IllegalStateException: Invalid BundleContext.
        at org.apache.felix.framework.BundleContextImpl.checkValidity(BundleContextImpl.java:365)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.framework.BundleContextImpl.getBundle(BundleContextImpl.java:92)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.scr.impl.ComponentRegistry.checkComponentName(ComponentRegistry.java:276)[71:org.apache.felix.scr:1.6.0]
        at org.apache.felix.scr.impl.BundleComponentActivator.loadDescriptor(BundleComponentActivator.java:238)[71:org.apache.felix.scr:1.6.0]
        at org.apache.felix.scr.impl.BundleComponentActivator.initialize(BundleComponentActivator.java:147)[71:org.apache.felix.scr:1.6.0]
        at org.apache.felix.scr.impl.BundleComponentActivator.<init>(BundleComponentActivator.java:111)[71:org.apache.felix.scr:1.6.0]
        at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:285)[71:org.apache.felix.scr:1.6.0]
        at org.apache.felix.scr.impl.Activator.bundleChanged(Activator.java:203)[71:org.apache.felix.scr:1.6.0]
        at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:807)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:729)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:610)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:3761)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.framework.Felix.startBundle(Felix.java:1787)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.framework.Felix$RefreshHelper.restart(Felix.java:4534)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.framework.Felix.refreshPackages(Felix.java:3591)[org.apache.felix.framework-3.0.9.jar:]
        at org.apache.felix.framework.PackageAdminImpl.run(PackageAdminImpl.java:363)[org.apache.felix.framework-3.0.9.jar:]
        at java.lang.Thread.run(Unknown Source)[:1.6.0_29]


This time it seems like the deactivate was called fine, and so was the activate call. The activate failed this time though, due to internal problems (which I cannot really determine what it was, our activate exception catcher called an internal cleanup function which ALSO failed. Thus the original problem was never seen..). That is however not related, I think.

Oh, and if anyone wonders why there are two posts on Nabble, I tried there first but Nabble failed to send my post to the mailing-list due to SPF blocks. Reposted directly to list to get it posted here as well.

/Johan

On Apr 23, 2012, at 12:15 , Johan Ström wrote:

> Hi,
>
> I'm running karaf 2.2.6 on Linux, with a number of bundles utilizing SCR. The bundle in question provides a SCR component (non-factory, immediate=true, config designate set). The bundle is loaded from the deploy/ directory by fileinstall.
> Today I dropped a new version of this bundle in the deploy directory, with the same filename. The reaction I expected (and which has been working fine earlier in same setup) was that the existing component instance was deactivated, and a new instance from the new bundle to be activated.
> This was partly what happened.. The old component was first deactivated fine, and the new component was initated fine. However, right after the activate() method had done its deed, the following appeared in the log:
>
> 2012-04-23 11:21:29,751 | ERROR | usr/karaf/deploy | scr                              | ?                                   ? | 45 - org.apache.felix.scr - 1.6.0 | Error while loading components of bundle our-bundle-name/98
> java.lang.IllegalStateException: Invalid BundleContext.
>        at org.apache.felix.framework.BundleContextImpl.checkValidity(BundleContextImpl.java:365)[org.apache.felix.framework-3.0.9.jar:]
>        at org.apache.felix.framework.BundleContextImpl.getService(BundleContextImpl.java:315)[org.apache.felix.framework-3.0.9.jar:]
>        at org.osgi.util.tracker.ServiceTracker.addingService(ServiceTracker.java:442)[45:org.apache.felix.scr:1.6.0]
>        at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:896)[45:org.apache.felix.scr:1.6.0]
>        at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:261)[45:org.apache.felix.scr:1.6.0]
>        at org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:184)[45:org.apache.felix.scr:1.6.0]
>        at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:339)[45:org.apache.felix.scr:1.6.0]
>        at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:273)[45:org.apache.felix.scr:1.6.0]
>        at org.apache.felix.scr.impl.BundleComponentActivator.<init>(BundleComponentActivator.java:101)[45:org.apache.felix.scr:1.6.0]
>        at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:285)[45:org.apache.felix.scr:1.6.0]
>        at org.apache.felix.scr.impl.Activator.bundleChanged(Activator.java:203)[45:org.apache.felix.scr:1.6.0]
>        at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:807)[org.apache.felix.framework-3.0.9.jar:]
>        at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:729)[org.apache.felix.framework-3.0.9.jar:]
>        at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:610)[org.apache.felix.framework-3.0.9.jar:]
>        at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:3761)[org.apache.felix.framework-3.0.9.jar:]
>        at org.apache.felix.framework.Felix.startBundle(Felix.java:1787)[org.apache.felix.framework-3.0.9.jar:]
>        at org.apache.felix.framework.BundleImpl.start(BundleImpl.java:918)[org.apache.felix.framework-3.0.9.jar:]
>        at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1232)[6:org.apache.felix.fileinstall:3.2.0]
>
> The component seems to have been started properly though. However, now I tried to do a console osgi:restart on this bundle, just to see if this was an temporary race-problem or similar. The restart yielded the following:
>
> 2012-04-23 11:25:00,787 | ERROR | Thread-1332      | our-bundle-name       | ?                                   ? | 98 - our-bundle-name - 1.2.1.0 | [com.our.bundle.component.Class] Cannot register Component
> java.lang.IllegalStateException: Invalid BundleContext.
>        at org.apache.felix.framework.BundleContextImpl.checkValidity(BundleContextImpl.java:365)
>        at org.apache.felix.framework.BundleContextImpl.getBundle(BundleContextImpl.java:92)
>        at org.apache.felix.scr.impl.ComponentRegistry.checkComponentName(ComponentRegistry.java:276)
>        at org.apache.felix.scr.impl.BundleComponentActivator.loadDescriptor(BundleComponentActivator.java:238)
>        at org.apache.felix.scr.impl.BundleComponentActivator.initialize(BundleComponentActivator.java:147)
>        at org.apache.felix.scr.impl.BundleComponentActivator.<init>(BundleComponentActivator.java:111)
>        at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:285)
>        at org.apache.felix.scr.impl.Activator.bundleChanged(Activator.java:203)
>        at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:807)
>        at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:729)
>        at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:610)
>        at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:3761)
>        at org.apache.felix.framework.Felix.startBundle(Felix.java:1787)
>        at org.apache.felix.framework.BundleImpl.start(BundleImpl.java:918)
>        at org.apache.felix.framework.BundleImpl.start(BundleImpl.java:905)
>        at org.apache.karaf.shell.osgi.RestartBundle.doExecute(RestartBundle.java:31)
>        at org.apache.karaf.shell.osgi.BundlesCommand.doExecute(BundlesCommand.java:37)
>        at org.apache.karaf.shell.console.OsgiCommandSupport.execute(OsgiCommandSupport.java:38)
>        at org.apache.felix.gogo.commands.basic.AbstractCommand.execute(AbstractCommand.java:35)
>        at org.apache.felix.gogo.runtime.CommandProxy.execute(CommandProxy.java:78)
>        at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:474)
>        at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:400)
>        at org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)
>        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:183)
>        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:120)
>        at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:89)
>        at org.apache.karaf.shell.console.jline.Console.run(Console.java:166)
>        at java.lang.Thread.run(Unknown Source)[:1.6.0_29]
>        at org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$4.doRun(ShellFactoryImpl.java:142)[14:org.apache.karaf.shell.ssh:2.2.6]
>        at org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$4$1.run(ShellFactoryImpl.java:133)
>        at java.security.AccessController.doPrivileged(Native Method)[:1.6.0_29]
>        at javax.security.auth.Subject.doAs(Unknown Source)[:1.6.0_29]
>        at org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$4.run(ShellFactoryImpl.java:131)[14:org.apache.karaf.shell.ssh:2.2.6]
>
> No deactivate of the previous component was seen. However, the activator method of the component was still called. This failed though, since the old component instance had not been torn down properly (the component works with some parts which can only run one at at time in a JRE).
>
> So, it seems like the component started partially the first time, at least the activate() method did it's work. After that though, something failed, and the component was not registered as started (?). Thus when I restarted the bundle later, it did not have anything to stop() before.
> I've tried a few other things after this, removing the bundle file, removing the associated configuration file for the component, but nothing seems to kill this run-away component instance.
>
> So, currently my component is running in this instance, without any control possible.. I cannot stop it, and thus not start a new.. At least not without restarting the whole karaf instance. Which I think is required by now, since it has started to fail with java.lang.NoClassDefFoundError errors.. Probably due to classloader issues after bundle restart/removal I guess?
>
> Anyone seen anything similar? Any way to fix this without restarting the whole karaf instance? I'll have to do that this time anyway to get it back to working condition, but would be good to know if it happens again in the future.
>
> Thank you
> Johan