Uploaded image for project: 'Infinispan'
  1. Infinispan
  2. ISPN-6098

LockManagerTest.testMultipleCounterStripped random failures

XMLWordPrintable

      Doesn't appear to fail in CI, but I did get a couple failures running the test on my machine:

      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
      

      In another run, I got a deadlock that I think is related in InfinispanLockTest:

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

      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.

            pruivo@redhat.com Pedro Ruivo
            dberinde@redhat.com Dan Berindei (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: