Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

FiberAsyncTest.whenCancelRunBlockingInterruptExecutingThread() fails sometimes #266

Open
felixvf opened this issue May 2, 2017 · 5 comments

Comments

@felixvf
Copy link

felixvf commented May 2, 2017

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

@pron
Copy link
Contributor

pron commented May 3, 2017

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
Copy link
Author

felixvf commented May 3, 2017

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
Copy link
Contributor

pron commented May 3, 2017

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

@felixvf
Copy link
Author

felixvf commented May 3, 2017

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 pron added bug and removed bug labels May 5, 2017
@pron
Copy link
Contributor

pron commented May 11, 2017

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants