Loading...

Type: Bug
Resolution: Done
Priority: Major
Fix Version/s: 9.0.0.Final
Affects Version/s: 8.2.0.Final
Component/s: Core, Test Suite
Labels:
- testsuite_stability

Git Pull Request:
https://github.com/infinispan/infinispan/pull/4185

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:

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/:?]

Log.unableToAcquireLock doesn't log the cause exception, but it seems unlikely that the timeout came from somewhere else.

- - Sort By Name
  - Sort By Date
  - Ascending
  - Descending
  - Thumbnails
  - List
  - Download All

LocalTopKeyTest_pr_pruivo_t_6437_refactor_20160328.log
58 kB
2016/03/28 10:38 AM
LocalTopKeyTest.log.gz
158 kB
2016/03/24 1:53 PM

Details

Description

Attachments

Attachments

Easy Agile Planning Poker

Activity

People

Dates

PagerDuty