[infinispan-issues] [JBoss JIRA] (ISPN-6437) InfinispanLock.LockPlaceHolder sometimes doesn't invoke its listeners

InfinispanLock.LockPlaceHolder sometimes doesn't invoke its listeners --------------------------------------------------------------------- Key: ISPN-6437 URL: https://issues.jboss.org/browse/ISPN-6437 Project: Infinispan Issue Type: Bug Components: Core, Test Suite - Core Affects Versions: 8.2.0.Final Reporter: Dan Berindei Assignee: Pedro Ruivo Labels: testsuite_stability Fix For: 9.0.0.Alpha1 Attachments: LocalTopKeyTest.log.gz, LocalTopKeyTest_pr_pruivo_t_6437_refactor_20160328.log When {{InfinispanLock.LockPlaceHolder.lock()}} times out in the {{await()}} call, it doesn't CAS the state and it doesn't run the listeners. Listeners are used by the extended statistics module, and missed invocations cause random failures in {{LocalTopKeyTest}}: {noformat} 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [DefaultLockManager] Lock key=key for owner=GlobalTransaction:<null>:34:local. timeout=100 (MILLISECONDS) 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Acquire lock for GlobalTransaction:<null>:34:local. Timeout=100 (MILLISECONDS) 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Created a new one: LockPlaceHolder{lockState=WAITING, owner=GlobalTransaction:<null>:34:local} 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Try acquire. Next in queue=LockPlaceHolder{lockState=WAITING, owner=GlobalTransaction:<null>:34:local}. Current=LockPlaceHolder{lockState=ACQUIRED, owner=GlobalTransaction:<null>:33:local} 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Unable to acquire. Lock is held. 17:44:50,515 ERROR (testng-LocalTopKeyTest:[___defaultcache]) [InvocationContextInterceptor] ISPN000136: Error executing command VersionedPrepareCommand, writing keys [key] org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 100 milliseconds for key key and requestor GlobalTransaction:<null>:34:local. Lock is held by GlobalTransaction:<null>:33:local at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:200) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:200) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:166) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:70) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:153) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:140) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.stats.topK.LocalTopKeyTest$PrepareCommandBlocker.visitPrepareCommand(LocalTopKeyTest.java:229) ~[test-classes/:?] at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.stats.topK.CacheUsageInterceptor.visitPrepareCommand(CacheUsageInterceptor.java:78) ~[classes/:?] at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:110) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:79) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:335) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.transaction.impl.TransactionCoordinator.prepare(TransactionCoordinator.java:121) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.transaction.impl.TransactionCoordinator.prepare(TransactionCoordinator.java:104) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:111) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:698) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)] at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2364) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)] at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1518) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)] at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)] at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)] at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1200) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)] at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)] at org.infinispan.cache.impl.CacheImpl.tryCommit(CacheImpl.java:1679) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.cache.impl.CacheImpl.executeCommandAndCommitIfNeeded(CacheImpl.java:1636) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.cache.impl.CacheImpl.putInternal(CacheImpl.java:1163) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:1153) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:1699) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:241) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT] at org.infinispan.stats.topK.LocalTopKeyTest.testLockFailed(LocalTopKeyTest.java:84) [test-classes/:?] 17:44:50,581 ERROR (testng-LocalTopKeyTest:[]) [UnitTestTestNGListener] Test testLockFailed(org.infinispan.stats.topK.LocalTopKeyTest) failed. java.lang.AssertionError: Wrong number of locked keys expected [2] but found [1] at org.testng.Assert.fail(Assert.java:94) ~[testng-6.8.8.jar:?] at org.testng.Assert.failNotEquals(Assert.java:494) ~[testng-6.8.8.jar:?] at org.testng.Assert.assertEquals(Assert.java:123) ~[testng-6.8.8.jar:?] at org.testng.Assert.assertEquals(Assert.java:265) ~[testng-6.8.8.jar:?] at org.infinispan.stats.topK.LocalTopKeyTest.assertTopKeyLocked(LocalTopKeyTest.java:188) ~[test-classes/:?] at org.infinispan.stats.topK.LocalTopKeyTest.assertLockInformation(LocalTopKeyTest.java:204) ~[test-classes/:?] at org.infinispan.stats.topK.LocalTopKeyTest.testLockFailed(LocalTopKeyTest.java:96) ~[test-classes/:?] {noformat} {{Log.unableToAcquireLock}} doesn't log the cause exception, but it seems unlikely that the timeout came from somewhere else.