improper connection use in multi-bean transaction?
bruces Jun 20, 2002 6:46 PMI have a stateful sessionbean that
1) starts a bean-managed transaction
2) gets a connection through jca to my adapter
3) invokes another stateful sessionbean
That bean then
4) starts its own bean-managed transaction
5) gets a connection through jca to my adapter
6) performs an update
7) commits the transaction
and returns. The original bean then performs an update and tries to commit its transaction.
I see the connection manager correctly handle the connection in the first sequence. The second bean is then invoked in the same dispatch thread and is given the same connection (via matchManagedConnections). The container then issues a second XAResource.start on the connection's resource using a new GID.
The problem is that the connection associated with this resource can only handle one transaction at a time, and it's already in a transaction. The second "start" is assumed by my XAResource to be an association of the resource with an in-process transaction with the given XID. There isn't one, and strange things proceed to happen.
This looks like a bug in the connection manager to me. The same connection shouldn't be associated with two global transaction identifiers. The CM should get a different connection, get the XAResource from that connection, and issue a start with that resource.
server log-------------------------
12:20:25,305 INFO [STDOUT] [06/20/02 12:20:25.305 PDT]::::: CLIENT->BEAN TX CALL CHAIN :::::
12:20:25,307 INFO [STDOUT] [06/20/02 12:20:25.306 PDT]::::: INITIAL USER TX STATUS IS No Transaction
12:20:25,309 INFO [STDOUT] [06/20/02 12:20:25.309 PDT]::::: POST BEGIN TX STATUS IS Active
12:20:25,311 INFO [STDOUT] [06/20/02 12:20:25.310 PDT]::::: Getting Connection
12:20:25,312 INFO [Facets] [06/20/02 12:20:25.312 PDTRMI TCP Connection(5)-10.80.10.114] [Facets] using pooled connection CC2( PM 198 (workspace 3) (inactive manual txn) inJTx=false)
12:20:25,314 INFO [Facets] [06/20/02 12:20:25.313 PDTRMI TCP Connection(5)-10.80.10.114] #mc.getXAResource# CC2( PM 198 (workspace 3) (inactive manual txn) inJTx=false)
12:20:25,316 INFO [Facets] [06/20/02 12:20:25.315 PDTRMI TCP Connection(5)-10.80.10.114] #xa.start[hash=2346814,session=PM 198 (workspace 3) (inactive manual txn)] xid=XidImpl [FormatId=257, GlobalId=dirt//11, BranchQual=1]
12:20:25,320 INFO [Facets] [06/20/02 12:20:25.319 PDTRMI TCP Connection(5)-10.80.10.114] #mc.getConnection# CC2( PM 198 (workspace 3) (active manual txn) inJTx=true)
12:20:25,321 INFO [Facets] [06/20/02 12:20:25.321 PDTRMI TCP Connection(5)-10.80.10.114] [Facets] no user/password for CC2( PM 198 (workspace 3) (active manual txn) inJTx=true)
12:20:25,323 INFO [STDOUT] [06/20/02 12:20:25.323 PDT]::::: Connection obtained
12:20:25,325 INFO [STDOUT] [06/20/02 12:20:25.324 PDT]::::: INITIAL SESSION INFO :::::
12:20:25,326 INFO [STDOUT] [06/20/02 12:20:25.325 PDT]::::: jca.ejb.bmtx.TestServiceBean.testSessionCallChain_Bean_Tx SID: 198 TxID: 358157322813443 Tx: true
12:20:25,334 INFO [Facets] [06/20/02 12:20:25.334 PDTRMI TCP Connection(5)-10.80.10.114] #mc.cleanup# CC2( PM 198 (workspace 3) (active manual txn) inJTx=true)
12:20:25,336 INFO [Facets] [06/20/02 12:20:25.335 PDTRMI TCP Connection(5)-10.80.10.114] #mc.cleanup# CC2( PM 198 (workspace 3) (active manual txn) inJTx=true)
12:20:25,356 INFO [Facets] [06/20/02 12:20:25.356 PDTRMI TCP Connection(5)-10.80.10.114] [Facets] using pooled connection CC1( PM 196 (workspace 1) (inactive manual txn) inJTx=false)
12:20:25,358 INFO [Facets] [06/20/02 12:20:25.357 PDTRMI TCP Connection(5)-10.80.10.114] #mc.associateConnection# CC1( PM 196 (workspace 1) (inactive manual txn) inJTx=false) associating session wrapper JCA session PM 198 (workspace 3) (active manual txn)
12:20:25,361 INFO [Facets] [06/20/02 12:20:25.360 PDTRMI TCP Connection(5)-10.80.10.114] #mc.cleanup# CC1( PM 196 (workspace 1) (inactive manual txn) inJTx=false)
12:20:25,448 INFO [Facets] [06/20/02 12:20:25.448 PDTRMI TCP Connection(5)-10.80.10.114] #mc.cleanup# CC1( PM 196 (workspace 1) (inactive manual txn) inJTx=false)
12:20:25,450 INFO [STDOUT] [06/20/02 12:20:25.450 PDT]::::: TEST BEAN TX BEGIN:::::
12:20:25,452 INFO [STDOUT] [06/20/02 12:20:25.451 PDT]::::: INITIAL USER TX STATUS IS No Transaction
12:20:25,454 INFO [STDOUT] [06/20/02 12:20:25.453 PDT]::::: POST BEGIN TX STATUS IS Active
12:20:25,455 INFO [STDOUT] [06/20/02 12:20:25.454 PDT]::::: Getting Connection
12:20:25,457 INFO [Facets] [06/20/02 12:20:25.456 PDTRMI TCP Connection(5)-10.80.10.114] [Facets] using pooled connection CC2( PM 198 (workspace 3) (active manual txn) inJTx=true)
12:20:25,458 INFO [Facets] [06/20/02 12:20:25.458 PDTRMI TCP Connection(5)-10.80.10.114] #mc.getXAResource# CC2( PM 198 (workspace 3) (active manual txn) inJTx=true)
12:20:25,459 INFO [Facets] [06/20/02 12:20:25.459 PDTRMI TCP Connection(5)-10.80.10.114] #xa.start[hash=2346814,session=PM 198 (workspace 3) (active manual txn)] xid=XidImpl [FormatId=257, GlobalId=dirt//12, BranchQual=1]
12:20:25,461 INFO [Facets] [06/20/02 12:20:25.460 PDTRMI TCP Connection(5)-10.80.10.114] #mc.getConnection# CC2( PM 198 (workspace 3) (active manual txn) inJTx=true)
12:20:25,462 INFO [Facets] [06/20/02 12:20:25.461 PDTRMI TCP Connection(5)-10.80.10.114] [Facets] no user/password for CC2( PM 198 (workspace 3) (active manual txn) inJTx=true)
12:20:25,464 INFO [STDOUT] [06/20/02 12:20:25.463 PDT]::::: Connection obtained
12:20:25,465 INFO [STDOUT] [06/20/02 12:20:25.465 PDT]::::: INITIAL SESSION INFO :::::
12:20:25,467 INFO [STDOUT] [06/20/02 12:20:25.466 PDT]::::: jca.ejb.bmtx.OtherStatefulSessionBean.test_Bean_Tx SID: 198 TxID: 358157322813443 Tx: true
12:20:25,486 INFO [STDOUT] [06/20/02 12:20:25.485 PDT]::::::::::::::::::::::::::::::::::::::
12:20:25,487 INFO [STDOUT] [06/20/02 12:20:25.486 PDT]::::: ADDED AO USING KEY: 11416452005
12:20:25,489 INFO [STDOUT] [06/20/02 12:20:25.488 PDT]::::::::::::::::::::::::::::::::::::::
12:20:25,490 INFO [STDOUT] [06/20/02 12:20:25.489 PDT]::::: PRE COMMIT TX STATUS IS Active
12:20:25,491 INFO [STDOUT] [06/20/02 12:20:25.491 PDT]::::: COMMITTING
12:20:25,493 INFO [Facets] [06/20/02 12:20:25.492 PDTRMI TCP Connection(5)-10.80.10.114] #xa.end[hash=2346814,session=PM 198 (workspace 3) (active manual txn)] xid=XidImpl [FormatId=257, GlobalId=dirt//12, BranchQual=1]
12:20:25,494 INFO [Facets] [06/20/02 12:20:25.494 PDTRMI TCP Connection(5)-10.80.10.114] #xa.commit[hash=2346814,session=PM 198 (workspace 3) (active manual txn)] xid=XidImpl [FormatId=257, GlobalId=dirt//12, BranchQual=1] trs=resource
12:20:25,516 INFO [Facets] [06/20/02 12:20:25.515 PDTRMI TCP Connection(5)-10.80.10.114] #xa.forget[hash=2346814,session=PM 198 (workspace 3) (inactive manual txn)] xid=XidImpl [FormatId=257, GlobalId=dirt//12, BranchQual=1] trs=resource
12:20:25,756 INFO [STDOUT] [06/20/02 12:20:25.517 PDT]::::: COMMITTED
12:20:25,764 INFO [STDOUT] [06/20/02 12:20:25.763 PDT]::::: POST COMMIT TX STATUS IS No Transaction
12:20:25,765 INFO [STDOUT] [06/20/02 12:20:25.764 PDT] Session.isClosed(): false
12:20:25,767 INFO [Facets] [06/20/02 12:20:25.766 PDTRMI TCP Connection(5)-10.80.10.114] [Facets] Closing PM 198 (workspace 3) (inactive manual txn)
12:20:25,769 INFO [Facets] [06/20/02 12:20:25.768 PDTRMI TCP Connection(5)-10.80.10.114] #mc.notifyListeners# connection closed
12:20:25,770 INFO [Facets] [06/20/02 12:20:25.769 PDTRMI TCP Connection(5)-10.80.10.114] #mc.cleanup# CC2( PM 198 (workspace 3) (inactive manual txn) inJTx=false)
12:20:25,771 INFO [Facets] [06/20/02 12:20:25.771 PDTRMI TCP Connection(5)-10.80.10.114] #mc.cleanup# CC2( PM 198 (workspace 3) (inactive manual txn) inJTx=false)
12:20:25,773 INFO [STDOUT] [06/20/02 12:20:25.772 PDT]::::: TEST BEAN TX END :::::
12:20:25,775 INFO [Facets] [06/20/02 12:20:25.774 PDTRMI TCP Connection(5)-10.80.10.114] [Facets] using pooled connection CC1( PM 196 (workspace 1) (inactive manual txn) inJTx=false)
12:20:25,776 INFO [Facets] [06/20/02 12:20:25.775 PDTRMI TCP Connection(5)-10.80.10.114] #mc.associateConnection# CC1( PM 196 (workspace 1) (inactive manual txn) inJTx=false) associating session wrapper JCA session PM 196 (workspace 1) (inactive manual txn)
12:20:25,796 INFO [STDOUT] [06/20/02 12:20:25.796 PDT]::::::::::::::::::::::::::::::::::::::
12:20:25,798 INFO [STDOUT] [06/20/02 12:20:25.797 PDT]::::: ADDED AO USING KEY: 11416452006
12:20:25,799 INFO [STDOUT] [06/20/02 12:20:25.799 PDT]::::::::::::::::::::::::::::::::::::::
12:20:25,800 INFO [STDOUT] [06/20/02 12:20:25.800 PDT]::::: PRE COMMIT TX STATUS IS Active
12:20:25,802 INFO [STDOUT] [06/20/02 12:20:25.801 PDT]::::: COMMITTING
12:20:25,803 INFO [Facets] [06/20/02 12:20:25.803 PDTRMI TCP Connection(5)-10.80.10.114] #xa.end[hash=2346814,session=PM 198 (workspace 3) (inactive manual txn)] xid=XidImpl [FormatId=257, GlobalId=dirt//11, BranchQual=1]
12:20:25,804 INFO [Facets] [06/20/02 12:20:25.804 PDTRMI TCP Connection(5)-10.80.10.114] #xa.commit[hash=2346814,session=PM 198 (workspace 3) (inactive manual txn)] xid=XidImpl [FormatId=257, GlobalId=dirt//11, BranchQual=1] trs=resource
12:20:25,835 INFO [Facets]
[06/20/02 12:20:25.823 PDT RMI TCP Connection(5)-10.80.10.114] Facets connection error
com.gemstone.persistence.GsTransactionNotInProgressException: Cannot commit transaction PM 198 (workspace 3) (inactive manual txn) that has not begun.
at com.gemstone.persistence.jdo.PersistenceManagerImpl.commit(PersistenceManagerImpl.java:1678)
at com.gemstone.persistence.connection.internal.ContainerXAResource.commit(ContainerXAResource.java:74)
at org.jboss.tm.TxCapsule.commitResources(TxCapsule.java:1656)
at org.jboss.tm.TxCapsule.commit(TxCapsule.java:357)
at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:74)
at org.jboss.tm.TxManager.commit(TxManager.java:138)
at org.jboss.ejb.EnterpriseContext$UserTransactionImpl.commit(EnterpriseContext.java:439)
at jca.ejb.bmtx.TestServiceBean.testSessionCallChain_Bean_Tx(TestServiceBean.java:720)
at java.lang.reflect.Method.invoke(Native Method)
at org.jboss.ejb.StatefulSessionContainer$ContainerInterceptor.invoke(StatefulSessionContainer.java:823)
at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:129)
at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:186)
at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:96)
at org.jboss.ejb.plugins.AbstractTxInterceptorBMT.invokeNext(AbstractTxInterceptorBMT.java:144)
at org.jboss.ejb.plugins.TxInterceptorBMT.invoke(TxInterceptorBMT.java:62)
at org.jboss.ejb.plugins.StatefulSessionInstanceInterceptor.invoke(StatefulSessionInstanceInterceptor.java:266)
at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:166)
at org.jboss.ejb.StatefulSessionContainer.invoke(StatefulSessionContainer.java:380)
at org.jboss.ejb.Container.invoke(Container.java:705)
at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:491)
at org.jboss.invocation.jrmp.server.JRMPInvoker.invoke(JRMPInvoker.java:362)
at java.lang.reflect.Method.invoke(Native Method)
at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:236)
at sun.rmi.transport.Transport$1.run(Transport.java:147)
at java.security.AccessController.doPrivileged(Native Method)
at sun.rmi.transport.Transport.serviceCall(Transport.java:143)
at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:460)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:701)
at java.lang.Thread.run(Thread.java:479)
12:20:25,840 INFO [Facets] [06/20/02 12:20:25.839 PDTRMI TCP Connection(5)-10.80.10.114] #mc.notifyListeners# connection error occurred
12:20:25,841 INFO [Facets] [06/20/02 12:20:25.840 PDTRMI TCP Connection(5)-10.80.10.114] #mc.cleanup# CC2( PM 198 (workspace 3) (inactive manual txn) inJTx=false)
12:20:25,842 INFO [Facets] [06/20/02 12:20:25.842 PDTRMI TCP Connection(5)-10.80.10.114] #mc.destroy# CC2( PM 198 (workspace 3) (inactive manual txn) inJTx=false)
12:20:25,956 WARN [TxCapsule] XAException: tx=XidImpl [FormatId=257, GlobalId=dirt//11, BranchQual=] errorCode=XAER_NOTA
javax.transaction.xa.XAException
at com.gemstone.persistence.connection.internal.ContainerXAResource.commit(ContainerXAResource.java:89)
at org.jboss.tm.TxCapsule.commitResources(TxCapsule.java:1656)
at org.jboss.tm.TxCapsule.commit(TxCapsule.java:357)
at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:74)
at org.jboss.tm.TxManager.commit(TxManager.java:138)
at org.jboss.ejb.EnterpriseContext$UserTransactionImpl.commit(EnterpriseContext.java:439)
at jca.ejb.bmtx.TestServiceBean.testSessionCallChain_Bean_Tx(TestServiceBean.java:720)
at java.lang.reflect.Method.invoke(Native Method)
at org.jboss.ejb.StatefulSessionContainer$ContainerInterceptor.invoke(StatefulSessionContainer.java:823)
at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:129)
at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:186)
at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:96)
at org.jboss.ejb.plugins.AbstractTxInterceptorBMT.invokeNext(AbstractTxInterceptorBMT.java:144)
at org.jboss.ejb.plugins.TxInterceptorBMT.invoke(TxInterceptorBMT.java:62)
at org.jboss.ejb.plugins.StatefulSessionInstanceInterceptor.invoke(StatefulSessionInstanceInterceptor.java:266)
at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:166)
at org.jboss.ejb.StatefulSessionContainer.invoke(StatefulSessionContainer.java:380)
at org.jboss.ejb.Container.invoke(Container.java:705)
at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:491)
at org.jboss.invocation.jrmp.server.JRMPInvoker.invoke(JRMPInvoker.java:362)
at java.lang.reflect.Method.invoke(Native Method)
at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:236)
at sun.rmi.transport.Transport$1.run(Transport.java:147)
at java.security.AccessController.doPrivileged(Native Method)
at sun.rmi.transport.Transport.serviceCall(Transport.java:143)
at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:460)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:701)
at java.lang.Thread.run(Thread.java:479)
12:20:25,967 INFO [Facets] [06/20/02 12:20:25.966 PDTRMI TCP Connection(5)-10.80.10.114] #xa.forget[hash=2346814,session=PM 198 (workspace 0) (shutdownPending closed txn)] xid=XidImpl [FormatId=257, GlobalId=dirt//11, BranchQual=1] trs=resource
12:20:25,975 INFO [Facets] [06/20/02 12:20:25.971 PDTRMI TCP Connection(5)-10.80.10.114] #mc.cleanup# CC1( PM 196 (workspace 1) (inactive manual txn) inJTx=false)
12:20:25,977 INFO [Facets] [06/20/02 12:20:25.976 PDTRMI TCP Connection(5)-10.80.10.114] #mc.getXAResource# CC1( PM 196 (workspace 1) (inactive manual txn) inJTx=false)