[jspies2]

I tried the build and unfortunately didn't have any luck.  I tried with both <property name="eclipselink.deploy-on-startup" value="true" /> there and not.  I'm not sure if it has anything to do with the update or not, but it did push most of the Revert warnings to the bottom of the log compared to previously.

[smarlow]

Jason,

According to https://wiki.eclipse.org/EclipseLink/UserGuide/JPA/Advanced_JPA_Development/Performance/Weaving/Dynamic_Weaving+http://stackoverflow.com/questions/18307579/jpa-weaving-not-enabled-while-running-test-cases/18360167#18360167, you also need to use -javaagent:eclipselink.jar.

I'm not yet sure of the impact of having the EclipseLink jar be loaded as a javaagent.  I think the underlying question is whether the rewritten entity classes will have any class references to (javaagent loaded) EclipseLink jar.  Which will be a different (EclipseLink) classloader than is later used for deploying the application.

Try the javaagent option and let us know how that goes.

[smarlow]

I created WFLY-3482 for the ordering code change that is needed to ensure that the ClassFileTransformer is always registered before it is referenced by the persistence provider.  Will be interesting to see if the EclipseLink javaagent works for you.

[jspies2]

Hey Scott-

I added the java agent but am now receiving other errors on startup shown below.  It looks like that option may be for Java SE environments and EE environments are supposed to support it automatically.  Also found it interesting that the Eclipselink JPA FAQ (which may be outdated) states that JBOSS does not allow weaving:

https://wiki.eclipse.org/EclipseLink/FAQ/JPA

In a Java EE environment weaving is enabled by default (on any JEE EJB 3.0 fully compliant app server, Weblogic, Webspehere, Glassfish. JBoss does not allow weaving so you must use static weaving or Spring).

One other thing to note that I find very interesting, is that prior to the code changes you committed, I would sometimes get different amounts of the Revert warnings, and the ones that didn't get the warnings actually worked correctly.  If i deployed enough times, over and over again, I would randomly hit a time when I would get 0 warnings and the app would work as expected.  After the code changes committed, I always get 65 Revert warnings, no matter how many times I redeploy which is all of the relationships that could be reverted.  It seems that the code change did effect the outcome, but now makes it always occur instead of being random.  Is there a chance that you added an order to loading something, that maybe got switched around or should be the other way?  Thanks again!

javaagent error below:

FATAL ERROR in native method: processing of -javaagent failed

Press any key to continue . . . java.lang.reflect.InvocationTargetException

  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)

  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

  at java.lang.reflect.Method.invoke(Method.java:606)

  at sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:382)

  at sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:397)

Caused by: java.lang.NoClassDefFoundError: javax/persistence/spi/PersistenceUnitInfo

  at java.lang.Class.forName0(Native Method)

  at java.lang.Class.forName(Class.java:190)

  at org.eclipse.persistence.internal.jpa.deployment.JavaSECMPInitializerAgent.initializeFromAgent(JavaSECMPInitializerAgent.java:44)

  at org.eclipse.persistence.internal.jpa.deployment.JavaSECMPInitializerAgent.premain(JavaSECMPInitializerAgent.java:39)

  ... 6 more

Caused by: java.lang.ClassNotFoundException: javax.persistence.spi.PersistenceUnitInfo

  at java.net.URLClassLoader$1.run(URLClassLoader.java:366)

  at java.net.URLClassLoader$1.run(URLClassLoader.java:355)

  at java.security.AccessController.doPrivileged(Native Method)

  at java.net.URLClassLoader.findClass(URLClassLoader.java:354)

  at java.lang.ClassLoader.loadClass(ClassLoader.java:425)

  at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:308)

  at java.lang.ClassLoader.loadClass(ClassLoader.java:358)

  ... 10 more

Exception in thread "main"

[smarlow]

Sounds like we shouldn't need the javaagent.  Could you try setting a breakpoint in org.jboss.as.jpa.classloader.JPADelegatingClassFileTransformer.transform(ClassLoader classLoader, String className, Class<?> aClass, ProtectionDomain protectionDomain, byte[] originalBuffer) and see if that is reached?

