[jspies2]

Just noticed and tested multiple times, ever since I added the stack trace, I haven't gotten a Revert warning since.  I have also verified it is working correctly and not EAGERLY fetching the relationships.  If I remove the stacktrace, it goes back to having the Revert errors.  Odd.

[smarlow]

Looks like the JSFManagedBeanProcessor is loading application classes before they can be weaved.

[smarlow]

The Thread.dumpStack is showing that JSFManagedBeanProcessor is loading the entity classes before they are enhanced/weaved/rewritten.

From the TRACE output, I see that tcApp.jar contains the persistence.xml.  Where are the entity classes contained in your ear?

You could disable the Thread.dumpStack or comment it out to reduce the output.  Could you also update class org.jboss.as.jsf.deployment.JSFManagedBeanProcessor to log some information?

Please replace:

final Class<?> componentClass = module.getClassLoader().loadClass(managedBean);
componentClass.getConstructor();

With:

final Class<?> componentClass = module.getClassLoader().loadClass(managedBean);
JSFLogger.ROOT_LOGGER.tracef("!!!JSFManagedBeanProcessor deployment phase=%s, managedBean=%s, module classloader=%s",phaseContext.getPhase().name(), managedBean, module.getClassLoader());
componentClass.getConstructor();

I think that we are getting closer.  Thanks for doing all of the debugging through logging. 

[smarlow]

Also, enable tracing for org.jboss.as.jsf or you could instead log at the INFO level:

final Class<?> componentClass = module.getClassLoader().loadClass(managedBean);  
JSFLogger.ROOT_LOGGER.infof("!!!JSFManagedBeanProcessor deployment phase=%s, managedBean=%s, module classloader=%s",phaseContext.getPhase().name(), managedBean, module.getClassLoader());  
componentClass.getConstructor();  

[jspies2]

All of the entity classes as well as any class that injects the PersistenceUnit are also in tcApp.jar with persistence.xml.   When I deploy just tcApp or the EAR with just tcApp, everything works fine.  I thought tcWeb might be deploying first, so I tried adding the initialize in order to application.xml with tcApp first then tcWeb, since tcWeb is dependent on tcApp and there is no dependency for tcApp on tcWeb.  In doing this however, it actually wouldn't deploy and gave a bunch of other errors. Based on the random behavior and the fact that deploying multiple times and adding logging can change the outcome, I'm assuming it's some form of concurrent loading, and depending on if the eclipselink weaver/classfiletransformer gets loaded first or not is whether all, some, or no weaving gets done.

I'll work on getting the other logging now.  Thanks!

[jspies2]

Attached is the latest log.  I removed the stack trace logging.  Let me know if I can provide anything else.

[smarlow]

I am looking at the server2.log output and can see that the first JSFManagedBeanProcessor output is for the OrganizationConfigController class which seems to have references to varies entities like the PivotData class.  I think that is why the JSFManagedBeanProcessor loading of all managed bean classes (in tcWeb.war), which is also loading entity classes (coming from tcApp.jar).  Do you agree that OrganizationConfigController is referencing entity classes?  Do you have a faces-config.xml or *.faces-config.xml config file that lists the managed-bean-class? 

00:34:27,972 INFO  [org.jboss.as.jsf] (MSC service thread 1-5) !!!JSFManagedBeanProcessor deployment phase=POST_MODULE, managedBean=tc.web.controller.settings.OrganizationConfigController, module classloader=ModuleClassLoader for Module "deployment.EnterpriseApplication1.ear.tcWeb.war:main" from Service Module Loader

00:34:27,976 INFO  [org.jboss.as.jsf] (MSC service thread 1-5) !!!JSFManagedBeanProcessor deployment phase=POST_MODULE, managedBean=tc.web.controller.dashboard.indicator.FileDashboardController, module classloader=ModuleClassLoader for Module "deployment.EnterpriseApplication1.ear.tcWeb.war:main" from Service Module Loader

00:34:27,977 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/entities/type/PivotData

00:34:27,977 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/entities/type/Attribute

00:34:27,978 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform org/primefaces/model/tagcloud/TagCloudItem

00:34:27,979 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/web/model/workflow/AbstractTaskDataModel

00:34:27,979 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/web/model/AbstractSearchSelectedLazyDataModel

00:34:27,979 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/web/model/AbstractSearchLazyDataModel

00:34:27,979 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/web/model/AbstractLazyDataModel

00:34:27,979 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform org/primefaces/model/LazyDataModel

00:34:27,980 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform org/primefaces/model/SelectableDataModel

00:34:27,980 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/web/model/workflow/OrganizationIndicatorTaskDataModel

00:34:27,980 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/web/model/indicator/IndicatorAssociationLazyDataModel

00:34:27,981 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/entities/type/Notification

00:34:27,981 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/service/attribute/AbstractAttributeService

00:34:27,981 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/service/attribute/IndicatorAttributeService

00:34:27,982 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/web/model/alert/AbstractAlertLazyDataModel

00:34:27,982 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/web/model/alert/OrganizationIndicatorAlertLazyDataModel

00:34:27,982 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/entities/type/Postable

00:34:27,983 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/entities/type/FullIndicator

00:34:27,983 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/entities/type/Alertable

00:34:27,984 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/service/indicator/AbstractIndicatorService

00:34:27,984 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/service/type/PostSearchService

00:34:27,984 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/service/indicator/FileIndicatorService

00:34:27,985 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/web/model/indicator/FileActionsLazyDataModel

00:34:27,985 TRACE [org.jboss.as.jpa] (MSC service thread 1-5) !!!JPADelegatingClassFileTransformer.transform tc/web/model/indicator/AbstractOrganizationIndicatorLazyDataModel

00:34:28

Just prior to the above "web" processing, I can see that we are still deploying the persistence.xml in the "jar":

00:34:27,837 TRACE [org.jboss.as.jpa] (ServerService Thread Pool -- 57) calling createContainerEntityManagerFactory for pu=EnterpriseApplication1.ear/tcApp.jar#MyPU with integration properties={eclipselink.archive.factory=org.jipijapa.eclipselink.JBossArchiveFactoryImpl, eclipselink.target-server=org.jipijapa.eclipselink.JBossAS7ServerPlatform, eclipselink.logging.logger=org.jipijapa.eclipselink.JBossLogger}, application properties={eclipselink.jpa.uppercase-column-names=true, eclipselink.cache.size.default=5000, eclipselink.logging.level=FINE, eclipselink.logging.logger=JavaLogger}

00:

I would like to see another trace output to the deployPersistenceUnit method in org.jboss.as.jpa.processor.PersistenceUnitServiceHandler:

JPA_LOGGER.infof("!!!PersistenceUnitServiceHandler deployPersistenceUnit deployment phase=%s startEarly=",phaseContext.getPhase().name(), startEarly);

[jspies2]

I am looking at the server2.log output and can see that the first JSFManagedBeanProcessor output is for the OrganizationConfigController class which seems to have references to varies entities like the PivotData class.  I think that is why the JSFManagedBeanProcessor loading of all managed bean classes (in tcWeb.war), which is also loading entity classes (coming from tcApp.jar).  Do you agree that OrganizationConfigController is referencing entity classes?  Do you have a faces-config.xml or *.faces-config.xml config file that lists the managed-bean-class?

Yes, most of the managed beans do use one or more entity classes located in tcApp. It does this via the data access classes also in tcApp, but does reference the actual entities. I do not have a faces-config class that has anything useful in it, all of the managedbeans and faces config are done via annotations.

I would like to see another trace output to the deployPersistenceUnit method in org.jboss.as.jpa.processor.PersistenceUnitServiceHandler:

I will work on getting this.

[jspies2]

Attached is the newest log.

[smarlow]

Thanks Jason.  Some interesting lines are copied here:

1.  11:59:56,710 TRACE [org.jboss.as.server] (MSC service thread 1-1) !!!DelegatingClassFileTransformer.addTransformer org.jboss.as.jpa.classloader.JPADelegatingClassFileTransformer@5dc3dfea

2.  11:59:56,968 TRACE [org.jboss.as.server] (MSC service thread 1-12) !!!DelegatingClassFileTransformer.addTransformer org.jboss.as.jpa.classloader.JPADelegatingClassFileTransformer@292fabca

3.  11:59:57,082 INFO  [org.jboss.as.jpa] (MSC service thread 1-12) !!!PersistenceUnitServiceHandler deployPersistenceUnit deployment phase=FIRST_MODULE_USE startEarly=

4. 1:59:57,246 INFO  [org.jboss.as.jsf] (MSC service thread 1-12) !!!JSFManagedBeanProcessor deployment phase=POST_MODULE, managedBean=tc.web.controller.settings.OrganizationConfigController, module classloader=ModuleClassLoader for Module "deployment.EnterpriseApplication1.ear.tcWeb.war:main" from Service Module Loader

5. 11:59:57,250 INFO  [org.jboss.as.jsf] (MSC service thread 1-12) !!!JSFManagedBeanProcessor deployment phase=POST_MODULE, managedBean=tc.web.controller.dashboard.indicator.FileDashboardController, module classloader=ModuleClassLoader for Module "deployment.EnterpriseApplication1.ear.tcWeb.war:main" from Service Module Loader

