Issue Details (XML | Word | Printable)

Key: NUCCORE-985
Type: Task Task
Status: Closed Closed
Resolution: Fixed
Priority: Major Major
Assignee: Unassigned
Reporter: Andy Jefferson
Votes: 0
Watchers: 1
Operations

If you were logged in you would be able to see more operations.
DataNucleus Core

When calling ExecutionContext.close on JTA transaction only check the "active" flag (i.e don't trigger rejoin)

Created: 20/Jan/13 12:12 PM   Updated: 04/Feb/13 07:13 PM   Resolved: 27/Jan/13 05:14 PM
Component/s: Transactions
Affects Version/s: None
Fix Version/s: 3.2.0.m3


Andy Jefferson added a comment - 20/Jan/13 12:12 PM
SVN trunk handles this now

Andy Jefferson made changes - 20/Jan/13 12:12 PM
Field Original Value New Value
Status Open [ 1 ] Resolved [ 5 ]
Resolution Fixed [ 1 ]
Andy Jefferson made changes - 21/Jan/13 07:51 PM
Status Resolved [ 5 ] Closed [ 6 ]
nicolas added a comment - 27/Jan/13 04:50 PM
See NUCACCESS-109, the fix does not solve the afterCompletion() call.

Andy Jefferson made changes - 27/Jan/13 05:14 PM
Resolution Fixed [ 1 ]
Status Closed [ 6 ] Reopened [ 4 ]
Andy Jefferson made changes - 27/Jan/13 05:14 PM
Status Reopened [ 4 ] Resolved [ 5 ]
Resolution Fixed [ 1 ]
nicolas added a comment - 27/Jan/13 05:29 PM
ExecutionContextImpl.java, line 359:
jtaTx {com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple@730} value is "TransactionImple < ac, BasicAction: 0:ffffc0a83801:68a1d22c:51055004:13 status: ActionStatus.COMMITTED >"
joinStatus {org.datanucleus.JTATransactionImpl$JoinStatus@820} = "JOINED"

internal closed flag is "false".

line 363, if(tx.getIsActive())

TransactionImpl, the flag is active = "true".


It is a wild shot but it looks like the ExecutionContextImpl.java is called BEFORE TransactionImpl:
 protected void internalPostCommit()

And that is the logical place that sets the active flag to false.

To sum up... the ExecutionContextImpl.close() is called first, this throws an exception. Then arjuna invokes the JTATransactionImpl.afterCompletion() which invoked the super.internalPostCommit().

Any tips? I dont know when I will have time to work on this. My work schedule is sort of hectic...


Andy Jefferson added a comment - 27/Jan/13 05:34 PM
You said previously that afterCompletion was called with some status flag, so where does that feature in your wild shot?
If JBoss is indeed calling EC.close before afterCompletion is called on the transaction (that is owned by the EC) then ask JBoss why they are calling EC.close (EM.close) before it has called afterCompletion() on the transaction.

Makes no sense to me, but then containers make little sense to me either...

nicolas added a comment - 27/Jan/13 05:42 PM
Partial thread dump:
http-/127.0.0.1:8080-63@251, prio=5, in group 'main', status: 'RUNNING'
at org.datanucleus.ExecutionContextImpl.close(ExecutionContextImpl.java:363)
at org.datanucleus.api.jpa.JPAEntityManager.close(JPAEntityManager.java:194)
at org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization.afterCompletion(TransactionUtil.java:193)
at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion(SynchronizationImple.java:96)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:402)

The arjuna two phase coordinator afterCompletion is invoked... This then call the JPAEntityManager.close() ...

I could try asking them.. my guess is that has something to do with some specs....

Note that removing in ExecutionContextImpl line 363:
       if (tx.getIsActive())
        {
            throw new TransactionActiveOnCloseException(this);
        }
would solve the problem when running in the container...


