JCA concurrent acces to ManagedConnection problem
Hello,
I'm using jBoss 4.2.2GA with jdk 1.5.0_12.
For my transactional monitor (a Tuxedo clone but a little faster :-)), I'm developing a JCA connector based on JCA specifications 1.0. Until now, everything was working fine until I tried to add XA functionality.
When jBoss is under stress, it seems that ManagedConnections can be used concurrently by 2 (or more) separated threads. As my implementation of ManagedConnection isn't thread-safe, I have troubles.
Is it normal that a ManagedConnection can be used by several threads ? I thought the pooling mechanism was built to avoid such cases.
I give you my trace just in case of I'm wrong in interpreting it. I add the thread id to the log4j pattern to known from which thread the message is coming from. As you can see, the thread http-7 is performing those steps:
1- gets the ManagedConnection@468c66b6 from the pool
2- sends message 548 (xa_start)
3- gets response 548 (XA_OK)
4- sends message 551 (service call)
5- gets response 551 (call OK)
6- sends message 559 (xa_end(TM_SUSPEND))
7- gets response 559 (XA_OK)
8- puts the ManagedConnection@468c66b6 back to the pool
9- sends message 560 (xa_end(TM_SUCCESS))
10- gets wrong response (overwrite by response) !!!!
Between step 9 and 10 of thread http-7, thread http-4 gets the same ManagedConnection@468c66b6 from the pool and begins its work:
1- gets the ManagedConnection@468c66b6 from the pool
2- sends message 561 (xa_start)
3- gets wrong response (overwrite by response 560) !!!!
I noticed that the problem always comes from XA orders sent after the ManagedConnection is returned to the pool.
Please help me.
Thanks in advance,
Pierre Brico
13:56:17,897-http-172.18.4.104-8180-7 TRACE [JBossManagedConnectionPool] supplying ManagedConnection from pool: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999777767 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=null]
13:56:17,898-http-172.18.4.104-8180-7 TRACE [JBossManagedConnectionPool] Got connection from pool org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999777767 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=null] [InUse/Available/Max]: [1/19/20]
13:56:17,898-http-172.18.4.104-8180-7 TRACE [TxConnectionManager] Pre-enlist: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999777767 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=null] threadTx=TransactionImple < ac, BasicAction: -53edfb98:e7a2:486b6b91:2abf status: ActionStatus.RUNNING >
13:56:17,898-http-172.18.4.104-8180-7 TRACE [TxConnectionManager] Get synchronizer org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999777767 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=null] threadTx=TransactionImple < ac, BasicAction: -53edfb98:e7a2:486b6b91:2abf status: ActionStatus.RUNNING >
13:56:17,898-http-172.18.4.104-8180-7 TRACE [TxConnectionManager] Enlisting resource org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999777767 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=TxSync731292857{tx=TransactionImple < ac, BasicAction: -53edfb98:e7a2:486b6b91:2abf status: ActionStatus.RUNNING > wasTrackByTx=false enlisted=false}]
13:56:17,899-http-172.18.4.104-8180-7 INFO [STDOUT] Sent header 548 tsdjca.TSDManagedConnection@468c66b6
13:56:17,900-http-172.18.4.104-8180-7 INFO [STDOUT] Sent body 548 tsdjca.TSDManagedConnection@468c66b6
13:56:17,980-http-172.18.4.104-8180-7 INFO [STDOUT] Received header 548 tsdjca.TSDManagedConnection@468c66b6
13:56:17,980-http-172.18.4.104-8180-7 INFO [STDOUT] Received body 548 tsdjca.TSDManagedConnection@468c66b6
13:56:17,980-http-172.18.4.104-8180-7 TRACE [TxConnectionManager] Enlisted resource org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999777767 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=TxSync731292857{tx=TransactionImple < ac, BasicAction: -53edfb98:e7a2:486b6b91:2abf status: ActionStatus.RUNNING > wasTrackByTx=false enlisted=false}]
13:56:17,980-http-172.18.4.104-8180-7 TRACE [TxConnectionManager] Check enlisted org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999777767 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=TxSync731292857{tx=TransactionImple < ac, BasicAction: -53edfb98:e7a2:486b6b91:2abf status: ActionStatus.RUNNING > wasTrackByTx=false enlisted=true}] threadTx=TransactionImple < ac, BasicAction: -53edfb98:e7a2:486b6b91:2abf status: ActionStatus.RUNNING >
13:56:17,983-http-172.18.4.104-8180-7 INFO [STDOUT] Sent header 551 tsdjca.TSDManagedConnection@468c66b6
13:56:17,999-http-172.18.4.104-8180-7 INFO [STDOUT] Sent body 551 tsdjca.TSDManagedConnection@468c66b6
13:56:18,378-http-172.18.4.104-8180-7 INFO [STDOUT] Received header 551 tsdjca.TSDManagedConnection@468c66b6
13:56:18,442-http-172.18.4.104-8180-7 INFO [STDOUT] Received body 551 tsdjca.TSDManagedConnection@468c66b6
13:56:18,448-http-172.18.4.104-8180-7 TRACE [TxConnectionManager] connectionClosed called mc=tsdjca.TSDManagedConnection@468c66b6
13:56:18,448-http-172.18.4.104-8180-7 TRACE [TxConnectionManager] isManagedConnectionFree=true mc=tsdjca.TSDManagedConnection@468c66b6
13:56:18,448-http-172.18.4.104-8180-7 TRACE [TxConnectionManager] delisting org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999777767 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=TxSync731292857{tx=TransactionImple < ac, BasicAction: -53edfb98:e7a2:486b6b91:2abf status: ActionStatus.RUNNING > wasTrackByTx=false enlisted=true}]
13:56:18,449-http-172.18.4.104-8180-7 INFO [STDOUT] Sent header 559 tsdjca.TSDManagedConnection@468c66b6
13:56:18,450-http-172.18.4.104-8180-7 INFO [STDOUT] Sent body 559 tsdjca.TSDManagedConnection@468c66b6
13:56:18,719-http-172.18.4.104-8180-7 INFO [STDOUT] Received header 559 tsdjca.TSDManagedConnection@468c66b6
13:56:18,720-http-172.18.4.104-8180-7 INFO [STDOUT] Received body 559 tsdjca.TSDManagedConnection@468c66b6
13:56:18,720-http-172.18.4.104-8180-7 TRACE [JBossManagedConnectionPool] putting ManagedConnection back into pool kill=false cl=org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999777767 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=null]
13:56:18,720-http-172.18.4.104-8180-7 TRACE [JBossManagedConnectionPool] Returning connection to pool org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999778720 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=null] [InUse/Available/Max]: [2/18/20]
13:56:18,720-http-172.18.4.104-8180-7 INFO [STDOUT] Sent header 560 tsdjca.TSDManagedConnection@468c66b6
13:56:18,722-http-172.18.4.104-8180-7 INFO [STDOUT] Sent body 560 tsdjca.TSDManagedConnection@468c66b6
13:56:18,783-http-172.18.4.104-8180-4 TRACE [JBossManagedConnectionPool] supplying ManagedConnection from pool: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999778720 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=null]
13:56:18,783-http-172.18.4.104-8180-4 TRACE [JBossManagedConnectionPool] Got connection from pool org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999778720 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=null] [InUse/Available/Max]: [3/17/20]
13:56:18,784-http-172.18.4.104-8180-4 TRACE [TxConnectionManager] No transaction, no need to enlist: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999778720 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=null]
13:56:18,786-http-172.18.4.104-8180-4 INFO [STDOUT] Sent header 561 tsdjca.TSDManagedConnection@468c66b6
13:56:18,791-http-172.18.4.104-8180-4 INFO [STDOUT] Sent body 561 tsdjca.TSDManagedConnection@468c66b6
13:56:18,990-http-172.18.4.104-8180-7 INFO [STDOUT] Received header 560 tsdjca.TSDManagedConnection@468c66b6
13:56:28,979-http-172.18.4.104-8180-4 INFO [STDOUT] Received header 12293 tsdjca.TSDManagedConnection@468c66b6
13:56:28,980-http-172.18.4.104-8180-4 TRACE [TxConnectionManager] connectionClosed called mc=tsdjca.TSDManagedConnection@468c66b6
13:56:28,980-http-172.18.4.104-8180-4 TRACE [TxConnectionManager] isManagedConnectionFree=true mc=tsdjca.TSDManagedConnection@468c66b6
13:56:28,980-http-172.18.4.104-8180-4 TRACE [TxConnectionManager] delisting org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999778720 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=null]
13:56:28,980-http-172.18.4.104-8180-4 TRACE [JBossManagedConnectionPool] putting ManagedConnection back into pool kill=false cl=org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999778720 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=null]
13:56:28,980-http-172.18.4.104-8180-4 TRACE [JBossManagedConnectionPool] Returning connection to pool org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@284ac3e1[state=NORMAL mc=tsdjca.TSDManagedConnection@468c66b6 handles=0 lastUse=1214999788980 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@2be8ac6f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3890c1ee xaResource=org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@4481fd71 txSync=null] [InUse/Available/Max]: [5/15/20]