6.  11:59:57,251 TRACE [org.jboss.as.jpa] (MSC service thread 1-12) !!!JPADelegatingClassFileTransformer.transform tc/entities/type/PivotData

7.  11:59:58,260 TRACE [org.jboss.as.jpa] (ServerService Thread Pool -- 59) !!!PersistenceUnitMetadataImpl.addTransformer org.eclipse.persistence.internal.jpa.weaving.PersistenceWeaver@7dac508

1

Item #1 + #2 happens early enough, we add update the per deployment module setting by calling DelegatingClassFileTransformer.addTransformer to add the JPADelegatingClassFileTransformer.  JPADelegatingClassFileTransformer will help handle tranforming/weaving of classes.  This is just an initial step though, the persistence provider (EclipseLink) needs to register with the JPADelegatingClassFileTransformer.

Item #3 is where we start the persistence unit service that will call the EclipseLink Provider.createContainerEntityManagerFactory().  We are starting the persistence unit service asynchrounously.  We mark that the next deployment phase shouldn't start until the persistence unit service is started (phaseContext.addToAttachmentList(Attachments.NEXT_PHASE_DEPS, puServiceName)).  I am starting to wonder if NEXT_PHASE_DEPS works for asynchronous services.

Item #4 + #5 is showing that the next deployment phase (POST_MODULE) has started and JSFManagedBeanProcessor is about to start loading managed bean classes associated with the web deployment part of the ear.

Item #6 is showing that the registered JPADelegatingClassFileTransformer callback has been called for an entity class that is referenced by a managed bean.

Item #7 is showing that the persistence unit is finally in the EclipseLink provider code and EclipseLink has registered its weaving class enhancer (too late for many of the entities that are already loaded now).

How is your appetite for hacking more code to debug further?  At some point, it might be easier to either come up with a test case that reproduces the issue or a unit test.  For the unit test side, I started some changes on https://github.com/scottmarlow/wildfly/tree/eclipselinkweaving which aren't correct yet (got the wrong warning and need jsf classes).

Scott

[jspies2]

Scott - I can continue and make any changes you suggest.  I'm building it on a command line with only a text editor right now since netbeans wouldn't check out the project correctly.  I can either try eclipse to help, or just make pointed changes as I have been doing.

I can also try to create a sample EAR with war and ejb-module that reproduces the problem too if that would help.  Just let me know.

[smarlow]

I posted on the wildfly-dev mailing list about what I mentioned above for #3.  If I am correct, I think that we are going to need a way to internally signal, when asynchronous services have started in the background, to delay starting the next deployment phase (see #4 + #5) until the persistence unit is deployed (EclipseLink weaving will be complete).

One quick thought is adding yet another deployment service that the async service depends on and that waits for the async service to signal it.

If you can verify the fix when we have it, that would be great.  If you feel like creating a test case, that is cool also.  If you want to help hack on the fix, let me know that as well (you have been very helpful so far, which is greatly appreciated!).

I've done the text editor thing, not fun.  I know that Intellij has a way to create a new project from a maven pom.xml.  That is easy to use.  I think that Eclipse probably does the same.  https://community.jboss.org/wiki/HackingOn has some tips on working with hacking on the WildFly source (sounds like you are mostly there).  https://community.jboss.org/wiki/HackingAS7UsingEclipse  might be outdated but talks about using Eclipse to load a project (there might be a better way now than using the M2E plugin).

If you like using the text editor.  You might like using the JDB debugger, which doesn't require source code for debugging (you just need to know class method names and line numbers generally).

Scott

[smarlow]

Hi Jason,

Could you add some more logging?

In org.jboss.as.jpa.service.PersistenceUnitServiceImpl.start(), please add the following after the call to context.complete():

persistenceUnitRegistry.add(getScopedPersistenceUnitName(), getValue());

context.complete();

JPA_LOGGER.trace("!!!PersistenceUnitServiceImpl startcontext marked complete");

Also in the same class (PersistenceUnitServiceImpl), please update method createContainerEntityManagerFactory() to have an additional trace in the finally clause:

JPA_LOGGER.trace("!!!completed createContainerEntityManagerFactory");

persistenceProviderAdaptor.afterCreateContainerEntityManagerFactory(pu);

Thanks,

Scott

[jspies2]

Hey Scott - Sorry for the delay.  I will get you this today.

[smarlow]

Hi Jason,

No rush.  I think the additional trace logging will help answer some questions as to what is wrong, with regard to timing and better identify where code changes are needed.

Scott