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

Bug 338043

Summary:	BundleException when persistence bundle refreshed
Product:	[RT] Gemini.JPA	Reporter:	Shaun Smith <shaun.smith>
Component:	Core	Assignee:	Michael Keith <michael.keith>
Status:	RESOLVED FIXED	QA Contact:
Severity:	normal
Priority:	P3	CC:	eduard.bartsch, jan.sievers, krum.tsvetkov
Version:	1.0.0
Target Milestone:	1.0.0 RC2
Hardware:	PC
OS:	Windows XP
Whiteboard:

Description Shaun Smith

2011-02-23 22:22:12 EST

I'm not sure what the cause or full impact of this exception is but it is unexpected.  Below is the console output with debugging turned on.  Note that weaving was enabled. 

One affect may be the failure to publish a EMF service which seems to be due to a timing problem with the JDBC service becoming available after Gemini JPA went looking for it.  This is probably the same problem as Bug 329030.  By stopping o.e.g.jpa bundle and then starting it I was able to get Gemini JPA to reprocess PU bundles and publish the EMF service.


osgi> EclipseLinkProvider starting...
GeminiServicesUtil registering provider service for org.eclipse.persistence.jpa.PersistenceProvider
GeminiServicesUtil successfully registered provider service for org.eclipse.persistence.jpa.PersistenceProvider
GeminiExtender listening
GeminiExtender looking at existing bundles: 
  org.eclipse.osgi_3.7.0.v20101207 [0]
  org.eclipse.gemini.jpa.weaving_1.0.0.M4-incubation [1]
  org.eclipse.gemini.jpa_1.0.0.M4-incubation [2]
  org.eclipse.persistence.antlr_2.3.0.v20110129-r8902 [3]
  javax.persistence_2.0.3.v201010191057 [4]
  osgi.enterprise_4.2.0.201003190513 [5]
  org.eclipse.persistence.jpa_2.3.0.v20110129-r8902 [6]
  org.eclipse.gemini.example.comics.model_1.0.0.qualifier [7]
  org.eclipse.persistence.core_2.3.0.v20110129-r8902 [8]
  org.eclipse.gemini.dbaccess.derby_1.0.0.M1-incubation [9]
  org.apache.derby_10.5.1.1 [10]
  org.eclipse.persistence.asm_2.3.0.v20110129-r8902 [11]
  org.eclipse.gemini.example.comics.client_1.0.0.qualifier [12]
GeminiExtender refreshing packages of bundle  bundle=org.eclipse.gemini.example.comics.model id=7 state=RESOLVED
GeminiExtender refreshing packages of bundle  bundle=org.eclipse.gemini.example.comics.client id=12 state=RESOLVED
EclipseLink Provider started
Extender - bundle event,  bundle=org.eclipse.gemini.jpa, event=STARTED
Extender - bundle event,  bundle=org.eclipse.persistence.antlr, event=STARTING
Extender - bundle event,  bundle=org.eclipse.persistence.antlr, event=STARTED
Extender - bundle event,  bundle=javax.persistence, event=STARTING
Extender - bundle event,  bundle=org.eclipse.gemini.example.comics.client, event=UNRESOLVED
GeminiExtender tryAssigningPersistenceUnitsInBundle:  bundle=org.eclipse.gemini.example.comics.client id=12 state=INSTALLED
Extender - bundle event,  bundle=javax.persistence, event=STARTED
Extender - bundle event,  bundle=osgi.enterprise, event=STARTING
Looking for persistence descriptors in bundle org.eclipse.gemini.example.comics.client
Extender - bundle event,  bundle=osgi.enterprise, event=STARTED
Extender - bundle event,  bundle=org.eclipse.persistence.jpa, event=STARTING
Found persistence descriptors: []
Extender - bundle event,  bundle=org.eclipse.persistence.jpa, event=STARTED
Parsed persistence descriptors: []
Extender - bundle event,  bundle=org.eclipse.gemini.example.comics.model, event=UNRESOLVED
GeminiExtender tryAssigningPersistenceUnitsInBundle:  bundle=org.eclipse.gemini.example.comics.model id=7 state=INSTALLED
Looking for persistence descriptors in bundle org.eclipse.gemini.example.comics.model
Found persistence descriptors: [Descriptor: META-INF/persistence.xml]
Parsing persistence descriptor META-INF/persistence.xml
getDescStream - Looking for descriptor in : null
Finished parsing persistence descriptor bundleentry://7.fwk15020296/META-INF/persistence.xml
Found 1 persistence units
Parsed persistence descriptors: [
PUnit: comics
  --- XML Data ---
  provider: null
  classes: [org.eclipse.gemini.example.comics.model.Series, org.eclipse.gemini.example.comics.model.Publisher, org.eclipse.gemini.example.comics.model.Issue]
  driverClassName: org.apache.derby.jdbc.ClientDriver
  driverUrl: jdbc:derby://localhost:1527/gemini;create=true
  driverUser: app
  driverPassword: app
  --- Runtime Data ---
  bundle: null
  assignedProvider: null
  descriptorInfo: Descriptor: META-INF/persistence.xml
  uniquePackageNames: null
  emfHandler: null
  emfBuilderHandler: null
  DSF tracker: null]