I think that the EclipseLink documentation is talking about older versions of the JBoss application server, when they say that JBoss doesn't work with "dynamic weaving". 

One other thing to note that I find very interesting, is that prior to the code changes you committed, I would sometimes get different amounts of the Revert warnings, and the ones that didn't get the warnings actually worked correctly.  If i deployed enough times, over and over again, I would randomly hit a time when I would get 0 warnings and the app would work as expected.  After the code changes committed, I always get 65 Revert warnings, no matter how many times I redeploy which is all of the relationships that could be reverted.  It seems that the code change did effect the outcome, but now makes it always occur instead of being random.  Is there a chance that you added an order to loading something, that maybe got switched around or should be the other way?  Thanks again!

Could be interesting to set a breakpoint on org.jboss.as.server.deployment.module.DelegatingClassFileTransformer.addTransformer(ClassFileTransformer) to verify if that is happening as expected. 

Instead of debugging, another approach could be adding more TRACE logging to let us know when we reach the above methods.

[jspies2]

I'll try and add some more logging.  I tried to set breakpoints but Netbeans was having all sorts of issues compiling.  I may try to use Eclipse to see if that works better.

I did find:  https://access.redhat.com/site/solutions/502083

The content is behind a subscription so I can't see it, but wasn't sure if it had any helpful information or now.  It may even be more relevant to me since we are potentially heading down the EAP Subscription path instead of Wildfly which may be quite a bit different for running Eclipselink.

[smarlow]

Adding logging should be the easiest.  I'd like to understand if we reach the org.jboss.as.server.deployment.module.DelegatingClassFileTransformer.addTransformer(ClassFileTransformer) initially, which should be passed a org.jboss.as.jpa.classloader.JPADelegatingClassFileTransformer instance. 

The org.jboss.as.jpa.classloader.JPADelegatingClassFileTransformer.transform(ClassLoader classLoader, String className, Class<?> aClass, ProtectionDomain protectionDomain, byte[] originalBuffer) method should be invoked for each entity class that needs to be "weaved" by EclipseLink.  So, adding trace to that should be helpful.

Also, adding TRACE logging to org.jboss.as.jpa.config.PersistenceUnitMetadataImpl.addTransformer(ClassTransformer) will tell us when EclipseLink added its "weaving" class transformer. 

Example of adding TRACE logging to a class method:

import static org.jboss.as.jpa.messages.JpaLogger.ROOT_LOGGER;

.

.

.

  ROOT_LOGGER.trace("PersistenceUnitMetadataImpl.addTransformer " + classTransformer);

or

  ROOT_LOGGER.tracef("PersistenceUnitMetadataImpl.addTransformer %s", classTransformer);

[jspies2]

Thanks Scott, I'll try this out tomorrow and report back with the log.

[smarlow]

Let me know if you have problems with adding the trace logging.  I also made a few changes to the (simple) EclipseLink unit test that is now reproducing the "weaving" problem also (server.log contains "2014-06-12 10:48:56,769 INFO  [org.eclipse.persistence.weaver] (ServerService Thread Pool -- 50) Class org.jboss.as.test.compat.jpa.eclipselink.Company could not be weaved for change tracking as it is not supported by its mappings."). 

I pushed the unit test change to https://github.com/scottmarlow/wildfly/tree/eclipselinkweaving and included the ClassFileTransformer ordering fix.

I'll sit back and wait for you to make progress with the trace logging.

[smarlow]

Also, you can use grep to filter out the non-JPA messages if you like before attaching the log.  Something like "grep orb.joss.as.jpa server.log > jpa.log".

For attaching the log, click on "use advanced editor" and look for "file attach" at bottom of page.

[jspies2]

I'm working from a text editor to add the logging, so have limited IDE help.  When I tried to import org.jboss.as.jpa.messages.JpaLogger.ROOT_LOGGER in to org.jboss.as.server.deployment.module.DelegatingClassFileTransformer I got an error that the package could not be found on build.  Instead, I imported org.jboss.as.server.logging.ServerLogger and logged as:

ServerLogger.ROOT_LOGGER.trace("!!!DelegatingClassFileTransformer " + classFileTransformer);

I then bumped up org.jboss.as.server to Trace logging as well (which added quite a bit of other logging obviously).

I added logging to the three methods you mentioned, all with !!!.  So in the logs there should be:

!!!DelegatingClassFileTransformer.addTransformer

!!!JPADelegatingClassFileTransformer.transform

!!!PersistenceUnitMetadataImpl.addTransformer

Please let me know if you need anything else. Thanks!

[smarlow]

Thanks Jason, I will take a look.  I'm glad you figured out the right imports.  In your next test, you might also want to include TRACE logging for "org.eclipse.persistence.weaver".

[smarlow]

It looks like the JPADelegatingClassFileTransformer, is correct registered early enough to do its work but something is then reading the application classes before EclipseLink has had a change to register its classfiletransformer.  Interesting output.

1.  JPADelegatingClassFileTransformer is registered first to be invoked when any application class is loaded.

15:15:14,433 TRACE [org.jboss.as.server] (MSC service thread 1-3) !!!DelegatingClassFileTransformer org.jboss.as.jpa.classloader.JPADelegatingClassFileTransformer@402faf58

.

.

.

15:15:14,724 TRACE [org.jboss.as.server] (MSC service thread 1-2) !!!DelegatingClassFileTransformer org.jboss.as.jpa.classloader.JPADelegatingClassFileTransformer@39ce0811

2.  We can see that application classes are being loaded but not sure why as its too early. 

15:15:15,387 TRACE [org.jboss.as.jpa] (MSC service thread 1-7) !!!JPADelegatingClassFileTransformer.transform tc/entities/type/PivotData

15:15:15,389 TRACE [org.jboss.as.jpa] (MSC service thread 1-7) !!!JPADelegatingClassFileTransformer.transform tc/entities/type/Attribute

15

.

.

.

3.  We then see that the EclipseLink classfiletransformer is added too late.

15:15:17,699 TRACE [org.jboss.as.jpa] (ServerService Thread Pool -- 57) !!!PersistenceUnitMetadataImpl.addTransformer org.eclipse.persistence.internal.jpa.weaving.PersistenceWeaver@75bb5bfe

15

Could you add one more line to the JPADelegatingClassFileTransformer class?  In the transform method, call java.lang.Thread.dumpStack() right before logging the other information.  This will show us what is loading the application class before the JPA persistence unit service has been created. 

[jspies2]

I'll get something up a bit later tonight. Thanks!

[jspies2]

The log is quite large with the multiple stack traces, but is attached.  I added the stack trace right before the logger. I also set org.eclipse.persistence.weaver  to trace logging in it if that is helpful.  Here is one of them below.

2014-06-12 17:31:06,822 ERROR [stderr] (MSC service thread 1-4) java.lang.Exception: Stack trace

2014-06-12 17:31:06,823 ERROR [stderr] (MSC service thread 1-4) at java.lang.Thread.dumpStack(Thread.java:1365)

2014-06-12 17:31:06,823 ERROR [stderr] (MSC service thread 1-4) at org.jboss.as.jpa.classloader.JPADelegatingClassFileTransformer.transform(JPADelegatingClassFileTransformer.java:48)

2014-06-12 17:31:06,824 ERROR [stderr] (MSC service thread 1-4) at org.jboss.as.server.deployment.module.DelegatingClassFileTransformer.transform(DelegatingClassFileTransformer.java:63)

2014-06-12 17:31:06,824 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ModuleClassLoader.defineClass(ModuleClassLoader.java:474)

2014-06-12 17:31:06,825 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ModuleClassLoader.loadClassLocal(ModuleClassLoader.java:277)

2014-06-12 17:31:06,825 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ModuleClassLoader$1.loadClassLocal(ModuleClassLoader.java:92)

2014-06-12 17:31:06,825 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.Module.loadModuleClass(Module.java:568)

2014-06-12 17:31:06,826 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ModuleClassLoader.findClass(ModuleClassLoader.java:205)

