LockManagerTest.testMultipleCounterStripped random failures ----------------------------------------------------------- Key: ISPN-6098 URL: https://issues.jboss.org/browse/ISPN-6098 Project: Infinispan Issue Type: Bug Components: Test Suite - Core Affects Versions: 8.1.0.Final Reporter: Dan Berindei Assignee: Pedro Ruivo Fix For: 8.2.1.Final, 9.0.0.Alpha1, 9.0.0.Final Attachments: LockManagerTest_ISPN-3305_remove_lock_reordering_tests_20160324.log.gz Doesn't appear to fail in CI, but I did get a couple failures running the test on my machine: {noformat} 17:42:29,998 ERROR (testng-LockManagerTest:) [UnitTestTestNGListener] Test testMultipleCounterStripped(org.infinispan.lock.LockManagerTest) failed. java.util.concurrent.ExecutionException: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 60 seconds for key key-6 and requestor Thread[pool-1127-thread-4,5,main]. Lock is held by null at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:1.8.0_60] at java.util.concurrent.FutureTask.get(FutureTask.java:192) ~[?:1.8.0_60] at org.infinispan.lock.LockManagerTest.doMultipleCounterTest(LockManagerTest.java:193) ~[test-classes/:?] at org.infinispan.lock.LockManagerTest.testMultipleCounterStripped(LockManagerTest.java:67) ~[test-classes/:?] Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 60 seconds for key key-6 and requestor Thread[pool-1127-thread-4,5,main]. Lock is held by null at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236) ~[classes/:?] at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305) ~[classes/:?] at org.infinispan.lock.LockManagerTest.lambda$doMultipleCounterTest$483(LockManagerTest.java:163) ~[test-classes/:?] ... 4 more {noformat} In another run, I got a deadlock that I think is related in {{InfinispanLockTest}}: {noformat} "testng-InfinispanLockTest" #19 prio=5 os_prio=0 tid=0x00007ff7f0eeb800 nid=0x4f5d waiting on condition [0x00007ff770da5000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x0000000084202448> (a java.util.concurrent.FutureTask) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429) at java.util.concurrent.FutureTask.get(FutureTask.java:191) at org.infinispan.lock.InfinispanLockTest.testSingleCounter(InfinispanLockTest.java:262) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:84) at org.testng.internal.Invoker.invokeMethod(Invoker.java:714) at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:901) at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1231) at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127) at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111) at org.testng.TestRunner.privateRun(TestRunner.java:767) at org.testng.TestRunner.run(TestRunner.java:617) at org.testng.SuiteRunner.runTest(SuiteRunner.java:348) at org.testng.SuiteRunner.access$000(SuiteRunner.java:38) at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:382) at org.testng.internal.thread.ThreadUtil$2.call(ThreadUtil.java:64) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Locked ownable synchronizers: - <0x0000000082875cc0> (a java.util.concurrent.ThreadPoolExecutor$Worker) "pool-1011-thread-7" #9840 prio=5 os_prio=0 tid=0x00007ff7380da000 nid=0x75f7 waiting on condition [0x00007ff698409000] java.lang.Thread.State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000000842020d8> (a java.util.concurrent.CompletableFuture$Signaller) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1695) at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323) at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1775) at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915) at org.infinispan.util.concurrent.CompletableFutures.await(CompletableFutures.java:74) at org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.lock(InfinispanLock.java:319) at org.infinispan.lock.InfinispanLockTest.lambda$testSingleCounter$509(InfinispanLockTest.java:243) at org.infinispan.lock.InfinispanLockTest$$Lambda$516/1905052434.call(Unknown Source) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Locked ownable synchronizers: - <0x00000000842021f8> (a java.util.concurrent.ThreadPoolExecutor$Worker) "pool-1011-thread-6" #9839 prio=5 os_prio=0 tid=0x00007ff738130800 nid=0x75f6 waiting on condition [0x00007ff699c21000] java.lang.Thread.State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000000842023a0> (a java.util.concurrent.CompletableFuture$Signaller) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1695) at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323) at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1775) at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915) at org.infinispan.util.concurrent.CompletableFutures.await(CompletableFutures.java:74) at org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.lock(InfinispanLock.java:319) at org.infinispan.lock.InfinispanLockTest.lambda$testSingleCounter$509(InfinispanLockTest.java:243) at org.infinispan.lock.InfinispanLockTest$$Lambda$516/1905052434.call(Unknown Source) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Locked ownable synchronizers: - <0x0000000084202468> (a java.util.concurrent.ThreadPoolExecutor$Worker) {noformat} I also suggest using {{AbstractInfinispanTest.fork()}} instead of an explicit {{ExecutorService}} in both tests, because without the test name in the thread name it's impossible to filter the test logs.