search

puniverse / quasar

Fibers, Channels and Actors for the JVM
http://docs.paralleluniverse.co/quasar/
Other
4.56k stars 574 forks source link

FiberAsyncTest.whenCancelRunBlockingInterruptExecutingThread() fails sometimes #266

Open felixvf opened 7 years ago

felixvf commented 7 years ago

When running the test FiberAsyncTest.whenCancelRunBlockingInterruptExecutingThread() as of https://github.com/puniverse/quasar/commits/df07c60aeccf3aacc3c0bd3534d1bba01ca50b72 repeatedly, it fails, while it should not fail.

pron commented 7 years ago

Does the failure occur with the same frequency when the sleep time is increased to, say, 10s? This could be a simple timing issue.

felixvf commented 7 years ago

It seems that the test fails with similar frequency regardless of whether the Fiber sleeps for 1000ms or 10000ms.

The reason seems to be a race-condition between 

interrupted.set(true)

at the fiber and

interrupted.get()

at the outer caller.

Apparently, fiber.join() does not wait for the InterruptedException to be processed by the fiber. Hence, it is possible that the outer caller still observes interrupted.get()==false while the fiber is going to call interrupted.set(true) some time in the future.

It seems that the expected behavior is

  1. either that joining a canceled fiber should return immediately (since it is canceled)
  2. or that joining a canceled fiber should return only after the fiber has ceased processing its InterruptedException (possibly never).

As Fibers should implement cooperative multitasking with predictable scheduling properties, option (1) seems to be undesirable and option (2) seems to be desirable, but the decision of what should be correct behavior is up to you.

pron commented 7 years ago

On which line does the test fail? Are you sure the fiber has started executing?

felixvf commented 7 years ago

When executing this code:


//  @Ignore // FIXME: This test currently fails and needs to be investigated. 
    @Test
    public void whenCancelRunBlockingInterruptExecutingThread() throws Exception {
        for (int i = 0;i<100;i++) {
            System.out.println("i="+i+".");
            final AtomicBoolean started = new AtomicBoolean();
            final AtomicBoolean interrupted = new AtomicBoolean();

            Fiber fiber = new Fiber(new SuspendableRunnable() {
                @Override
                public void run() throws SuspendExecution, InterruptedException {
                    FiberAsync.runBlocking(Executors.newSingleThreadExecutor(),
                            new CheckedCallable<Void, RuntimeException>() {
                                @Override
                                public Void call() throws RuntimeException {
                                    System.out.println("inner:  starting.");
                                    started.set(true);
                                    System.out.println("inner:  started.");
                                    try {
                                        System.out.println("inner:  sleeping.");
                                        Thread.sleep(10000);
                                        System.out.println("inner:  sleeped.");
                                    } catch (InterruptedException e) {
                                        System.out.println("inner:  setting interrupted.");
                                        interrupted.set(true);
                                        System.out.println("inner:  set interrupted.");
                                    }
                                    return null;
                                }
                            });
                }
            });

            fiber.start();
            Thread.sleep(100);
            fiber.cancel(true);
            try {
                System.out.println("outer:  joining.");
                fiber.join(5, TimeUnit.MILLISECONDS);
                System.out.println("outer:  joined.");
                fail("InterruptedException not thrown");
            } catch(ExecutionException e) {
                System.out.println("outer:  caught "+e+".");
//              e.printStackTrace();
                if (!(e.getCause() instanceof InterruptedException))
                    fail("InterruptedException not thrown");
            }
            System.out.println("outer:  reading started.");
            assertThat(started.get(), is(true));
            System.out.println("outer:  reading interrupted.");
            assertThat(interrupted.get(), is(true)); // line 366
        }
    }

using commandline gradle --no-daemon quasar-core:jdk7Test --tests '*FiberAsyncTest' --debug, then this output is produced:

[DEBUG] [TestEventLogger] co.paralleluniverse.fibers.FiberAsyncTest STARTED
[QUIET] [org.gradle.api.Task] Running test: Test whenCancelRunBlockingInterruptExecutingThread(co.paralleluniverse.fibers.FiberAsyncTest)
[DEBUG] [TestEventLogger] 
[DEBUG] [TestEventLogger] co.paralleluniverse.fibers.FiberAsyncTest > whenCancelRunBlockingInterruptExecutingThread STARTED
[DEBUG] [TestEventLogger] 
[DEBUG] [TestEventLogger] co.paralleluniverse.fibers.FiberAsyncTest > whenCancelRunBlockingInterruptExecutingThread STANDARD_OUT
[DEBUG] [TestEventLogger]     i=0.
[DEBUG] [TestEventLogger] 
[DEBUG] [TestEventLogger] co.paralleluniverse.fibers.FiberAsyncTest > whenCancelRunBlockingInterruptExecutingThread STANDARD_ERROR
[DEBUG] [TestEventLogger]     QUASAR WARNING: Assertions enabled. This may harm performance.
[DEBUG] [TestEventLogger] 
[DEBUG] [TestEventLogger] co.paralleluniverse.fibers.FiberAsyncTest > whenCancelRunBlockingInterruptExecutingThread STANDARD_OUT
[DEBUG] [TestEventLogger]     inner:  starting.
[DEBUG] [TestEventLogger]     inner:  started.
[DEBUG] [TestEventLogger]     inner:  sleeping.
[DEBUG] [TestEventLogger]     outer:  joining.
[DEBUG] [TestEventLogger]     outer:  caught java.util.concurrent.ExecutionException: java.lang.InterruptedException.
[DEBUG] [TestEventLogger]     inner:  setting interrupted.
[DEBUG] [TestEventLogger]     inner:  set interrupted.
[DEBUG] [TestEventLogger]     outer:  reading started.
[DEBUG] [TestEventLogger]     outer:  reading interrupted.
[DEBUG] [TestEventLogger]     i=1.
[DEBUG] [TestEventLogger]     inner:  starting.
[DEBUG] [TestEventLogger]     inner:  started.
[DEBUG] [TestEventLogger]     inner:  sleeping.
[DEBUG] [TestEventLogger]     outer:  joining.
[DEBUG] [TestEventLogger]     inner:  setting interrupted.
[DEBUG] [TestEventLogger]     inner:  set interrupted.
[DEBUG] [TestEventLogger]     outer:  caught java.util.concurrent.ExecutionException: java.lang.InterruptedException.
[DEBUG] [TestEventLogger]     outer:  reading started.
[DEBUG] [TestEventLogger]     outer:  reading interrupted.
[DEBUG] [TestEventLogger]     i=2.
[DEBUG] [TestEventLogger]     inner:  starting.
[DEBUG] [TestEventLogger]     inner:  started.
[DEBUG] [TestEventLogger]     inner:  sleeping.
[DEBUG] [TestEventLogger]     outer:  joining.
[DEBUG] [TestEventLogger]     outer:  caught java.util.concurrent.ExecutionException: java.lang.InterruptedException.
[DEBUG] [TestEventLogger]     outer:  reading started.
[DEBUG] [TestEventLogger]     outer:  reading interrupted.
[DEBUG] [TestEventLogger]     FAILED TEST whenCancelRunBlockingInterruptExecutingThread: 
[DEBUG] [TestEventLogger]     inner:  setting interrupted.
[DEBUG] [TestEventLogger]     inner:  set interrupted.
[DEBUG] [TestEventLogger]     Expected: is <true>
[DEBUG] [TestEventLogger]          but: was <false>
[DEBUG] [TestEventLogger] 
[DEBUG] [TestEventLogger] co.paralleluniverse.fibers.FiberAsyncTest > whenCancelRunBlockingInterruptExecutingThread STANDARD_ERROR
[DEBUG] [TestEventLogger]     java.lang.AssertionError: 
[DEBUG] [TestEventLogger]     Expected: is <true>
[DEBUG] [TestEventLogger]          but: was <false>
[DEBUG] [TestEventLogger]          at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
[DEBUG] [TestEventLogger]          at org.junit.Assert.assertThat(Assert.java:956)
[DEBUG] [TestEventLogger]          at org.junit.Assert.assertThat(Assert.java:923)
[DEBUG] [TestEventLogger]          at co.paralleluniverse.fibers.FiberAsyncTest.whenCancelRunBlockingInterruptExecutingThread(FiberAsyncTest.java:366)
[DEBUG] [TestEventLogger]          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[DEBUG] [TestEventLogger]          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[DEBUG] [TestEventLogger]          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[DEBUG] [TestEventLogger]          at java.lang.reflect.Method.invoke(Method.java:498)
[DEBUG] [TestEventLogger]          at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[DEBUG] [TestEventLogger]          at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[DEBUG] [TestEventLogger]          at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[DEBUG] [TestEventLogger]          at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[DEBUG] [TestEventLogger]          at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
[DEBUG] [TestEventLogger]          at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
[DEBUG] [TestEventLogger]          at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[DEBUG] [TestEventLogger]          at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
[DEBUG] [TestEventLogger]          at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
[DEBUG] [TestEventLogger]          at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
[DEBUG] [TestEventLogger]          at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[DEBUG] [TestEventLogger]          at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[DEBUG] [TestEventLogger]          at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[DEBUG] [TestEventLogger]          at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[DEBUG] [TestEventLogger]          at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[DEBUG] [TestEventLogger]          at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[DEBUG] [TestEventLogger]          at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.runTestClass(JUnitTestClassExecuter.java:114)
[DEBUG] [TestEventLogger]          at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.execute(JUnitTestClassExecuter.java:57)
[DEBUG] [TestEventLogger]          at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassProcessor.processTestClass(JUnitTestClassProcessor.java:66)
[DEBUG] [TestEventLogger]          at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51)
[DEBUG] [TestEventLogger]          at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
[DEBUG] [TestEventLogger]          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[DEBUG] [TestEventLogger]          at java.lang.reflect.Method.invoke(Method.java:498)
[DEBUG] [TestEventLogger]          at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
[DEBUG] [TestEventLogger]          at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
[DEBUG] [TestEventLogger]          at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32)
[DEBUG] [TestEventLogger]          at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93)
[DEBUG] [TestEventLogger]          at com.sun.proxy.$Proxy3.processTestClass(Unknown Source)
[DEBUG] [TestEventLogger]          at org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:109)
[DEBUG] [TestEventLogger]          at sun.reflect.GeneratedMethodAccessor3.invoke(Unknown Source)
[DEBUG] [TestEventLogger]          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[DEBUG] [TestEventLogger]          at java.lang.reflect.Method.invoke(Method.java:498)
[DEBUG] [TestEventLogger]          at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
[DEBUG] [TestEventLogger]          at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
[DEBUG] [TestEventLogger]          at org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:377)
[DEBUG] [TestEventLogger]          at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:54)
[DEBUG] [TestEventLogger]          at org.gradle.internal.concurrent.StoppableExecutorImpl$1.run(StoppableExecutorImpl.java:40)
[DEBUG] [TestEventLogger]          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[DEBUG] [TestEventLogger]          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[DEBUG] [TestEventLogger]          at java.lang.Thread.run(Thread.java:745)
[QUIET] [org.gradle.api.Task] Failed test whenCancelRunBlockingInterruptExecutingThread [co.paralleluniverse.fibers.FiberAsyncTest] with exception: java.lang.AssertionError: 
Expected: is <true>
     but: was <false>

So

On which line does the test fail?

At the line assertThat(interrupted.get(), is(true));

Are you sure the fiber has started executing?

Yes.

pron commented 7 years ago

Sorry, I completely spaced out on this one. What makes you think this is a bug at all? Obviously, the test is brittle, but there's no guarantee -- nor any need -- that the exception will be handled by the thread task by the time the fiber is joined. Normally, one does not wait for a canceled task to complete.