Some Eclipse Foundation services are deprecated, or will be soon. Please ensure you've read this important communication.

Bug 345678

Summary: [zoodiscovery][examples] hello example consumer sometimes throws BundleStateException
Product: [RT] ECF Reporter: Scott Lewis <slewis>
Component: ecf.discoveryAssignee: Wim Jongman <wim.jongman>
Status: RESOLVED FIXED QA Contact:
Severity: major    
Priority: P3 CC: ahmed.aadel, bugs.eclipse.org, wim.jongman
Version: unspecified   
Target Milestone: 3.5.2   
Hardware: PC   
OS: Windows XP   
Whiteboard:
Attachments:
Description Flags
revised DiscoveryActivator class for org.eclipse.ecf.provider.zookeeper provider none

Description Scott Lewis CLA 2011-05-12 19:11:53 EDT
When running the ECF Hello world example remote service consumer product, I sometimes get this exception

!ENTRY org.eclipse.osgi 2 0 2011-05-12 15:51:50.094
!MESSAGE While loading class "org.eclipse.ecf.core.AbstractContainer", thread "Thread[Thread-2,5,main]" timed out waiting (5000ms) for thread "Thread[app thread - org.eclipse.ecf.examples.remoteservices.hello.consumer.HelloConsumer.0,5,main]" to finish starting bundle "org.eclipse.ecf_3.1.0.v20100906-1425 [4]". To avoid deadlock, thread "Thread[Thread-2,5,main]" is proceeding but "org.eclipse.ecf.core.AbstractContainer" may not be fully initialized.
!STACK 0
org.osgi.framework.BundleException: State change in progress for bundle "initial@reference:file:plugins/org.eclipse.ecf_3.1.0.v20100906-1425.jar/" by thread "app thread - org.eclipse.ecf.examples.remoteservices.hello.consumer.HelloConsumer.0".
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.beginStateChange(AbstractBundle.java:1087)
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.java:297)
	at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:440)
	at org.eclipse.osgi.internal.loader.BundleLoader.setLazyTrigger(BundleLoader.java:268)
	at org.eclipse.core.runtime.internal.adaptor.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:107)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:460)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:216)
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:400)
	at org.eclipse.osgi.internal.loader.SingleSourcePackage.loadClass(SingleSourcePackage.java:35)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:473)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:429)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:417)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:107)
	at java.lang.ClassLoader.loadClass(Unknown Source)
	at java.lang.ClassLoader.loadClassInternal(Unknown Source)
	at java.lang.ClassLoader.defineClass1(Native Method)
	at java.lang.ClassLoader.defineClass(Unknown Source)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.defineClass(DefaultClassLoader.java:188)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.defineClass(ClasspathManager.java:589)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findClassImpl(ClasspathManager.java:557)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClassImpl(ClasspathManager.java:488)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass_LockClassLoader(ClasspathManager.java:476)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:456)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:216)
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:400)
	at org.eclipse.osgi.internal.loader.SingleSourcePackage.loadClass(SingleSourcePackage.java:35)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:473)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:429)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:417)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:107)
	at java.lang.ClassLoader.loadClass(Unknown Source)
	at java.lang.ClassLoader.loadClassInternal(Unknown Source)
	at java.lang.ClassLoader.defineClass1(Native Method)
	at java.lang.ClassLoader.defineClass(Unknown Source)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.defineClass(DefaultClassLoader.java:188)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.defineClass(ClasspathManager.java:589)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findClassImpl(ClasspathManager.java:557)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClassImpl(ClasspathManager.java:488)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass_LockClassLoader(ClasspathManager.java:476)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:456)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:216)
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:400)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:476)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:429)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:417)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:107)
	at java.lang.ClassLoader.loadClass(Unknown Source)
	at java.lang.ClassLoader.loadClassInternal(Unknown Source)
	at org.eclipse.ecf.provider.zookeeper.DiscoveryActivator.startup(DiscoveryActivator.java:63)
	at org.eclipse.ecf.provider.zookeeper.DiscoveryActivator.access$0(DiscoveryActivator.java:50)
	at org.eclipse.ecf.provider.zookeeper.DiscoveryActivator$1.run(DiscoveryActivator.java:45)
	at java.lang.Thread.run(Unknown Source)