Thread dump:
http-/127.0.0.1:8080-63@251, prio=5, in group 'main', status: 'RUNNING'
at org.datanucleus.ExecutionContextImpl.close(ExecutionContextImpl.java:363)
at org.datanucleus.api.jpa.JPAEntityManager.close(JPAEntityManager.java:194)
at org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization.afterCompletion(TransactionUtil.java:193)
at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion(SynchronizationImple.java:96)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:402)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:103)
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1165)
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:91)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:252)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.requiresNew(CMTTxInterceptor.java:344)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:216)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165)
at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:182)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72)
at data.LocalSBDao$$$view3.createCompany(Unknown Source:-1)
at loader.MyLoader.createACompanyWithEmployee(MyLoader.java:74)
at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)
at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:58)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)
at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:58)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:235)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.notSupported(CMTTxInterceptor.java:299)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:212)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165)
at org.jboss.as.webservices.invocation.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:111)
at org.jboss.wsf.stack.cxf.JBossWSInvoker.performInvocation(JBossWSInvoker.java:149)
at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96)
at org.apache.cxf.jaxws.AbstractJAXWSMethodInvoker.invoke(AbstractJAXWSMethodInvoker.java:178)
at org.apache.cxf.jaxws.JAXWSMethodInvoker.invoke(JAXWSMethodInvoker.java:66)
at org.jboss.wsf.stack.cxf.JBossWSInvoker.invoke(JBossWSInvoker.java:129)
at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:58)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at org.apache.cxf.workqueue.SynchronousExecutor.execute(SynchronousExecutor.java:37)
at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:107)
at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:262)
at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121)
at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:237)
at org.jboss.wsf.stack.cxf.RequestHandlerImpl.handleHttpRequest(RequestHandlerImpl.java:95)
at org.jboss.wsf.stack.cxf.transport.ServletHelper.callRequestHandler(ServletHelper.java:156)
at org.jboss.wsf.stack.cxf.CXFServletExt.invoke(CXFServletExt.java:87)
at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:225)
at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doPost(AbstractHTTPServlet.java:145)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:754)
at org.jboss.wsf.stack.cxf.CXFServletExt.service(CXFServletExt.java:135)
at org.jboss.wsf.spi.deployment.WSFServlet.service(WSFServlet.java:140)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:295)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:149)
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:145)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:336)
at org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:350)
at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:902)
at org.apache.tomcat.util.net.NioEndpoint$ChannelProcessor.run(NioEndpoint.java:1031)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)

Andy Jefferson added a comment - 27/Jan/13 06:01 PM - edited
Obviously i'm not simply removing perfectly sensible code, and the real problem is why is the transaction still active and why hasn't the "container" called afterCompletion on it after it registered for synchronisation using "jtaTx.registerSynchronization(this)" when it joined to it.

Likely JBoss insist on the implementation calling TransactionSynchronizationRegistry.registerInterposedSynchronization(this);
which seemingly places the call to beforeCompletion/afterCompletion earlier in the sync callbacks. That is not implemented currently. Maybe JBoss is ignoring the JTA1.0 registration process now, or intends to call it after it has closed the EM. Anyway, unimplemented if that is the case

Andy Jefferson made changes - 27/Jan/13 07:51 PM
Comment [ Maybe JBoss require this TransactionSynchronizationRegistry.registerInterposedSynchronization(...) calling instead? but then why does JTA have two mechanisms for the same apparent thing, and would it work registering on both, or just one, or what? That question is general to JTA across all JTA implementations, what would work for all? ]
nicolas added a comment - 28/Jan/13 06:28 PM
Hi Andy,

Why do u think the Tx needs to have this flag active = true? This local variable bothers me. It should be sufficient to look at the JTA Tx and to see that it is in COMMITTED state to allow the em.close().


Andy Jefferson added a comment - 28/Jan/13 07:15 PM
JTATransactionImpl needs to keep an "active" flag to know if it has had the chance to commit the transaction contents. If afterCompletion is not run (which it seemingly isn't) then all is not well. Hence exception. QED.

PS I added TransactionSynchronizationRegistry.registerInterposedSynchronization(this); yesterday. No idea if it works with JBoss but then its in SVN trunk and nightly builds so easy enough for you to test (and provide patch updates should it not be optimised)

nicolas added a comment - 28/Jan/13 08:07 PM
" nightly builds so easy enough for you to test (and provide patch updates should it not be optimised)"
I promise to test it :)

When it comes to patches, this area/DN is quite new to me so finding a solution is not trivial. From what I read, this boolean flag seems dangerous, while the Tx (JtaTx ref) is more reliable. So overall, I I am not sure close() should verify if the Tx is active using this flag rather than check the status of the Tx from the JtaTx ref. Could you tell me where you find that this "active" flag is required?

BTW Scott Marlowe commented on the JBoss forums that JTA/persistence spec do not specify an order for EntityManager.close() and JTA Synchronization.afterCompletion(). I looked at the JTA Spec, but I could not find anything either.

Added a question on the JBoss Transactions Development forums (https://community.jboss.org/thread/220618).

nicolas added a comment - 28/Jan/13 08:51 PM
Tested with the latest source. Same error. Will try again with a nightly build (just in case).

20:48:50,013 FINE [DataNucleus.Query] (http-/127.0.0.1:8080-6) JPQL Query : Compiling "SELECT COUNT(c.id) FROM Company c WHERE c.name = :name"
20:48:50,032 FINE [DataNucleus.Query] (http-/127.0.0.1:8080-6) JPQL Query : Compile Time = 19 ms
20:48:50,033 FINE [DataNucleus.Query] (http-/127.0.0.1:8080-6) QueryCompilation:
  [result:InvokeExpression{STATIC.COUNT(PrimaryExpression{c.id})}]
  [from:ClassExpression(alias=c)]
  [filter:DyadicExpression{PrimaryExpression{c.name} = ParameterExpression{name}}]
  [symbols: c type=data.persist.Company, name type=java.lang.String]
20:48:50,034 FINE [DataNucleus.Query] (http-/127.0.0.1:8080-6) JPQL Query : Compiling "SELECT COUNT(c.id) FROM Company c WHERE c.name = :name" for datastore
20:48:50,047 FINE [DataNucleus.Query] (http-/127.0.0.1:8080-6) JPQL Query : Compile Time for datastore = 12 ms
20:48:50,047 FINE [DataNucleus.Query] (http-/127.0.0.1:8080-6) SELECT COUNT(c.id) FROM Company c WHERE c.name = :name Query compiled to datastore query "SELECT COUNT(`C`.`ID`) FROM `COMPANY` `C` WHERE `C`.`NAME` = ?"
20:48:50,048 FINE [DataNucleus.Persistence] (http-/127.0.0.1:8080-6) ExecutionContext.internalFlush() process started using ordered flush - 0 dirty objects
20:48:50,048 FINE [DataNucleus.Persistence] (http-/127.0.0.1:8080-6) ExecutionContext.internalFlush() process finished
20:48:50,048 FINE [DataNucleus.Query] (http-/127.0.0.1:8080-6) Query "SELECT COUNT(c.id) FROM Company c WHERE c.name = :name" of language "JPQL" has been run before so reusing existing generic compilation
20:48:50,049 FINE [DataNucleus.Query] (http-/127.0.0.1:8080-6) Query "SELECT COUNT(c.id) FROM Company c WHERE c.name = :name" of language "JPQL" for datastore "rdbms-mysql" has been run before so reusing existing datastore compilation
20:48:50,050 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,050 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionSynchronizationRegistryImple.getTransactionKey
20:48:50,050 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionSynchronizationRegistryImple.getTransactionKey
20:48:50,050 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionSynchronizationRegistryImple.getResource
20:48:50,050 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,050 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionSynchronizationRegistryImple.getTransactionKey
20:48:50,050 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionSynchronizationRegistryImple.getResource
20:48:50,051 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,051 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionSynchronizationRegistryImple.putResource
20:48:50,051 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,051 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionSynchronizationRegistryImple.getResource
20:48:50,051 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,051 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionSynchronizationRegistryImple.getTransactionKey
20:48:50,051 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionSynchronizationRegistryImple.getResource
20:48:50,051 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,051 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionSynchronizationRegistryImple.getResource
20:48:50,051 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,051 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionSynchronizationRegistryImple.putResource
20:48:50,051 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,051 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) BaseTransaction.getStatus
20:48:50,051 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,052 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionSynchronizationRegistryImple.registerInterposedSynchronization
20:48:50,052 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,053 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.enlistResource ( LocalXAResourceImpl@4c1f9e24[connectionListener=155d3125 connectionManager=2fc77487 warned=false currentXid=null productName=MySQL productVersion=5.2.13-MariaDB jndiName=java:/jdbc/simple] )
20:48:50,053 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,053 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) InputObjectState::InputObjectState()
20:48:50,053 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid : 0:0:0:0:0
InputObjectState Type : null
InputObjectState Size : 0
InputObjectState Buffer: , -1)
20:48:50,053 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) OutputObjectState::OutputObjectState()
20:48:50,054 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) FileSystemStore.read_committed(0:ffffc0a83801:-3bbd39cb:50f04dbf:13, EISNAME)
20:48:50,054 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) ShadowingStore.read_state(0:ffffc0a83801:-3bbd39cb:50f04dbf:13, EISNAME, StateType.OS_ORIGINAL)
20:48:50,054 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) ShadowingStore.genPathName(0:ffffc0a83801:-3bbd39cb:50f04dbf:13, EISNAME, StateType.OS_SHADOW)
20:48:50,054 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) FileSystemStore.genPathName(0:ffffc0a83801:-3bbd39cb:50f04dbf:13, EISNAME, 10)
20:48:50,054 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) ShadowingStore.genPathName(0:ffffc0a83801:-3bbd39cb:50f04dbf:13, EISNAME, StateType.OS_ORIGINAL)
20:48:50,054 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) FileSystemStore.genPathName(0:ffffc0a83801:-3bbd39cb:50f04dbf:13, EISNAME, 11)
20:48:50,054 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) ShadowingStore.currentState(0:ffffc0a83801:-3bbd39cb:50f04dbf:13, EISNAME) - returning StateStatus.OS_COMMITTED
20:48:50,054 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) ShadowingStore.genPathName(0:ffffc0a83801:-3bbd39cb:50f04dbf:13, EISNAME, StateType.OS_ORIGINAL)
20:48:50,054 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) FileSystemStore.genPathName(0:ffffc0a83801:-3bbd39cb:50f04dbf:13, EISNAME, 11)
20:48:50,055 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) FileSystemStore.openAndLock(E:\tools\jboss\jboss-as-7.2.0.Alpha1-SNAPSHOT\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83801_-3bbd39cb_50f04dbf_13, FileLock.F_RDLCK, false)
20:48:50,055 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) InputObjectState::InputObjectState(0:ffffc0a83801:-3bbd39cb:50f04dbf:13, EISNAME)
20:48:50,055 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) FileSystemStore.closeAndUnlock(E:\tools\jboss\jboss-as-7.2.0.Alpha1-SNAPSHOT\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83801_-3bbd39cb_50f04dbf_13, java.io.FileInputStream@7369469e, null)
20:48:50,055 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) FileSystemStore.read_committed(0:ffffc0a83801:701356c4:50f0697c:11, EISNAME)
20:48:50,055 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) ShadowingStore.read_state(0:ffffc0a83801:701356c4:50f0697c:11, EISNAME, StateType.OS_ORIGINAL)
20:48:50,055 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) ShadowingStore.genPathName(0:ffffc0a83801:701356c4:50f0697c:11, EISNAME, StateType.OS_SHADOW)
20:48:50,055 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) FileSystemStore.genPathName(0:ffffc0a83801:701356c4:50f0697c:11, EISNAME, 10)
20:48:50,055 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) ShadowingStore.genPathName(0:ffffc0a83801:701356c4:50f0697c:11, EISNAME, StateType.OS_ORIGINAL)
20:48:50,055 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) FileSystemStore.genPathName(0:ffffc0a83801:701356c4:50f0697c:11, EISNAME, 11)
20:48:50,056 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) ShadowingStore.currentState(0:ffffc0a83801:701356c4:50f0697c:11, EISNAME) - returning StateStatus.OS_COMMITTED
20:48:50,056 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) ShadowingStore.genPathName(0:ffffc0a83801:701356c4:50f0697c:11, EISNAME, StateType.OS_ORIGINAL)
20:48:50,056 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) FileSystemStore.genPathName(0:ffffc0a83801:701356c4:50f0697c:11, EISNAME, 11)
20:48:50,056 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) FileSystemStore.openAndLock(E:\tools\jboss\jboss-as-7.2.0.Alpha1-SNAPSHOT\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83801_701356c4_50f0697c_11, FileLock.F_RDLCK, false)
20:48:50,056 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) InputObjectState::InputObjectState(0:ffffc0a83801:701356c4:50f0697c:11, EISNAME)
20:48:50,056 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) FileSystemStore.closeAndUnlock(E:\tools\jboss\jboss-as-7.2.0.Alpha1-SNAPSHOT\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83801_701356c4_50f0697c_11, java.io.FileInputStream@49b6a44, null)
20:48:50,058 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) StateManager::StateManager( 0:0:0:0:1 )
20:48:50,059 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) AbstractRecord::AbstractRecord (0:0:0:0:1)
20:48:50,059 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) LastResourceRecord()
20:48:50,060 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/LastResourceRecord for 0:0:0:0:1
20:48:50,060 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) BaseTransaction.getStatus
20:48:50,060 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,060 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) BaseTransaction.getStatus
20:48:50,061 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,061 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) BaseTransaction.getStatus
20:48:50,061 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,061 FINE [DataNucleus.Query] (http-/127.0.0.1:8080-6) JPQL Query : Executing "SELECT COUNT(c.id) FROM Company c WHERE c.name = :name" ...
20:48:50,062 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) BaseTransaction.getStatus
20:48:50,062 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,064 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) BaseTransaction.getStatus
20:48:50,064 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,070 FINE [DataNucleus.Query] (http-/127.0.0.1:8080-6) JPQL Query : Execution Time = 9 ms
20:48:50,071 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,071 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,071 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionSynchronizationRegistryImple.getResource
20:48:50,071 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,071 DEBUG [org.jboss.as.jpa] (http-/127.0.0.1:8080-6) http-/127.0.0.1:8080-6:[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffffc0a83801:-43fbb4e3:5106d5f1:b status: ActionStatus.RUNNING >
20:48:50,072 FINE [DataNucleus.Persistence] (http-/127.0.0.1:8080-6) Making object persistent : "data.persist.Company@37959c9d"
20:48:50,073 FINE [DataNucleus.Transaction] (http-/127.0.0.1:8080-6) Object "data.persist.Company@37959c9d" (id="org.datanucleus.identity.IdentityReference@3884be12") enlisted in transactional cache
20:48:50,098 FINE [DataNucleus.Persistence] (http-/127.0.0.1:8080-6) Object "data.persist.Company@37959c9d" has been marked for persistence but its actual persistence to the datastore will be delayed due to use of optimistic transactions or "delayDatastoreOperationsUntilCommit"
20:48:50,099 TRACE [org.jboss.as.jpa] (http-/127.0.0.1:8080-6) persist entityClass 'data.persist.Company' took 28ms
20:48:50,099 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,099 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) BaseTransaction.commit
20:48:50,099 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.commitAndDisassociate
20:48:50,099 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) SynchronizationImple.beforeCompletion
20:48:50,099 FINE [DataNucleus.Transaction] (http-/127.0.0.1:8080-6) Transaction committing for ExecutionContext org.datanucleus.ExecutionContextImpl@64148ad0
20:48:50,099 FINE [DataNucleus.Persistence] (http-/127.0.0.1:8080-6) ExecutionContext.internalFlush() process started using ordered flush - 1 dirty objects
20:48:50,103 FINE [DataNucleus.Persistence] (http-/127.0.0.1:8080-6) Object "data.persist.Company@37959c9d" being inserted into table "`COMPANY`"
20:48:50,104 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) BaseTransaction.getStatus
20:48:50,104 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,104 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) BaseTransaction.getStatus
20:48:50,104 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,105 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) BaseTransaction.getStatus
20:48:50,105 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,105 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) BaseTransaction.getStatus
20:48:50,105 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,107 FINE [DataNucleus.Transaction] (http-/127.0.0.1:8080-6) Object "data.persist.Company@37959c9d" (id="org.datanucleus.identity.IdentityReference@3884be12") enlisted in transactional cache is now enlisted using id="data.persist.Company:15"
20:48:50,108 FINE [DataNucleus.Persistence] (http-/127.0.0.1:8080-6) Insert of object "data.persist.Company@37959c9d" is calling insertPostProcessing for field "data.persist.Company.employees"
20:48:50,108 FINE [DataNucleus.Persistence] (http-/127.0.0.1:8080-6) Insert of object "data.persist.Company@37959c9d" is calling postInsert for field "data.persist.Company.employees"
20:48:50,109 FINE [DataNucleus.Persistence] (http-/127.0.0.1:8080-6) Field "data.persist.Company.employees" is being persisted for "cascade-persist".
20:48:50,109 FINE [DataNucleus.Persistence] (http-/127.0.0.1:8080-6) Object "data.persist.Company@37959c9d" field "employees" is replaced by a SCO wrapper of type "org.datanucleus.store.types.backed.Set" [cache-values=true, lazy-loading=false, queued-operations=false, allow-nulls=false]
20:48:50,109 FINE [DataNucleus.Persistence] (http-/127.0.0.1:8080-6) Object "data.persist.Company@37959c9d" field "employees" loading contents to SCO wrapper from the datastore
20:48:50,110 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) BaseTransaction.getStatus
20:48:50,110 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,110 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) BaseTransaction.getStatus
20:48:50,110 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) TransactionImple.getStatus
20:48:50,111 FINE [DataNucleus.Persistence] (http-/127.0.0.1:8080-6) ExecutionContext.internalFlush() process finished
20:48:50,112 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) SynchronizationImple.beforeCompletion
20:48:50,112 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) SynchronizationImple.beforeCompletion
20:48:50,112 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) BasicAction::End() for action-id 0:ffffc0a83801:-43fbb4e3:5106d5f1:b
20:48:50,112 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) BasicAction::onePhaseCommit() for action-id 0:ffffc0a83801:-43fbb4e3:5106d5f1:b
20:48:50,112 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) LastResourceRecord::topLevelPrepare() for 0:0:0:0:1
20:48:50,116 TRACE [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-6) LastResourceRecord::topLevelCommit() for 0:0:0:0:1
20:48:50,116 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) SynchronizationImple.afterCompletion
20:48:50,116 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) SynchronizationImple.afterCompletion
20:48:50,116 DEBUG [org.jboss.as.jpa] (http-/127.0.0.1:8080-6) http-/127.0.0.1:8080-6:[transaction scoped EntityManager]: closing entity managersession
20:48:50,117 WARN [com.arjuna.ats.jta] (http-/127.0.0.1:8080-6) ARJUNA016029: SynchronizationImple.afterCompletion - failed for org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization@d287be4 with exception: javax.persistence.PersistenceException: Transaction is still active. You should always close your transactions correctly using commit() or rollback().
at org.datanucleus.api.jpa.NucleusJPAHelper.getJPAExceptionForNucleusException(NucleusJPAHelper.java:414) [datanucleus-api-jpa-3.2.0-m3-SNAPSHOT.jar:]
at org.datanucleus.api.jpa.JPAEntityManager.close(JPAEntityManager.java:198) [datanucleus-api-jpa-3.2.0-m3-SNAPSHOT.jar:]
at org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization.afterCompletion(TransactionUtil.java:193) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion(SynchronizationImple.java:96)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:402)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:103)
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1165)
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:91) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:252) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.requiresNew(CMTTxInterceptor.java:344) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:216) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:182) [jboss-as-ee-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72) [jboss-as-ee-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at data.LocalSBDao$$$view3.createCompany(Unknown Source) [simple-jpa-0.0.1-SNAPSHOT.jar:]
at loader.MyLoader.createACompanyWithEmployee(MyLoader.java:74) [simple-jpa-0.0.1-SNAPSHOT.jar:]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_09]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_09]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_09]
at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_09]
at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:58) [jboss-as-ee-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:58) [jboss-as-ee-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:235) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.notSupported(CMTTxInterceptor.java:299) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:212) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54) [jboss-as-ejb3-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.webservices.invocation.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:111)
at org.jboss.wsf.stack.cxf.JBossWSInvoker.performInvocation(JBossWSInvoker.java:149)
at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96)
at org.apache.cxf.jaxws.AbstractJAXWSMethodInvoker.invoke(AbstractJAXWSMethodInvoker.java:178)
at org.apache.cxf.jaxws.JAXWSMethodInvoker.invoke(JAXWSMethodInvoker.java:66)
at org.jboss.wsf.stack.cxf.JBossWSInvoker.invoke(JBossWSInvoker.java:129)
at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:58)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_09]
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) [rt.jar:1.7.0_09]
at java.util.concurrent.FutureTask.run(FutureTask.java:166) [rt.jar:1.7.0_09]
at org.apache.cxf.workqueue.SynchronousExecutor.execute(SynchronousExecutor.java:37)
at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:107)
at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:262)
at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121)
at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:237)
at org.jboss.wsf.stack.cxf.RequestHandlerImpl.handleHttpRequest(RequestHandlerImpl.java:95)
at org.jboss.wsf.stack.cxf.transport.ServletHelper.callRequestHandler(ServletHelper.java:156)
at org.jboss.wsf.stack.cxf.CXFServletExt.invoke(CXFServletExt.java:87)
at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:225)
at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doPost(AbstractHTTPServlet.java:145)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:754) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.jboss.wsf.stack.cxf.CXFServletExt.service(CXFServletExt.java:135)
at org.jboss.wsf.spi.deployment.WSFServlet.service(WSFServlet.java:140) [jbossws-spi-2.1.1.Final.jar:2.1.1.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:295)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:149)
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:145)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:336)
at org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:350)
at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:902)
at org.apache.tomcat.util.net.NioEndpoint$ChannelProcessor.run(NioEndpoint.java:1031)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) [rt.jar:1.7.0_09]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) [rt.jar:1.7.0_09]
at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_09]
Caused by: org.datanucleus.exceptions.TransactionActiveOnCloseException: Transaction is still active. You should always close your transactions correctly using commit() or rollback().
at org.datanucleus.ExecutionContextImpl.close(ExecutionContextImpl.java:370) [datanucleus-core-3.2.0-m3-SNAPSHOT.jar:]
at org.datanucleus.api.jpa.JPAEntityManager.close(JPAEntityManager.java:194) [datanucleus-api-jpa-3.2.0-m3-SNAPSHOT.jar:]
... 113 more

Andy Jefferson added a comment - 28/Jan/13 09:04 PM
Was TransactionSynchronizationRegistry used to register the Synchronization? because then JBoss is supposed to process those first when doing the "afterCompletion" callbacks (at least before the ones that were registered on the JTA transaction itself).

No, "active" is not dangerous. JTATransactionImpl cannot simply return false based on some "txn status" without afterCompletion being called. If it isn't called the sh*t will hit the fan afterwards ... because the JDBC connection isn't closed and various other things won't be finished. Closing an EntityManager before sending such afterCompletion notices is simply weird (to me), after all it is the transaction of the EntityManager that asked for such a callback.

Obviously we could put some flag in there that says "oh this is JBoss and afterCompletion isn't yet called, so we'll leave the ExecutionContext open until the call finally comes through (assuming it does), and then when it does we get the JDBC connection closed, and we close the ExecutionContext ... but I'd like to avoid such ugly hacks.

nicolas added a comment - 29/Jan/13 11:35 AM
"Was TransactionSynchronizationRegistry used to register the Synchronization? "
I think so.
registry = (TransactionSynchronizationRegistry) ctx.lookup("java:comp/TransactionSynchronizationRegistry"); // This returns a valid instance

In JTATransactionImpl, the following is called:
 public void joinTransaction()

And
    if (jtaSyncRegistry != null)
    {
        // Register via TransactionSynchronizationRegistry
        jtaSyncRegistry.register(this);
    }

was invoked.

nicolas added a comment - 29/Jan/13 11:49 AM
Checking the java doc: http://docs.oracle.com/javaee/6/api/javax/transaction/TransactionSynchronizationRegistry.html#registerInterposedSynchronization(javax.transaction.Synchronization)

"Its beforeCompletion will be called after all SessionSynchronization beforeCompletion callbacks and callbacks registered directly with the Transaction, but before the 2-phase commit process starts. Similarly, the afterCompletion callback will be called after 2-phase commit completes but before any SessionSynchronization and Transaction afterCompletion callbacks."

And checking: http://lists.jboss.org/pipermail/jboss-as7-dev/2011-June/002336.html

I am not sure this guarantees the ordering.

Andy Jefferson added a comment - 29/Jan/13 01:01 PM
The DN requirement of expecting a correct registration of a Synchronisation hook to have its afterCompletion called before the container closes an EntityManager is perfectly reasonable IMHO. Maybe the people behind specs couldn't see their way to actually specify this (amongst the other things that aren't specified and just left to interpretation), but that doesn't negate how reasonable an expectation it is.

That aside, SVN trunk has updates to close the Transaction when EC.close is called, so any subsequent afterCompletion calls won't be processed (assuming JBoss is finally bothering to call that afterCompletion some time after closing the EM), and the getIsActive() makes some use of the JTA txn status in its return. aka dirty hack. Give it a try.

TransactionSyncrhonizationRegistry is also now moved to NucleusContext so the JNDI lookup is done once per EMF/PMF.

nicolas added a comment - 29/Jan/13 01:06 PM - edited
"3:04:21,254 WARNING [DataNucleus.Transaction] (http--127.0.0.1-8000-1) Transaction.afterCompletion called on org.datanucleus.JTATransactionImpl@37b1c095 but is already closed. This is likely because youre using a JavaEE container like JBoss that has closed the EntityManager before calling afterCompletion on the transaction of that EntityManager - go figure. Any statistics gathering is rendered incorrect as a result."
lol

I thought you said no ugly hack...

It works though.

public boolean getIsActive()
    {
        if (closed)
        {
            return false;
        }
        int txnStatus = getTransactionStatus();
        if (txnStatus == Status.STATUS_COMMITTED || txnStatus == Status.STATUS_ROLLEDBACK)
        {
            return false;
        }
        return super.getIsActive();
    }

Looks OK to me...


Andy Jefferson made changes - 01/Feb/13 07:41 AM
Status Resolved [ 5 ] Closed [ 6 ]
Scott Marlow added a comment - 01/Feb/13 08:01 PM
DataNucleus is currently closing the entity manager, when the JPA specification clearly states in section 7.9.1, that the (Java EE) container is responsible for doing that.