EclipseProvider assignPersistenceUnitsInBundle: org.eclipse.gemini.example.comics.model
PUnit bundle proxy loader created: org.eclipse.gemini.jpa.classloader.BundleProxyClassLoader@1479feb(org.eclipse.gemini.example.comics.model)
  Parent loader: sun.misc.Launcher$AppClassLoader@11b86e7
  Parent loader: sun.misc.Launcher$ExtClassLoader@35ce36
Provider bundle proxy loader created: org.eclipse.gemini.jpa.classloader.BundleProxyClassLoader@1543c88(org.eclipse.gemini.jpa)
  Parent loader: sun.misc.Launcher$AppClassLoader@11b86e7
  Parent loader: sun.misc.Launcher$ExtClassLoader@35ce36
Composite loader created: org.eclipse.gemini.jpa.classloader.CompositeClassLoader@15212bc
  Parent loader: sun.misc.Launcher$AppClassLoader@11b86e7
  Parent loader: sun.misc.Launcher$ExtClassLoader@35ce36
Parsing Eclipse .classpath
Finished parsing Eclipse .classpath: bin
Extender - bundle event,  bundle=org.eclipse.gemini.example.comics.model, event=RESOLVED
Extender - bundle event,  bundle=org.eclipse.gemini.example.comics.client, event=RESOLVED
Extender - bundle event,  bundle=org.eclipse.gemini.example.comics.model, event=STARTING
GeminiExtender registerPersistenceUnitsInBundle:  bundle=org.eclipse.gemini.example.comics.model id=7 state=STARTING
GeminiExtender checking bundle compatibility of:  bundle=org.eclipse.gemini.example.comics.model id=7 state=STARTING
GeminiExtender provider compatible with bundle:  bundle=org.eclipse.gemini.example.comics.model id=7 state=STARTING
!SESSION EclipseLinkProvider registerPersistenceUnits: [
PUnit: comics
  --- XML Data ---
  provider: null
  classes: [org.eclipse.gemini.example.comics.model.Series, org.eclipse.gemini.example.comics.model.Publisher, org.eclipse.gemini.example.comics.model.Issue]
  driverClassName: org.apache.derby.jdbc.ClientDriver
  driverUrl: jdbc:derby://localhost:1527/gemini;create=true
  driverUser: app
  driverPassword: app
  --- Runtime Data ---
  bundle: org.eclipse.gemini.example.comics.model
  assignedProvider: org.eclipse.gemini.jpa.provider.EclipseLinkOSGiProvider@11978b
  descriptorInfo: Descriptor: META-INF/persistence.xml
  uniquePackageNames: null
  emfHandler: null
  emfBuilderHandler: null
  DSF tracker: null]
2011-02-23 17:07:52.147 -GeminiServicesUtil registerEMFServices for comics
GeminiServicesUtil EMF[Builder] services props: {osgi.managed.bundles=org.eclipse.gemini.example.comics.model_1.0.0.qualifier, osgi.unit.version=1.0.0.qualifier, osgi.unit.name=comics, osgi.unit.provider=org.eclipse.persistence.jpa.PersistenceProvider}
GeminiServicesUtil register EMF service
GeminiServicesUtil loading EMF class
GeminiServicesUtil EMF proxy class array: 
  interface javax.persistence.EntityManagerFactory
------------------GeminiServicesUtil proxy loader org.eclipse.gemini.jpa.classloader.CompositeClassLoader@f7c31d
  Parent loader: sun.misc.Launcher$AppClassLoader@11b86e7
  Parent loader: sun.misc.Launcher$ExtClassLoader@35ce36
----------------------------
eclipse.buildId=unknown
java.version=1.6.0_22
java.vendor=Sun Microsystems Inc.
BootLoader constants: OS=win32, ARCH=x86, WS=win32, NL=en_CA
Command-line arguments:  -dev file:D:/Conferences/EclipseCon 2011/Gemini-Virto Tutorial/workspace/.metadata/.plugins/org.eclipse.pde.core/comics client/dev.properties -os win32 -ws win32 -arch x86 -consoleLog -console -clean