Caused by: org.eclipse.osgi.framework.internal.core.AbstractBundle$BundleStatusException
	... 52 more
Root exception:
org.eclipse.osgi.framework.internal.core.AbstractBundle$BundleStatusException
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.beginStateChange(AbstractBundle.java:1087)
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.java:297)
	at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:440)
	at org.eclipse.osgi.internal.loader.BundleLoader.setLazyTrigger(BundleLoader.java:268)
	at org.eclipse.core.runtime.internal.adaptor.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:107)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:460)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:216)
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:400)
	at org.eclipse.osgi.internal.loader.SingleSourcePackage.loadClass(SingleSourcePackage.java:35)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:473)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:429)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:417)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:107)
	at java.lang.ClassLoader.loadClass(Unknown Source)
	at java.lang.ClassLoader.loadClassInternal(Unknown Source)
	at java.lang.ClassLoader.defineClass1(Native Method)
	at java.lang.ClassLoader.defineClass(Unknown Source)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.defineClass(DefaultClassLoader.java:188)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.defineClass(ClasspathManager.java:589)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findClassImpl(ClasspathManager.java:557)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClassImpl(ClasspathManager.java:488)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass_LockClassLoader(ClasspathManager.java:476)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:456)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:216)
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:400)
	at org.eclipse.osgi.internal.loader.SingleSourcePackage.loadClass(SingleSourcePackage.java:35)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:473)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:429)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:417)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:107)
	at java.lang.ClassLoader.loadClass(Unknown Source)
	at java.lang.ClassLoader.loadClassInternal(Unknown Source)
	at java.lang.ClassLoader.defineClass1(Native Method)
	at java.lang.ClassLoader.defineClass(Unknown Source)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.defineClass(DefaultClassLoader.java:188)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.defineClass(ClasspathManager.java:589)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findClassImpl(ClasspathManager.java:557)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClassImpl(ClasspathManager.java:488)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass_LockClassLoader(ClasspathManager.java:476)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:456)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:216)
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:400)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:476)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:429)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:417)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:107)
	at java.lang.ClassLoader.loadClass(Unknown Source)
	at java.lang.ClassLoader.loadClassInternal(Unknown Source)
	at org.eclipse.ecf.provider.zookeeper.DiscoveryActivator.startup(DiscoveryActivator.java:63)
	at org.eclipse.ecf.provider.zookeeper.DiscoveryActivator.access$0(DiscoveryActivator.java:50)
	at org.eclipse.ecf.provider.zookeeper.DiscoveryActivator$1.run(DiscoveryActivator.java:45)
	at java.lang.Thread.run(Unknown Source)


The issue appears to be that the classloading of some of the core ECF classes (upon which zoodiscovery provider depends) hasn't completed by the time that the IDiscoveryLocator service registration occurs inside the Zoodiscovery start-created thread.

Unfortunately, this doesn't occur consistently (i.e. sometimes it does not occur).
Comment 1 Scott Lewis CLA 2011-06-06 22:02:50 EDT
Created attachment 197473 [details]
revised DiscoveryActivator class for org.eclipse.ecf.provider.zookeeper provider

This attachment provides a revised implementation of the DiscoveryActivator for zookeeper provider.  In the old DiscoveryActivator, a new Thread was created in start(BundleContext) method, and that thread called the DiscoveryActivator.startup method asynchronously (in new thread).  I believe that the timing of the execution of this thread could be problematic, and lead to the BundleStatusException reported by this bug (or other exceptions).

The attached DiscoveryActivator uses a ServiceFactory to delay the creation of ZooDiscoveryContainer.getSingleton() method, which loads a number of classes and creates the ZooDiscoveryContainer instance...without using a separate thread to do so asynchronously.  This seems safer, as the ServiceFactory registration will complete without BundleStatusExceptions.

I've tested this fix with the zoodiscovery and r-osgi distribution provider.  Please review, test and if the fix is acceptable to the zookeeper provider authors, then please commit and release to master.  Thanks.
Comment 2 Wim Jongman CLA 2011-06-07 03:36:10 EDT
Adding Ahmed and myself.
Comment 3 Wim Jongman CLA 2011-06-07 13:02:01 EDT
Thanks Scott for the patch. I have updated the code and commited to master. The patch is currently compiling. After this is done I will consume the new zoodiscovery in our own product to test.
Comment 4 Scott Lewis CLA 2011-06-07 15:17:39 EDT
Added milestone 3.5.2 and added it as target milestone for this bug
Comment 5 Wim Jongman CLA 2011-06-08 03:51:30 EDT
I have implemented the code but bucky aborts the build because of a time-out. It seems that the discovery tests run for a long period of time [1]. This is different from the last successful build [2] where these tests took a few seconds.

Last build completed normally btw but tests take so long that they come close to the alotted build time of 15 minutes.

[1] https://build.ecf-project.org/jenkins/job/C-HEAD-discovery.zookeeper.feature/143/console
[2] https://build.ecf-project.org/jenkins/job/C-HEAD-discovery.zookeeper.feature/123/console


CURRENT TIMES:
------------------------------------------------------------------------
testAddServiceListenerIServiceTypeIDIServiceListenerOSGi...   ...OK [40.023s]
testAddServiceListenerIServiceTypeIDIServiceListenerOSGiWildcards...   ...OK [39.965s]
ZooDiscoveryServiceTest.testAddServiceTypeListenerOSGi... ...OK [40.07s]
ZooDiscoveryServiceTest.testAddServiceListenerIServiceListener...   ...OK [39.953s]
etc ..
INFO:    ...OK [40.016s]
INFO:    ...OK [39.958s]
INFO:    ...OK [39.014s]
INFO:    ...OK [38.966s]
INFO:    ...OK [39.016s]
INFO:    ...OK [38.983s]
INFO:    ...OK [38.966s]
INFO:    ...OK [39.004s]
INFO:    ...OK [38.961s]
INFO:    ...OK [39.007s]

INFO:  Running test org.eclipse.ecf.tests.provider.zookeeper.ZooDiscoveryServiceTest.testAddServiceListenerIServiceListenerOSGi...
Build timed out (after 15 minutes). Marking the build as aborted.
FATAL: java.lang.InterruptedException
java.lang.RuntimeException: java.lang.InterruptedException
		 at hudson.plugins.buckminster.EclipseBuckminsterBuilder.perform(EclipseBuckminsterBuilder.java:265)
		 at hudson.plugins.templateproject.ProxyBuilder.perform(ProxyBuilder.java:83)
		 at hudson.tasks.BuildStepMonitor$1.perform(BuildStepMonitor.java:19)
		 at hudson.model.AbstractBuild$AbstractRunner.perform(AbstractBuild.java:663)
		 at hudson.model.Build$RunnerImpl.build(Build.java:177)
		 at hudson.model.Build$RunnerImpl.doRun(Build.java:139)
		 at hudson.model.AbstractBuild$AbstractRunner.run(AbstractBuild.java:429)
		 at hudson.model.Run.run(Run.java:1375)
		 at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:46)
		 at hudson.model.ResourceController.execute(ResourceController.java:88)
		 at hudson.model.Executor.run(Executor.java:145)
Caused by: java.lang.InterruptedException
		 at java.lang.Object.wait(Native Method)
		 at java.lang.Object.wait(Object.java:485)
		 at java.lang.UNIXProcess.waitFor(UNIXProcess.java:165)
		 at hudson.Proc$LocalProc.join(Proc.java:319)
		 at hudson.plugins.buckminster.EclipseBuckminsterBuilder.perform(EclipseBuckminsterBuilder.java:261)
		 ... 10 more
Comment 6 Markus Kuppe CLA 2011-06-08 03:56:56 EDT
I have increased the build time to 30 minutes and the tests finish successfully. The reason for the long test run is, that the default timeout is configured to be high. We might wanna change this in the tests.
Comment 7 Wim Jongman CLA 2011-06-08 17:31:02 EDT
I have downloaded the latest zookeeper and it seems to be working fine, without any visible delays. This test is not extensive since it is hard for me to consume a development build ECF in our official build.

However, I have updated to the latest ECF in my Eclipse and the local launch seems to work fine.

TBC
Comment 8 Scott Lewis CLA 2011-08-03 20:21:17 EDT
This bug seems to be fixed by the fix released as described in comment 3.  Resolving as fixed.