If you think that the JBoss EE container code is wrong for doing that, could you explain why.

Also, regarding the question of the ordering of interposed/non-interposed synchronization invocation, the TransactionSynchornizationRegistry [javadoc|http://docs.oracle.com/javaee/5/api/javax/transaction/TransactionSynchronizationRegistry.html#registerInterposedSynchronization%28javax.transaction.Synchronization%29] states:

{quote}
 registerInterposedSynchronization

void registerInterposedSynchronization(Synchronization sync)

Register a Synchronization instance with special ordering semantics. Its beforeCompletion will be called after all SessionSynchronization beforeCompletion callbacks and callbacks registered directly with the Transaction, but before the 2-phase commit process starts. Similarly, the afterCompletion callback will be called after 2-phase commit completes but before any SessionSynchronization and Transaction afterCompletion callbacks.

The beforeCompletion callback will be invoked in the transaction context of the transaction bound to the current thread at the time this method is called. Allowable methods include access to resources, e.g. Connectors. No access is allowed to "user components" (e.g. timer services or bean methods), as these might change the state of data being managed by the caller, and might change the state of data that has already been flushed by another caller of registerInterposedSynchronization. The general context is the component context of the caller of registerInterposedSynchronization.

The afterCompletion callback will be invoked in an undefined context. No access is permitted to "user components" as defined above. Resources can be closed but no transactional work can be performed with them.

If this method is invoked without an active transaction context, an IllegalStateException is thrown.

If this method is invoked after the two-phase commit processing has started, an IllegalStateException is thrown.

Parameters:
        sync - the Synchronization instance.
Throws:
        IllegalStateException - if no transaction is active.
Since:
        JTA 1.1
{quote}

Is this jira the right place to discuss this issue or do you want to continue on https://community.jboss.org/message/795686 thread or http://www.datanucleus.org/servlet/forum/viewthread_thread,7378

Regards,
Scott

Andy Jefferson added a comment - 01/Feb/13 08:18 PM
Scott,
Please define "DataNucleus is closing the EntityManager". Referring to the stack trace of Nicolas,

at org.datanucleus.ExecutionContextImpl.close(ExecutionContextImpl.java:363)
at org.datanucleus.api.jpa.JPAEntityManager.close(JPAEntityManager.java:194)
at org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization.afterCompletion(TransactionUtil.java:193)
at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion(SynchronizationImple.java:96)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:402)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:103)
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1165)
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:91)

