[JCA/JBoss] - JCA concurrent acces to ManagedConnection problem - jboss-user

Wednesday, 2 July 2008

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]

View the original post :
http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4162043#...

Reply to the post :
http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&a...

2026

2025

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

2007

2006

[JCA/JBoss] - JCA concurrent acces to ManagedConnection problem