!ENTRY org.eclipse.gemini.example.comics.model 4 0 2011-02-23 17:07:53.317
!MESSAGE 
!STACK 0
org.osgi.framework.BundleException: State change in progress for bundle "initial@reference:file:../../../../org.eclipse.gemini.example.comics.model/" by thread "Refresh Packages".
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.beginStateChange(AbstractBundle.java:1075)
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(AbstractBundle.java:374)
	at org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Framework.java:1111)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:559)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:544)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(StartLevelManager.java:457)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(StartLevelManager.java:243)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:438)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:1)
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340)
Caused by: org.eclipse.osgi.framework.internal.core.AbstractBundle$BundleStatusException
	... 11 more
Root exception:
org.eclipse.osgi.framework.internal.core.AbstractBundle$BundleStatusException
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.beginStateChange(AbstractBundle.java:1075)
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(AbstractBundle.java:374)
	at org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Framework.java:1111)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:559)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:544)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(StartLevelManager.java:457)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(StartLevelManager.java:243)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:438)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:1)
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340)
GeminiServicesUtil created EMF proxy 
GeminiServicesUtil trackDataSourceFactory for p-unit comics
WARNING: DataSourceFactory for org.apache.derby.jdbc.ClientDriver not registered.
GeminiServicesUtil register EMFBuilder service
GeminiServicesUtil loading EMFBuilder class
GeminiServicesUtil EMFBuilder proxy class array: 
  interface org.osgi.service.jpa.EntityManagerFactoryBuilder
GeminiServicesUtil proxy loader org.eclipse.gemini.jpa.classloader.CompositeClassLoader@15ad5c6
  Parent loader: sun.misc.Launcher$AppClassLoader@11b86e7
Extender - bundle event,  bundle=org.eclipse.persistence.core, event=STARTING
  Parent loader: sun.misc.Launcher$ExtClassLoader@35ce36
Extender - bundle event,  bundle=org.eclipse.persistence.core, event=STARTED
Extender - bundle event,  bundle=org.eclipse.gemini.dbaccess.derby, event=STARTING
Gemini DBAccess - Derby JDBC starting
GeminiServicesUtil created EMFBuilder proxy 
GeminiServicesUtil registered EMFBuilder service for comics
Extender - bundle event,  bundle=org.eclipse.gemini.example.comics.model, event=STARTED
Extender - bundle event,  bundle=org.eclipse.gemini.example.comics.client, event=STARTING
Extender - bundle event,  bundle=org.eclipse.gemini.example.comics.client, event=STARTED
Extender - bundle event,  bundle=org.eclipse.gemini.example.comics.client, event=STOPPING
Extender - bundle event,  bundle=org.eclipse.gemini.example.comics.client, event=STOPPED
Extender - bundle event,  bundle=org.eclipse.gemini.example.comics.client, event=UNRESOLVED
Extender - bundle event,  bundle=org.eclipse.gemini.example.comics.client, event=RESOLVED
Extender - bundle event,  bundle=org.eclipse.gemini.example.comics.client, event=STARTING
Extender - bundle event,  bundle=org.eclipse.gemini.example.comics.client, event=STARTED
Extender - bundle event,  bundle=org.eclipse.gemini.dbaccess.derby, event=STARTED
Extender - bundle event,  bundle=org.apache.derby, event=STARTING
Extender - bundle event,  bundle=org.apache.derby, event=STARTED
Extender - bundle event,  bundle=org.eclipse.persistence.asm, event=STARTING
Extender - bundle event,  bundle=org.eclipse.persistence.asm, event=STARTED
Extender - bundle event,  bundle=org.eclipse.osgi, event=STARTED

Comment 1 Krum Tsvetkov

2011-04-21 06:01:26 EDT

I am seeing the same problem sporadically with a different sample application,
during startup of the OSGi framework. And I'm pretty sure there is no re-start of the DataSourceFactory.

I'm still wondering if the refreshPackages could be avoided in some way (and by this prevent problems like this one). But I already asked this in Bug 337157, hoping to get a better understanding why it is done.

Comment 2 Michael Keith

2011-04-23 12:51:31 EDT

Not sure about this one, but it may be related to a timing problem of the bundle being in some middle state after being installed but not yet started and that it is being refreshed before it has been activated. In any case, I think it has to do with the refresh, rather than the data source not being started yet.

See https://bugs.eclipse.org/bugs/show_bug.cgi?id=337157 for an explanation of why the refresh happens. I will be looking into this issue soon, I hope.

Comment 3 Michael Keith

2011-07-04 09:31:24 EDT

I can't reproduce but while fixing 342996 I saw some funniness in the state change code that could have caused this. Am hoping that it is fixed, now, but if someone encounters this again please reopen this bug.