Synchronization failure on aftrCompletion when using DataNucleus 3.2

[seyvet]

Using JBoss 7.1.1 Final + DataNucleus 3.2.0 as a JPA persistence provider, the following warning is generated on every commit (using Container Managed Persistency):

21:05:55,408 WARNING [DataNucleus.JPA] (http-/127.0.0.1:8080-4) EntityManager is managed by a container (JEE) and so cannot be closed by calling the EM.close() method. Please read JPA2 spec 3.1.1 for the close() method.

21:05:55,410 WARN  [com.arjuna.ats.jta] (http-/127.0.0.1:8080-4) ARJUNA016029: SynchronizationImple.afterCompletion - failed for org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization@10d400bb 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:41

4) [datanucleus-api-jpa-3.2.0-m2-SNAPSHOT.jar:]

at org.datanucleus.api.jpa.JPAEntityManager.close(JPAEntityManager.java:201) [datanucleus-api-jpa-3.2.0-m2-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(Synchronizatio

nImple.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(Transactio

nImple.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(Curre

ntInvocationContextInterceptor.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.jav

a: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(AdditionalSetu

pInterceptor.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.LocalDao$$$view3.createCompany(Unknown Source) [simple-jpa-0.0.1-SNAPSHOT.jar:]

at loader.MyLoader.createACompanyWithEmployee(MyLoader.java:75) [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(ExecutionTi

meInterceptor.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(ComponentDis

patcherInterceptor.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(PooledInstanceIntercept

or.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(Curre

ntInvocationContextInterceptor.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.jav

a: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(AdditionalSetu

pInterceptor.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:10

7)

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.jav

a: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:358) [datanucleus-core-3.2.0-m2-SNAPSHOT.jar:]

at org.datanucleus.api.jpa.JPAEntityManager.close(JPAEntityManager.java:197) [datanucleus-api-jpa-3.2.0-m2-SNAPSHOT.jar:]

... 113 more

21:05:55,451 WARN  [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-4) ARJUNA012127: TwoPhaseCoordinator.afterCompletion - returned failure for SynchronizationImple< 0:ffffc0a83801:34c0feac:50f07095:d, org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization@10d400bb >

The objects are successfully created/persisted.

Reading an object does not trigger this warning. Updating and deleteing does.

Here is the persistence.xml:


<?xml version="1.0" encoding="UTF-8"?>
<persistence xmlns="http://java.sun.com/xml/ns/persistence" version="1.0">

    <persistence-unit name="BM" transaction-type="JTA">
        <provider>org.datanucleus.api.jpa.PersistenceProviderImpl</provider>
        <!-- H2 data source
        <jta-data-source>java:jboss/datasources/ExampleDS</jta-data-source>
        <non-jta-data-source>java:jboss/datasources/ExampleDS-NonJTA</non-jta-data-source>
        -->
        <!-- MySQL DS -->
        <jta-data-source>java:/jdbc/simple</jta-data-source>
        <non-jta-data-source>java:/jdbc/simple-nonjta</non-jta-data-source>


        <class>data.persist.Company</class>
        <class>data.persist.Employee</class>

        <properties>
            <!-- Magic JBoss property for specifying the persistence provider -->
            <property name="jboss.as.jpa.providerModule" value="org.datanucleus"/>
            <!-- following is probably not useful... but...-->
            <property name="datanucleus.jtaLocator" value="custom_jndi"/>
            <property name="datanucleus.jtaJndiLocation" value="java:/TransactionManager"/>
            <!-- J2EE Close warning -->
            <property name="datanucleus.jpa.ignoreEntityManagerCloseByJ2EEContainer" value="true"/>
           
            <property name="datanucleus.autoCreateSchema" value="true"/>
            <property name="datanucleus.metadata.validate" value="false"/>
            <property name="datanucleus.validateTables" value="false"/>
            <property name="datanucleus.validateConstraints" value="false"/>
        </properties>
    </persistence-unit>

</persistence>

Maybe JBoss is calling something different, or not notifying the JTATransactionImpl via afterCompletion that the txn is finished?

Any hints? Or ideas?

[nickarls]

Show the class/code that does the persisting

[seyvet]

All the code is available from github: https://github.com/baboune/Simple-JPA/

In the Dao.java file:

   @TransactionAttribute(TransactionAttributeType.REQUIRES_NEW)

    public Long createCompany(final String name, final int nb) throws ConstraintException

    {

         if(!isUnique(name)) {

            throw new ConstraintException("Name already in use");

        }

        Company bc = new Company();

        bc.setName(name);

        Employee se = null;

        String time = String.valueOf(System.currentTimeMillis());

        for (int i = 0; i < nb; i++) {

            se = new Employee();

            se.setName(time + "::" + i);

            se.setCompany(bc);

            bc.getEmployees().add(se);

        }

        em.persist(bc);

        return bc.getId();

    }

(I tried with and without the REQUIRES_NEW transaction attribute.

[smarlow]

The JPA 2.0 specification section 7.9.1 states the following requirements:

7.9.1 Container Responsibilities

For the management of a transaction-scoped persistence context, if there is no EntityManager alreadyassociated with the JTA transaction:

- The container creates a new entity manager by calling EntityManagerFactory.createEntityManager when the first invocation of an entity manager with PersistenceContextType.TRANSACTION occurs within the scope of a business method executing in the JTA transaction.

- After the JTA transaction has completed (either by transaction commit or rollback), The container closes the entity manager by calling EntityManager.close. [79]

... see JPA 2.0 spec for ommitted text that is not relevant to this discussion ...

[79] The container may choose to pool EntityManagers: it instead of creating and closing in each case, it may acquire one from its pool and call clear() on it.

I think that you are hitting a DataNucleus bug as EE containers are supposed to close the EntityManager.  Its the application code that is not supposed to call EntityManager.close() but instead let the EE container handle that.  http://www.datanucleus.org/products/accessplatform/jpa/emf.html describes the following:

datanucleus.jpa.ignoreEntityManagerCloseByJ2EEContainer
Description	The JPA spec (3.11) says that a "container-managed" EntityManager should not be closed (by calling close()). Some JavaEE containers ignore this, and are non-compliant as a result but you can ignore such calls if you set this persistence property to true.
Range of Values	false | true

Can you raise this issue on the DataNucleus forums and create a DataNucleus bug.  Please post a link to this forum discussion when you do.  Also post a link on this forum discussion, to the DataNucleus discussion (forum and/or bug report). 

Scott

[seyvet]

Hi Scott,

Thanks for the thorough analysis.  You are correct about the JPA spec and the close issue.  BUT, there is already a flag in my application persistence.xml that is used to allow the container to call close:

            <!-- J2EE Close warning -->
            <property name="datanucleus.jpa.ignoreEntityManagerCloseByJ2EEContainer" value="true"/>

Using this flag (true) triggers the following WARNING in the logs (available in original posting) triggered by DN:

21:05:55,408 WARNING [DataNucleus.JPA] (http-/127.0.0.1:8080-4) EntityManager is managed by a container (JEE) and so cannot be closed by calling the EM.close() method. Please read JPA2 spec 3.1.1 for the close() method.

That being said, I agree with you that this should be fixed in datanucleus, and I will raise an issue.

However, when the flag is set to true, then datanucleus ignores this particular behavior. On the other hand, when this flag is not set (default) or set to false, then there DN will generate an ERROR and the Tx is rollbacked, as a result no data is persisted. Setting this to false triggers a different behaviour. And I am in contact with the DN guys that told me to use this flag set to true.

As such, when set to true as per DN recommendation, then (and only then) is the afterCompletion() error generated. This leads me to believe that this DN behavior is not related to the afterCompletion() error (ARJUNA ...) but rather something outside of DN or a bad transfer of the transaction between JBoss and DN.

In other words: I  have the described above exception which originated this post.

[smarlow]

That being said, I agree with you that this should be fixed in datanucleus, and I will raise an issue.

Sounds good.

However, when the flag is set to true, then datanucleus ignores this particular behavior. On the other hand, when this flag is not set (default) or set to false, then there DN will generate an ERROR and the Tx is rollbacked, as a result no data is persisted. Setting this to false triggers a different behaviour. And I am in contact with the DN guys that told me to use this flag set to true.

As such, when set to true as per DN recommendation, then (and only then) is the afterCompletion() error generated. This leads me to believe that this DN behavior is not related to the afterCompletion() error (ARJUNA ...) but rather something outside of DN or a bad transfer of the transaction between JBoss and DN.

In other words: I  have the described above exception which originated this post.

I haven't looked at the DN code but it sounds to me like "datanucleus.jpa.ignoreEntityManagerCloseByJ2EEContainer=true" is allowing the EntityManager.close() to occur but they still log a warning.

[seyvet]

Scott Marlow wrote:

I haven't looked at the DN code but it sounds to me like "datanucleus.jpa.ignoreEntityManagerCloseByJ2EEContainer=true" is allowing the EntityManager.close() to occur but they still log a warning.

That is correct.

Now the exception that we see in the logs of the first post has nothing to do with this flag.  Which is why I am wondering ig JBoss is calling something different, or not notifying the JTATransactionImpl via afterCompletion that the txn is finished?

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:358) [datanucleus-core-3.2.0-m2-SNAPSHOT.jar:]

at org.datanucleus.api.jpa.JPAEntityManager.close(JPAEntityManager.java:197) [datanucleus-api-jpa-3.2.0-m2-SNAPSHOT.jar:]

... 113 more

21:05:55,451 WARN  [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-4) ARJUNA012127: TwoPhaseCoordinator.afterCompletion - returned failure for SynchronizationImple< 0:ffffc0a83801:34c0feac:50f07095:d, org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization@10d400bb >

Could the transaction be active still?

(Datanucleus forum post: http://www.datanucleus.org/servlet/forum/viewthread_thread,7378)

[seyvet]

I have debugged a but further and this is the Arjuna Tx state on the afterCompletion() -> Close(), in the ExecutionContextImpl:

jtaTx = {com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple@2281} "TransactionImple < ac, BasicAction: 0:ffffc0a83801:-191825a3:50fa7887:19 status: ActionStatus.COMMITTED >"

joinStatus = {org.datanucleus.JTATranasactionImpl$JoinStatus@2308} "JOINED"

Status COMMITTED is defined as: http://docs.oracle.com/javaee/6/api/javax/transaction/Status.html

A transaction is associated with the target object and it has been committed. It is likely that heuristics exist; otherwise, the transaction would have been destroyed and NoTransaction returned.

This looks IMO normal.

DataNucleus then complains that the Tx is still active and that is why the Exception is thrown.

Thequestions:

- Is this a proper behaviour?

- If the JTA transaction is JOINED, on the afterCompletion() -> Close(), what would be a "normal" Transaction status? Ie which javax.transaction.Status are considered normal? And which one should be throwing an exception?

Thanks.

[smarlow]

DataNucleus doesn't have to check for EntityManager.close() being invoked, that is something that the EE container has to prevent the application from calling directly.

JPA 2.0 specification "7.9.1 Container Responsibilities" describes how this is the EE container responsibility:

For the management of a transaction-scoped persistence context, if there is no EntityManager already

associated with the JTA transaction:

*  The container creates a new entity manager by calling EntityManagerFactory.createEntityManager when the first invocation of an entity manager with PersistenceContextType.TRANSACTION occurs within the scope of a business method executing in the JTA transaction.

*  After the JTA transaction has completed (either by transaction commit or rollback), The container closes the entity manager by calling EntityManager.close. [79]

...

The container must throw the IllegalStateException if the application calls EntityManager.close on a container-managed entity manager.

...

I'll mention this in the DN forum.

Scott

[smarlow]

seyvet wrote:

I have debugged a but further and this is the Arjuna Tx state on the afterCompletion() -> Close(), in the ExecutionContextImpl:

jtaTx = {com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple@2281} "TransactionImple < ac, BasicAction: 0:ffffc0a83801:-191825a3:50fa7887:19 status: ActionStatus.COMMITTED >"

joinStatus = {org.datanucleus.JTATranasactionImpl$JoinStatus@2308} "JOINED"

Status COMMITTED is defined as: http://docs.oracle.com/javaee/6/api/javax/transaction/Status.html

A transaction is associated with the target object and it has been committed. It is likely that heuristics exist; otherwise, the transaction would have been destroyed and NoTransaction returned.

This looks IMO normal.

DataNucleus then complains that the Tx is still active and that is why the Exception is thrown.

Thequestions:

- Is this a proper behaviour?

- If the JTA transaction is JOINED, on the afterCompletion() -> Close(), what would be a "normal" Transaction status? Ie which javax.transaction.Status are considered normal? And which one should be throwing an exception?

Thanks.

I would like to see TRACE logging output while you hit this issue.  Could you enable TRACE log output for org.jboss.as.jpa + com.arjuna?

Also try to enable DataNucleus logging if possible (try adding a category similar to org.jboss.as.jpa when you enable that).  You can reference DataNucleus logging information here. 

Attach the server.log or the revevant part (from the middle of the database transaction where database operations are still occuring, to a few pages after the transaction actually ends).  This will give us more context.

Scott

[seyvet]

Hi,

Added logging.

Here is the full log from the AS start to the errror.

Thanks.

[smarlow]

I see at 16:36:25,913, that "the EE container" (org.jboss.as.jpa) is closing the entity manager and we see the warning that we discussed before that should be removed.  It also looks like the DataNucleus code is throwing a javax.persistence.PersistenceException which is also not expected to happen (DataNucleus should not throw that exception as mentioned before on the linked DataNucleus form).

16:36:25,912 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-4) SynchronizationImple.afterCompletion

16:36:25,912 TRACE [com.arjuna.ats.jta] (http-/127.0.0.1:8080-4) SynchronizationImple.afterCompletion

16:36:25,913 DEBUG [org.jboss.as.jpa] (http-/127.0.0.1:8080-4) http-/127.0.0.1:8080-4:[transaction scoped EntityManager]: closing entity managersession

16:36:25,913 WARNING [DataNucleus.JPA] (http-/127.0.0.1:8080-4) EntityManager is managed by a container (JEE) and so cannot be closed by calling the EM.close() method. Please read JPA2 spec 3.1.1 for the close() method.

16:36:25,914 WARN  [com.arjuna.ats.jta] (http-/127.0.0.1:8080-4) ARJUNA016029: SynchronizationImple.afterCompletion - failed for org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization@2b181277 with exception: javax.persistence.PersistenceException: Transaction is still active. You should always close your transactions correctly using commit() or rollback().

With the trace/debug information in the log, I can see what is going on now. 

I have debugged a but further and this is the Arjuna Tx state on the afterCompletion() -> Close(), in the ExecutionContextImpl:

jtaTx = {com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple@2281} "TransactionImple < ac, BasicAction: 0:ffffc0a83801:-191825a3:50fa7887:19 status: ActionStatus.COMMITTED >"

joinStatus = {org.datanucleus.JTATranasactionImpl$JoinStatus@2308} "JOINED"

Status COMMITTED is defined as: http://docs.oracle.com/javaee/6/api/javax/transaction/Status.html

A transaction is associated with the target object and it has been committed. It is likely that heuristics exist; otherwise, the transaction would have been destroyed and NoTransaction returned.

This looks IMO normal.

DataNucleus then complains that the Tx is still active and that is why the Exception is thrown.

Thequestions:

- Is this a proper behaviour?

- If the JTA transaction is JOINED, on the afterCompletion() -> Close(), what would be a "normal" Transaction status? Ie which javax.transaction.Status are considered normal? And which one should be throwing an exception?

I think that it makes sense that the transaction is "committed" in the TX afterCompletion.  I'm not sure why DataNucleus *needs* to throw that exception, the close() code should be examined if its just trying to be helpful or if there was a spec requirement that they are trying to implement with that check/throw.

I'm not sure about the meaning of the "joinStatus = {org.datanucleus.JTATranasactionImpl$JoinStatus@2308} "JOINED"".

[seyvet]

Need to reopen this...  After inspection of the thread dump and the order of invocation, it seems that JBoss is calling first the close() on the JPAEntityManager, and AFTER the  afterCompletion on the transaction.... Meaning the Tx is still active on the close()...

First this happens:

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)

Then:

http-/127.0.0.1:8080-36@224, prio=5, in group 'main', status: 'RUNNING'

            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)

Is this expected?  What to do with the close() if the Tx is active?

[smarlow]

Look at JPA 2.0 specification section 7.9.1, specifically the below text:

7.9.1 Container Responsibilities

For the management of a transaction-scoped persistence context, if there is no EntityManager already

associated with the JTA transaction:

• The container creates a new entity manager by calling EntityManagerFactory.createEntityManager when the first invocation of an entity manager with PersistenceContextType.TRANSACTION occurs within the scope of a business method executing in the JTA transaction.
• After the JTA transaction has completed (either by transaction commit or rollback), The container closes the entity manager by calling EntityManager.close.

I am not surprised that the transaction is marked active still in the after completion (so that we can still get status and other information from the transaction).  If you still think this is wrong, you can post to https://community.jboss.org/community/jbosstm/dev asking why the tx is active in after completion.

Is DataNucleus expecting the EntityManager to be closed when their interposed synchronization is invoked?  Of is it only the transction status that is in question for DataNucleus?

[seyvet]

Based on the 7.9.1 Container Responsibilities:

After the JTA transaction has completed (either by transaction commit or rollback), The container closes the entity manager by calling EntityManager.close.

DN expects the Transaction afterCompletion() to be triggered BEFORE the EntityManager.close().  The opposite is triggered by JBoss.

Based on the thread dump, arjuna calls first:

at org.datanucleus.api.jpa.JPAEntityManager.close(JPAEntityManager.java:194)

at org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization.afterCompletion(TransactionUtil.java:193)

(EntityManager.close() is called first)

Then JTA after completion:

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)

In other words JTA afterCompletion() is completed AFTER em.close() and not the other way around. DN expects the opposite.