2014-06-12 17:31:06,826 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ConcurrentClassLoader.performLoadClassUnchecked(ConcurrentClassLoader.java:459)

2014-06-12 17:31:06,826 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ConcurrentClassLoader.performLoadClassChecked(ConcurrentClassLoader.java:408)

2014-06-12 17:31:06,827 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ConcurrentClassLoader.performLoadClass(ConcurrentClassLoader.java:389)

2014-06-12 17:31:06,827 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ConcurrentClassLoader.loadClass(ConcurrentClassLoader.java:134)

2014-06-12 17:31:06,827 ERROR [stderr] (MSC service thread 1-4) at java.lang.ClassLoader.defineClass1(Native Method)

2014-06-12 17:31:06,828 ERROR [stderr] (MSC service thread 1-4) at java.lang.ClassLoader.defineClass(ClassLoader.java:800)

2014-06-12 17:31:06,828 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ModuleClassLoader.doDefineOrLoadClass(ModuleClassLoader.java:361)

2014-06-12 17:31:06,874 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ModuleClassLoader.defineClass(ModuleClassLoader.java:482)

2014-06-12 17:31:06,874 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ModuleClassLoader.loadClassLocal(ModuleClassLoader.java:277)

2014-06-12 17:31:06,874 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ModuleClassLoader$1.loadClassLocal(ModuleClassLoader.java:92)

2014-06-12 17:31:06,875 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.Module.loadModuleClass(Module.java:568)

2014-06-12 17:31:06,875 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ModuleClassLoader.findClass(ModuleClassLoader.java:205)

2014-06-12 17:31:06,875 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ConcurrentClassLoader.performLoadClassUnchecked(ConcurrentClassLoader.java:459)

2014-06-12 17:31:06,876 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ConcurrentClassLoader.performLoadClassChecked(ConcurrentClassLoader.java:408)

2014-06-12 17:31:06,876 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ConcurrentClassLoader.performLoadClass(ConcurrentClassLoader.java:389)

2014-06-12 17:31:06,876 ERROR [stderr] (MSC service thread 1-4) at org.jboss.modules.ConcurrentClassLoader.loadClass(ConcurrentClassLoader.java:134)

2014-06-12 17:31:06,877 ERROR [stderr] (MSC service thread 1-4) at java.lang.Class.getDeclaredConstructors0(Native Method)

2014-06-12 17:31:06,877 ERROR [stderr] (MSC service thread 1-4) at java.lang.Class.privateGetDeclaredConstructors(Class.java:2493)

2014-06-12 17:31:06,877 ERROR [stderr] (MSC service thread 1-4) at java.lang.Class.getConstructor0(Class.java:2803)

2014-06-12 17:31:06,878 ERROR [stderr] (MSC service thread 1-4) at java.lang.Class.getConstructor(Class.java:1718)

2014-06-12 17:31:06,878 ERROR [stderr] (MSC service thread 1-4) at org.jboss.as.jsf.deployment.JSFManagedBeanProcessor.deploy(JSFManagedBeanProcessor.java:100)

2014-06-12 17:31:06,879 ERROR [stderr] (MSC service thread 1-4) at org.jboss.as.server.deployment.DeploymentUnitPhaseService.start(DeploymentUnitPhaseService.java:156)

2014-06-12 17:31:06,879 ERROR [stderr] (MSC service thread 1-4) at org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:1948)

2014-06-12 17:31:06,879 ERROR [stderr] (MSC service thread 1-4) at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1881)

2014-06-12 17:31:06,880 ERROR [stderr] (MSC service thread 1-4) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

2014-06-12 17:31:06,880 ERROR [stderr] (MSC service thread 1-4) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

2014-06-12 17:31:06,880 ERROR [stderr] (MSC service thread 1-4) at java.lang.Thread.run(Thread.java:745)

2014-06-12 17:31:06,881 TRACE [org.jboss.as.jpa] (MSC service thread 1-4) !!!JPADelegatingClassFileTransformer.transform tc/entities/type/Alertable