The transaction commits and JBoss (org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization) calls close on the EntityManager.

As already said enough elsewhere, I don't use JavaEE so this is best discussed between people who do use it. The simple requirement I would like is to get the chance for any Synchronization afterCompletion to be called before closing any resource that registered it, namely the Synchronization that was registered by the DN EntityManager (JTATransactionImpl). If the JPA spec doesn't provide for that, then fine, but it's a reasonable thing to ask IMHO.

Scott Marlow added a comment - 01/Feb/13 10:22 PM
Andy,

All good questions to ask, IMHO ;)

From what Nicolas pasted to the jboss forum link above, the above call stack (which occurs first) and also the following call stack which happens after shows "DataNucleus is calling JPAEntityManager.close()". Also see https://community.jboss.org/message/794463#794463 if this isn't readable enough:

at org.datanucleus.TransactionImpl.internalPostCommit(TransactionImpl.java:563)
at org.datanucleus.JTATransactionImpl.afterCompletion(JTATransactionImpl.java:429)
at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion(SynchronizationImple.java:96)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:402)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:103)
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1165)
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)

From a JTA specification point of view, the only ordering requirement is that the TransactionSynchronizationRegistry (interposed) synchronizations are invoked before the Transaction registered (non-interposed) synchronizations.

The org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization.afterCompletion() will be called first and then the org.datanucleus.JTATransactionImpl.afterCompletion(). I thought that DataNucleus's JTATransactionImpl.afterCompletion() was also closing the entity manager but that doesn't seem to be the case.


Scott Marlow added a comment - 02/Feb/13 04:00 AM
^H^H^H^H over the first part of my last comment about DataNucleus closing the entity manager also. I think that we are sync now about that not being the case :)

I hope that the other information that I posted about synchronization ordering is helpful. Just to be clear, from a JTA standard point of view, the interposed synchronizations will be invoked in an indeterminate order (during after completion) but always before any non-interposed synchronizations are invoked.

Currently in JBoss, we do order the execution order of the interposed synchronizations, but you shouldn't depend on that, since other transaction managers may not (JBoss could also change this implementation detail in the future). That is how JBoss is always closing the entity manager before the org.datanucleus.JTATransactionImpl.afterCompletion() invocation.


nicolas added a comment - 04/Feb/13 06:17 PM
Hi Andy,

Some more info about JBoss and Tx.

https://community.jboss.org/message/795988#795988

"Hi Seyvet,
If you look at those two stack traces you can see a common line:

at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:402)
 
The only ordering that can be guaranteed is for interposed synchronizations (registered by the TransactionSynchronizationRegistry):
http://docs.oracle.com/javaee/5/api/javax/transaction/TransactionSynchronizationRegistry.html#registerInterposedSynchronization%28javax.transaction.Synchronization%29
 
There was a little mistype in my original response which I will now refactor in the original to say:
 
...
foreach ResourceManager
   rm::commit()
foreach InterposedSynchronization
   s::beforeCompletion();
foreach Synchronization
   s::afterCompletion();
 
i.e. When it comes to afterCompletion, interposed synchronizations will be called *first* which is one way (if you only have two synchronizations ) to guarentee order.
"

But, if I remember correctly you tried this and the order was the same...

nicolas added a comment - 04/Feb/13 06:24 PM
Correction: Interposed transaction is the JTA sort in DN.

As per JTASyncRegistry:
  public void register(Synchronization sync)
    {
        registry.registerInterposedSynchronization(sync);
    }

...

Andy Jefferson added a comment - 04/Feb/13 07:13 PM
Yes, DN will be using TransactionSynchronizationRegistry.registerInterposedSynchronization(). And the JTATransactionImpl.afterCompletion seemed (from your reports) to be called after org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization.afterCompletion was called.