Bug 383199 - Non-spec-compliant static metamodel bootstrap due to default lazy initialization of EMF
Summary: Non-spec-compliant static metamodel bootstrap due to default lazy initializat...
Status: CLOSED FIXED
Alias: None
Product: z_Archived
Classification: Eclipse Foundation
Component: Eclipselink (show other bugs)
Version: unspecified   Edit
Hardware: PC All
: P2 normal (vote)
Target Milestone: ---   Edit
Assignee: Nobody - feel free to take it CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on: 383224
Blocks: 383201
  Show dependency tree
 
Reported: 2012-06-21 05:25 EDT by Craig Ringer CLA
Modified: 2022-06-09 10:21 EDT (History)
6 users (show)

See Also:


Attachments
Test case showing problem may not be fixed in 2.4.0-RC2 and 2.3.3-M3 (25.50 KB, application/zip)
2012-06-21 05:42 EDT, Craig Ringer CLA
no flags Details
AS7 server log from test run with EclipseLink 2.4.0, AS7 with AS7-4996 fix (7.2.0-ALPHA, git 51a5c0ffd00ad7666f349c7f57c8c1635fd6b911) (47.57 KB, text/plain)
2012-07-29 22:28 EDT, Craig Ringer CLA
no flags Details
AS7 server log, same as above but ONLY contains test run for staticMetaModelWorks() (30.30 KB, text/x-log)
2012-07-29 22:51 EDT, Craig Ringer CLA
no flags Details
Proposed documentation patch to make this issue more discoverable. No behaviour change. (2.46 KB, patch)
2012-07-30 04:48 EDT, Craig Ringer CLA
no flags Details | Diff
Alternate patch: Documentation fixes, plus change the default to deploy on startup by default (3.84 KB, patch)
2012-07-30 04:57 EDT, Craig Ringer CLA
no flags Details | Diff
proposed fix - initial version (37.08 KB, patch)
2013-07-10 11:10 EDT, Tom Ware CLA
no flags Details | Diff
proposed fix update - includes new files (47.95 KB, patch)
2013-07-10 13:18 EDT, Tom Ware CLA
no flags Details | Diff
updated patch (54.84 KB, patch)
2013-08-13 09:41 EDT, Tom Ware CLA
no flags Details | Diff
updated patch (55.64 KB, patch)
2013-08-15 15:26 EDT, Tom Ware CLA
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Craig Ringer CLA 2012-06-21 05:25:41 EDT
Build Identifier: 

A project that uses the static metamodel will fail with NullPointerException when deployed on JBoss AS 7.1.1.Final . It appears that dynamic enrichment (weaving) isn't occurring.

A test case for this issue is attached.

I'm struggling to isolate why weaving isn't performed, so I can't absolutely verify that it's an EclipseLink bug not an AS7 issue. Dynamic weaving works as expected with Hibernate as the persistence provider.

Reproducible: Always

Steps to Reproduce:
1. Download testcase
2. Download JBoss AS 7.1.1.Final and unzip it
3. Follow instructions in README
Comment 1 Craig Ringer CLA 2012-06-21 05:26:09 EDT
Note that the test case includes a workaround for:

https://bugs.eclipse.org/bugs/show_bug.cgi?id=365704
Comment 2 Craig Ringer CLA 2012-06-21 05:42:12 EDT
Created attachment 217681 [details]
Test case showing problem may not be fixed in 2.4.0-RC2 and 2.3.3-M3
Comment 3 Craig Ringer CLA 2012-06-21 11:53:53 EDT
Interestingly, the following appears in the log:

23:25:40,545 TRACE [org.eclipse.persistence.metamodel] (pool-4-thread-1) Canonical Metamodel class [id.au.ringerc.testcase.as7.eclipselink.entities.DummyEntity_] found and instantiated during initialization.

However, it occurs *after* the user test code that tried to access DummyEntity_ has run!

Looking at my test logs I can see that the dynamic metamodel test has run after the static metamodel test. This made me suspect that some kind of lazily triggered initialisation is being triggered by dynamic metamodel access. Sure enough, the following unit test SUCCEEDS when added to ExplicitClassesTest.java:

	@Test
	public void dynamicMetamodelPopulatesStaticModel() {
		Assert.assertNull(DummyEntity_.id);
		super.dynamicMetaModelWorks();
		Assert.assertNotNull(DummyEntity_.id);
	}

even when all other tests are disabled.


BTW, I've updated the above testcase to produce more readable logging output by integrating into JBoss's logging. New testcase here:

https://github.com/ringerc/scrapcode/tree/master/testcases/javaee/JBossAS7-EclipseLink-Module/as7.eclipselink

and it includes the test showing that access to the dynamic metamodel loads the static metamodel.

(not re-attached since I'm using this test in several bugs and there's no point repeating it over and over).
Comment 4 Tom Ware CLA 2012-07-23 09:59:49 EDT
Setting target and priority.  See the following page for the meanings of these fields:

http://wiki.eclipse.org/EclipseLink/Development/Bugs/Guidelines

Community: Please vote for this bug if it is important to you.  Votes are one of the main criteria we use to determine which bugs to fix next.
Comment 5 Michael Keith CLA 2012-07-25 09:03:55 EDT
Does the fix introduced by https://issues.jboss.org/browse/AS7-4996
solve this problem?
Comment 6 Craig Ringer CLA 2012-07-29 22:19:52 EDT
Tested on today's AS 7.2-ALPHA which incorporates the AS7-4996 fix. Git ref is 51a5c0ffd00ad7666f349c7f57c8c1635fd6b911 .

