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

LockManagerTest.testMultipleCounterStripped random failures

    XMLWordPrintable

Details

    Description

      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.

      Attachments

        Activity

          People

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

            Dates

              Created:
              Updated:
              Resolved: