[ https://issues.jboss.org/browse/ISPN-1595?page=com.atlassian.jira.plugin.... ] Galder Zamarreño updated ISPN-1595: ----------------------------------- Description: 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. was: 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

[ https://issues.jboss.org/browse/ISPN-1595?page=com.atlassian.jira.plugin.... ] Manik Surtani updated ISPN-1595: -------------------------------- Priority: Blocker (was: Major) -- 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

[ https://issues.jboss.org/browse/ISPN-1595?page=com.atlassian.jira.plugin.... ] Galder Zamarreño commented on ISPN-1595: ---------------------------------------- Assigning it to myself to investigate it while Mircea is away on holidays... -- 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

[ 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) -- 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

[ https://issues.jboss.org/browse/ISPN-1595?page=com.atlassian.jira.plugin.... ] Galder Zamarreño commented on ISPN-1595: ---------------------------------------- @Mircea, when you fix this, please also add the commit in https://github.com/galderz/infinispan/commit/a1d01399d10deddde14d250f478f... -- 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

[ https://issues.jboss.org/browse/ISPN-1595?page=com.atlassian.jira.plugin.... ] Manik Surtani resolved ISPN-1595. --------------------------------- Resolution: Done -- 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