I tested with an updated version of the test case that uses EclipseLink 2.4.0 final (now it's out), has a configurable JBoss AS 7 version, and fixes a compatibility issue with post-7.1.1 AS7. I've pushed it to my git scrapcode repo so you'll see it as the current version of the test case.

I Built AS7:

{code}
./build.sh clean install
cd build/target/jboss-as-7.2.0.Alpha1-SNAPSHOT
{code}

Copied the EclipseLink module over as per the test case README:

{code}
cp ~/.m2/repository/org/eclipse/persistence/eclipselink/2.4.0/eclipselink-2.4.0.jar jboss7modules/org/eclipse/persistence/main/eclipselink-2.4.0.jar

cp -r jboss7modules/* ~/projects/jboss-as/build/target/jboss-as-7.2.0.Alpha1-SNAPSHOT/modules/
{code}

Started AS7

{code}
bin/standalone.sh
{code}

Increased EclipseLink logging verbosity with:

{code}
bin/jboss-cli.sh --connect '/subsystem=logging/logger=org.eclipse:add(level=FINEST)'
{code}

Deleted @Ignore annotations from:

{code}
ExplicitClassesTest.staticMetaModelWorks()
ExplicitClassesTest.staticMetamodelWorksAfterDynamicModelAccess()
ExplicitClassesTest.dynamicMetaModelWorks()
{code}

... ran the tests from the root dir of my test case:

{code}
mvn -Djboss.as.version=7.2.0.Alpha1-SNAPSHOT clean test
{code}

... and got:

{code}

Failed tests:   staticMetaModelWorks(id.au.ringerc.testcase.as7.eclipselink.ExplicitClassesTest): Static metamodel has null members: java.lang.NullPointerException
{code}

for the test code:

{code}
	protected void staticMetaModelWorks() {
		try {
			DummyEntity_.id.getName();
		} catch (NullPointerException ex) {
			Assert.fail("Static metamodel has null members: " + ex);
		}
	}
{code}

(called via ExplicitClassesTest)


Note that dynamicMetaModelWorks() and staticMetamodelWorksAfterDynamicModelAccess() both passed. The behaviour has not changed, and this bug is not fixed as of EclipseLink 2.4.0 final and today's AS7.
Comment 7 Craig Ringer CLA 2012-07-29 22:28:43 EDT
Created attachment 219319 [details]
AS7 server log from test run with EclipseLink 2.4.0, AS7 with AS7-4996 fix (7.2.0-ALPHA, git 51a5c0ffd00ad7666f349c7f57c8c1635fd6b911)

Sorry about JIRA-style {code} comments; I forget EclipseLink is on BugZilla. Can't preview comments or edit after posting, so not much I can do.

I'll attach the AS7 server log from the test run. I've also set some more logging:

   /subsystem=logging/logger=org.jboss.as.jpa:add(level=TRACE)
   /subsystem=logging/logger=org.jboss.as.deployment-scanner:add(level=TRACE)
Comment 8 Craig Ringer CLA 2012-07-29 22:51:05 EDT
Created attachment 219320 [details]
AS7 server log, same as above but ONLY contains test run for staticMetaModelWorks()

I've attached another log. This is bascially the same as the prior one, but it *only* contains a test run for ExplicitClassesTest.staticMetaModelWorks() , which is the problem test. This should make it easier to compare.
Comment 9 Craig Ringer CLA 2012-07-30 00:03:25 EDT
I've split DummyEJB.dynamicMetaModelWorks() into individual metamodel access statements with logging.

I can now confirm that the following call triggers the static metamodel to be populated:

Metamodel mm = em.getMetamodel();

... where "em" is of course the EntityManager.

I'm struggling to track it down more tightly because the call path is *insanely* complicated and full of proxies, interceptors and man-eating grues. 

The sane option would be to set a watch breakpoint on:

  id.au.ringerc.testcase.as7.eclipselink.entities.DummyEntity_.id

, ie wait for the field to change and grab the call stack. Unfortunately, Eclipse isn't breaking when the field changes - maybe because it's a volatile static field? I'm not sure.

So all I can tell you so far is that it's accessing the dynamic on the EntityManager that triggers population of the static metamodel.

The log looks like this:


11:59:24,364 INFO  [id.au.ringerc.testcase.as7.eclipselink.DummyEJB] (pool-3-thread-1) Before get metamodel, DummyEntity_.id is null
11:59:24,368 TRACE [org.jboss.as.jpa] (pool-3-thread-1) pu search for name '' inside of explicit-classes.war
11:59:24,368 TRACE [org.jboss.as.jpa] (pool-3-thread-1) pu search for name '' inside of explicit-classes.war
11:59:24,369 TRACE [org.jboss.as.jpa] (pool-3-thread-1) findWithinDeployment check '' against pu 'as7.eclipselink'
11:59:24,369 TRACE [org.jboss.as.jpa] (pool-3-thread-1) findWithinDeployment matched '' against pu 'as7.eclipselink'
11:59:24,370 TRACE [org.jboss.as.jpa] (pool-3-thread-1) pu search found explicit-classes.war#as7.eclipselink
11:59:24,377 TRACE [org.eclipse.persistence.jpa] (pool-3-thread-1) Begin deploying Persistence Unit as7.eclipselink; session vfs:/content/explicit-classes.war/WEB-INF/classes/_as7.eclipselink; state Predeployed; factoryCount 1
.... lots of deployment messages from EclipseLink ...
11:59:25,080 TRACE [org.eclipse.persistence.jpa] (pool-3-thread-1) End deploying Persistence Unit as7.eclipselink; session vfs:/content/explicit-classes.war/WEB-INF/classes/_as7.eclipselink; state Deployed; factoryCount 1
11:59:25,098 DEBUG [org.jboss.as.jpa] (pool-3-thread-1) pool-3-thread-1:[transaction scoped EntityManager]: created entity manager session TransactionImple < ac, BasicAction: 0:ffff7f000001:-61c02f50:50160633:8 status: ActionStatus.RUNNING >
11:59:25,099 TRACE [org.jboss.as.jpa] (pool-3-thread-1) getMetamodel took 726ms



From this, you can see that EclipseLink's full PU deploy (as opposed to predeploy) is only triggered when the metamodel is accessed.

Something is being a little too enthusiastically lazy here.
Comment 10 Craig Ringer CLA 2012-07-30 00:31:19 EDT
In DummyEJB.java, if I change:

@Inject
private EntityManager em;

... to:

@PersistenceContext(name="as7.eclipselink")
private EntityManager em;

then the EntityManager gets initialized at entry to the EJB and consequently DummyEntity_.id is non-null when dynamicMetaModelWorks() is entered, before the em.getMetaModel() call. It's still null before the EJB call.


In other words, it isn't necessary to access the dynamic metamodel to populate the static metamodel. It's only necessary to initialize an entity manager. The getMetamodel() angle was the wrong tree; it worked because CDI-injected entity managers are not initialized until a method call is made on the proxy object.

Even calling `em.isOpen()' is sufficient; anything that causes the proxied EntityManager to be initialized by hitting API defined in the EntityManager interface will do.


It looks like AS7 is lazily creating the persistence unit and EclipseLink populates the static metamodel during full deploy not predeploy. The combination of the two: *boom*.

Solutions:

- AS7 eagerly deploys the persistence unit

- EclipseLink populates the static metamodel during predeploy (if this is possible); or

- EclipseLink provides an explicit SPI to allow the static metamodel to be populated without a full deploy, and AS7 calls it after predeploy.
Comment 11 Craig Ringer CLA 2012-07-30 00:50:59 EDT
The JSR317 spec says that:

When the entity manager factory for a persistence unit is created, it is the responsibility of the persistence provider to initialize the state of the metamodel classes of the persistence unit. Any generated
metamodel classes must be accessible on the classpath.

It appears that EclipseLink is honouring that contract; the problem is that AS7 is a wee bit too flexible about exactly when it creates the EntityManagerFactory, especially where CDI is involved.

Moving to AS7 JIRA.
Comment 12 Craig Ringer CLA 2012-07-30 03:41:44 EDT
While writing a much more detailed test case for this to submit to AS7's JIRA, I've come to wonder if this is an AS7 issue after all.

I can inject an EntityManagerFactory and call methods like isOpen(), getPersistenceUnitUtil() and getProperties() on it without triggering population of the static metamodel.

That means that the EntityManagerFactory exists, but the metamodel isn't populated, violating the spec.

See more detailed test case and README here:

  https://github.com/ringerc/scrapcode/tree/master/testcases/javaee/eclipselink-as7.metamodel

If you want to run the test:

  git clone git://github.com/ringerc/scrapcode.git
  cd scrapcode/testcases/javaee/eclipselink-as7.metamodel
  less README
Comment 13 Craig Ringer CLA 2012-07-30 03:58:32 EDT
Here's a stack trace from where the static metamodel is assigned as a result of a call to "em.isOpen()" on an EntityManager injected into a test using @PersistenceContext.

org.eclipse.persistence.internal.jpa.metamodel.SingularAttributeImpl<X,T>.<init>(org.eclipse.persistence.internal.jpa.metamodel.ManagedTypeImpl<X>, org.eclipse.persistence.mappings.DatabaseMapping, boolean) line: 79	
org.eclipse.persistence.internal.jpa.metamodel.EntityTypeImpl<X>(org.eclipse.persistence.internal.jpa.metamodel.ManagedTypeImpl<X>).initialize() line: 1306	
org.eclipse.persistence.internal.jpa.metamodel.MetamodelImpl.initialize() line: 459	
org.eclipse.persistence.internal.jpa.metamodel.MetamodelImpl.<init>(org.eclipse.persistence.sessions.DatabaseSession) line: 111	
org.eclipse.persistence.internal.jpa.metamodel.MetamodelImpl.<init>(org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl) line: 130	
org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.getMetamodel() line: 2841	
org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.deploy(java.lang.ClassLoader, java.util.Map) line: 573	
org.eclipse.persistence.internal.jpa.EntityManagerFactoryDelegate.getDatabaseSession() line: 186	
org.eclipse.persistence.internal.jpa.EntityManagerFactoryDelegate.createEntityManagerImpl(java.util.Map) line: 278	
org.eclipse.persistence.internal.jpa.EntityManagerFactoryImpl.createEntityManagerImpl(java.util.Map) line: 304	
org.eclipse.persistence.internal.jpa.EntityManagerFactoryImpl.createEntityManager() line: 282	
org.jboss.as.jpa.container.EntityManagerUtil.createEntityManager(javax.persistence.EntityManagerFactory, java.util.Map) line: 44	
org.jboss.as.jpa.container.TransactionScopedEntityManager.getEntityManager() line: 78	
org.jboss.as.jpa.container.TransactionScopedEntityManager(org.jboss.as.jpa.container.AbstractEntityManager).isOpen() line: 511	
au.id.ringerc.testcases.eclipselink_as7.metamodel.PersistenceContextTest.metamodelPopulatedAfter() line: 26	




and here's when it's instantiated after a getMetamodel() call on an injected EntityManagerFactory:

org.eclipse.persistence.internal.jpa.metamodel.SingularAttributeImpl<X,T>.<init>(org.eclipse.persistence.internal.jpa.metamodel.ManagedTypeImpl<X>, org.eclipse.persistence.mappings.DatabaseMapping, boolean) line: 79	
org.eclipse.persistence.internal.jpa.metamodel.EntityTypeImpl<X>(org.eclipse.persistence.internal.jpa.metamodel.ManagedTypeImpl<X>).initialize() line: 1306	
org.eclipse.persistence.internal.jpa.metamodel.MetamodelImpl.initialize() line: 459	
org.eclipse.persistence.internal.jpa.metamodel.MetamodelImpl.<init>(org.eclipse.persistence.sessions.DatabaseSession) line: 111	
org.eclipse.persistence.internal.jpa.metamodel.MetamodelImpl.<init>(org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl) line: 130	
org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.getMetamodel() line: 2841	
org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.deploy(java.lang.ClassLoader, java.util.Map) line: 573	
org.eclipse.persistence.internal.jpa.EntityManagerFactoryDelegate.getDatabaseSession() line: 186	
org.eclipse.persistence.internal.jpa.EntityManagerFactoryDelegate.getMetamodel() line: 602	
org.eclipse.persistence.internal.jpa.EntityManagerFactoryImpl.getMetamodel() line: 516	
au.id.ringerc.testcases.eclipselink_as7.metamodel.PersistenceUnitTest_getMetamodelTest.metamodelPopulatedAfterMetamodelAccess() line: 19
Comment 14 Craig Ringer CLA 2012-07-30 04:05:55 EDT
Looks like this is related to https://bugs.eclipse.org/bugs/show_bug.cgi?id=322585 where issues with the dynamic metamodel cropped up after a performance optimisation.

The static metamodel can't be initialized lazily, because there's no safe way to trap the first access to it. It looks like EclipseLink is trying anyway.

(Why the JPA2 EG chose to use static volatile field access rather than method access is beyond me, given all the limitations Java places on field access...)
Comment 15 Craig Ringer CLA 2012-07-30 04:18:14 EDT
Now I know where I'm looking this is all over the place. See, eg:

http://www.eclipse.org/forums/index.php/mv/msg/277509/780994/

EclipseLink has a property, eclipselink.deploy-on-startup, that it uses to control whether the persistence unit and metamodel are lazily initialized. It defaults to false, so the static metamodel isn't populated even after the entity manager factory is created, in voliation of the spec.

This is not a JBoss AS 7 specific issue.

Adding:

  <property name="eclipselink.deploy-on-startup" value="True" />

to persistence.xml gets EclipseLink to behave in a compliant manner.

Is there any way to fix this? Change the default to a spec-compliant behaviour?  Detect the presence of static metamodel classes on the classpath during predeploy and force a full immediate deploy if they're found?
Comment 16 Craig Ringer CLA 2012-07-30 04:48:41 EDT
Created attachment 219323 [details]
Proposed documentation patch to make this issue more discoverable. No behaviour change.
Comment 17 Craig Ringer CLA 2012-07-30 04:57:47 EDT
Created attachment 219324 [details]
Alternate patch: Documentation fixes, plus change the default to deploy on startup by default

Attached a pair of patches. Both fix the documentation to make this clearer. The second one also changes the default so EclipseLink deploys on startup by default for strict JPA 2.0 compliance.

This early into 2.4.0, it may well be reasonable to change the default. If there's no way to detect the presence of static metamodel classes during scanning I think that'd be the safest course, if it doesn't break anything else.
Comment 18 Tom Ware CLA 2012-09-04 14:11:23 EDT
Pushing to a more major version.  The behavior has existed for a quite a while and we may need some design change.
Comment 19 Craig Ringer CLA 2012-09-15 20:48:33 EDT
Any chance the docs patch can be applied to 2.4.x at least, so this is easier to find out about?
Comment 20 Tom Ware CLA 2012-09-28 08:32:23 EDT
Updated the comments in 2.4.1.  Leaving this bug open for investigation in our next major release.
Comment 21 Tom Ware CLA 2013-05-16 13:53:43 EDT
Did not make 2.5.0.  Defer to 2.5.1
Comment 22 Tom Ware CLA 2013-07-10 11:10:49 EDT
Created attachment 233324 [details]
proposed fix - initial version

The attached proposed fix allows use of the metamodel without significantly altering our startup process.  Instead of forcing eager loading of persistence units that may not be used, we build the metamodel with a proxy object that is capable of triggering initialization on demand.

We should discuss whether to put this just in 2.6 or also in 2.5.1 - it does not create any backward incompatibility issues, but is a significant enough change to create some risk.
Comment 23 Tom Ware CLA 2013-07-10 13:18:33 EDT
Created attachment 233328 [details]
proposed fix update - includes new files
Comment 24 Tom Ware CLA 2013-08-13 09:41:45 EDT
Created attachment 234352 [details]
updated patch
Comment 25 Tom Ware CLA 2013-08-15 15:26:10 EDT
Created attachment 234468 [details]
updated patch
Comment 26 Tom Ware CLA 2013-08-16 08:54:30 EDT
Fix checked into our 2.6 stream.  This fix automatically populates the metamodel with proxies that will trigger the remainder of the persistence unit load when accessed.

Reviewed by Gordon Yorke

Added test to JUnitCriteriaSimpleTestSuite

Tested with JPA LRG

I am leaning towards fixing this only in 2.6 since there is some risk to the fix.  I will leave the bug open for a few days for comments requesting an alternate strategy.
Comment 27 Tom Ware CLA 2013-08-16 08:55:00 EDT
accidentally closed
Comment 28 Tom Ware CLA 2013-08-20 10:46:56 EDT
Closing.  There have been no requests for an earlier release.
Comment 29 Mauro Molinari CLA 2014-11-19 11:57:32 EST
Hi,
I've come across this bug after having issues with EclipseLink 2.5.2 configured with Spring.
Essentially, I'm using Spring to configure a TomcatLoadTimeWeaver and set it on EclipseLink. Debugging the bootstrap code, I see that the transformer provided by the weaver is correctly added to the Tomcat class loader, so I would expect weaving to work.
However, what I observe is that EclipseLink does the following (in this order):
1. process the metadata (for instance, it says it's applying default names for foreign keys, since I didn't specify foreign key column names in my annotations)
2. add the transformer for load time weaving
3. do other things which causes the following log to be produced:
"reverting the lazy setting on the onetoone or manytoone attribute [...]"
(the listed attributes are many, if not all, my OneToOne and ManyToOne relationship attributes).

I do have the metamodel classes on my classpath: so, I was wondering whether this bug were the actual source of my problem, so that I need to switch to 2.6.0 in order to make load time weaving work correctly.
Thanks in advance for any feedback.
Comment 30 Mauro Molinari CLA 2014-11-20 04:29:11 EST
For test, I updated to EclipseLink 2.6.0.v20140809-296a69f (2.6.0-M3 in Maven Central), but I still see my problem: weaving is not applied and "Reverting the lazy setting on the OneToOne or ManyToOne attribute" errors are produced, although the weaver IS applied (I think too late, though). Please let me know if I should open a new bug report and tell me what information I should provide.
For now, I must fall back to using static weaving.
Comment 31 Eclipse Webmaster CLA 2022-06-09 10:21:00 EDT
The Eclipselink project has moved to Github: https://github.com/eclipse-ee4j/eclipselink