[infinispan-issues] [JBoss JIRA] (ISPN-1595) Implicit transactions not being cleared from transaction table

[Galder Zamarreño (Commented) (JIRA)]

    [ https://issues.jboss.org/browse/ISPN-1595?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12652238#comment-12652238 ] 

Galder Zamarreño commented on ISPN-1595:
----------------------------------------

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 at 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 at 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