[
https://issues.jboss.org/browse/ISPN-1595?page=com.atlassian.jira.plugin....
]
Galder Zamarreño edited comment on ISPN-1595 at 12/20/11 5:19 AM:
------------------------------------------------------------------
TxCompletionNotificationCommand is used to remove remote transactions and this is sent
asynchronously. However, sometimes when the test is executed
(org.infinispan.lock.APITest.testSilentLockFailureAffectsPostOperations()), these commands
are only executed once the cache is stopped and at that point the cache is undefined,
i.e.
{code}2011-12-20 11:04:37,296 1353 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl]
(main:) NodeA-21646 broadcasting call
TxCompletionNotificationCommand{ xid=null, internalId=0,
gtx=GlobalTransaction:<NodeA-21646>:1:local, cacheName=___defaultcache}
to recipient list null
...
2011-12-20 11:04:37,329 1386 DEBUG [org.infinispan.CacheImpl] (main:) Stopping cache
___defaultcache on NodeB-21723
...
2011-12-20 11:04:37,330 1387 DEBUG [org.infinispan.transaction.TransactionTable] (main:)
Wait for on-going transactions to finish for 2
seconds.
...
2011-12-20 11:04:37,331 1388 TRACE
[org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher]
(Incoming-2,Infinispan-Cluster,NodeB-21723:)
Attempting to execute command: TxCompletionNotificationCommand{ xid=null, internalId=0,
gtx=GlobalTransaction:<NodeA-21646>:1:local,
cacheName=___defaultcache} [sender=NodeA-21646]
2011-12-20 11:04:37,332 1389 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl]
(Incoming-2,Infinispan-Cluster,NodeB-21723:) Strict peer to peer
off, so silently ignoring that ___defaultcache cache is not defined
{code}
There's a couple of interesting things here:
1. When a cache is stopped, the cache definition is cleared and so no
TxCompletionNotificationCommand can execute, so trying to wait for remote transactions to
useless.
2. I dunno whether is chance and or there's some other reason behind it, but it
appears as if the 'Incoming-' thread takes time to kick off, around 40ms. Might be
just timing...
I think we need a better solution for 1)
was (Author: galder.zamarreno):
TxCompletionNotificationCommand is used to remove remote transactions and this is sent
asynchronously. However, sometimes when the test is executed
(org.infinispan.lock.APITest.testSilentLockFailureAffectsPostOperations()), these commands
are only executed once the cache is stopped and at that point the cache is undefined,
i.e.
{code}2011-12-20 11:04:37,296 1353 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl]
(main:) NodeA-21646 broadcasting call TxCompletionNotificationCommand{ xid=null,
internalId=0, gtx=GlobalTransaction:<NodeA-21646>:1:local,
cacheName=___defaultcache} to recipient list null
...
2011-12-20 11:04:37,329 1386 DEBUG [org.infinispan.CacheImpl] (main:) Stopping cache
___defaultcache on NodeB-21723
...
2011-12-20 11:04:37,330 1387 DEBUG [org.infinispan.transaction.TransactionTable] (main:)
Wait for on-going transactions to finish for 2
...
2011-12-20 11:04:37,331 1388 TRACE
[org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher]
(Incoming-2,Infinispan-Cluster,NodeB-21723:) Attempting to execute command:
TxCompletionNotificationCommand{ xid=null, internalId=0,
gtx=GlobalTransaction:<NodeA-21646>:1:local, cacheName=___defaultcache}
[sender=NodeA-21646]
2011-12-20 11:04:37,332 1389 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl]
(Incoming-2,Infinispan-Cluster,NodeB-21723:) Strict peer to peer off, so silently ignoring
that ___defaultcache cache is not defined
seconds.
{code}
There's a couple of interesting things here:
1. When a cache is stopped, the cache definition is cleared and so no
TxCompletionNotificationCommand can execute, so trying to wait for remote transactions to
useless.
2. I dunno whether is chance and or there's some other reason behind it, but it
appears as if the 'Incoming-' thread takes time to kick off, around 40ms. Might be
just timing...
I think we need a better solution for 1)
Implicit transactions not being cleared from transaction table
--------------------------------------------------------------
Key: ISPN-1595
URL:
https://issues.jboss.org/browse/ISPN-1595
Project: Infinispan
Issue Type: Bug
Components: Transactions
Affects Versions: 5.1.0.CR1
Reporter: Galder Zamarreño
Assignee: Galder Zamarreño
Priority: Blocker
Fix For: 5.1.0.CR2
Attachments: infinispan.log, SampleTest.java
The attached test case results in a failure to stop the cache in time with a warning
message like this:
{code}2011-12-06 17:34:20,018 31733 WARN [org.infinispan.transaction.TransactionTable]
(main:) ISPN000100: Stopping but there're transactions that did not finish in time:
localTransactions={TransactionImple < ac, BasicAction: 0:ffffa9fe8742:dc96:4ede43ed:2
status: ActionStatus.COMMITTED >=LocalXaTransaction{xid=<
131076, 29, 28, 0000000000-1-1-87-2-1216600-36-10678-3467-19000249,
0000000000-1-1-87-2-1216600-36-10678-3467-190003 >}
LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false,
transaction=TransactionImple < ac, BasicAction: 0:ffffa9fe8742:dc96:4ede43ed:2 status:
ActionStatus.COMMITTED >, lockedKeys=null, backupKeyLocks=null, viewId=1}
org.infinispan.transaction.xa.recovery.RecoveryAwareLocalTransaction@1},
remoteTransactions{}{code}
It would appear that the implicitly started cache operation for "c0.put(1,
"v1");" is not properly cleared?
{code}2011-12-06 17:33:49,862 1577 TRACE [org.infinispan.CacheImpl] (main:) Implicit
transaction started!
2011-12-06 17:33:49,862 1577 TRACE [org.infinispan.CacheImpl] (main:) Marked tx as
implicit.
2011-12-06 17:33:49,863 1578 TRACE
[org.infinispan.interceptors.InvocationContextInterceptor] (main:___defaultcache) Invoked
with command
PutKeyValueCommand{key=1, value=v1, flags=null, putIfAbsent=false, lifespanMillis=-1,
maxIdleTimeMillis=-1} and InvocationContext
[LocalTxInvocationContext{flags=null}]
2011-12-06 17:33:49,863 1578 TRACE [org.infinispan.statetransfer.StateTransferLockImpl]
(main:___defaultcache) Acquired shared state transfer shared lock,
total holders: 1
2011-12-06 17:33:49,866 1581 TRACE [org.infinispan.transaction.TransactionTable]
(main:___defaultcache) Created a new tx: LocalXaTransaction{xid=null}
LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false,
transaction=TransactionImple < ac, BasicAction: 0:ffffa9fe8742:dc96:4ede43ed:2 status:
ActionStatus.RUNNING >, lockedKeys=null, backupKeyLocks=null, viewId=1}
org.infinispan.transaction.xa.recovery.RecoveryAwareLocalTransaction@1
...
2011-12-06 17:33:49,876 1591 TRACE [org.infinispan.CacheImpl] (main:) Committing
transaction as it was implicit: TransactionImple < ac, BasicAction:
0:ffffa9fe8742:dc96:4ede43ed:2 status: ActionStatus.RUNNING >
{code}
Find attached both test and trace log file.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators:
https://issues.jboss.org/secure/ContactAdministrators!default.jspa
For more information on JIRA, see:
http://www.atlassian.com/software/jira