[CI] Failure in ScheduleWithFixedDelayTests.testRunnableRunsAtMostOnceAfterCancellation

[cbuescher]

Build: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.4+multijob-unix-compatibility/os=oraclelinux/18/console

I couldn't reproduce this locally unfortunately

./gradlew :server:test \
  -Dtests.seed=693BD40745664A87 \
  -Dtests.class=org.elasticsearch.threadpool.ScheduleWithFixedDelayTests \
  -Dtests.method="testRunnableRunsAtMostOnceAfterCancellation" \
  -Dtests.security.manager=true \
  -Dtests.locale=ar-EG \
  -Dtests.timezone=Pacific/Palau

Failure:

java.lang.AssertionError: 
Expected: one of {<11>, <12>}
     but: was <13>
	at __randomizedtesting.SeedInfo.seed([693BD40745664A87:F070AE607B18647]:0)
	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
	at org.junit.Assert.assertThat(Assert.java:956)
	at org.junit.Assert.assertThat(Assert.java:923)
	at org.elasticsearch.threadpool.ScheduleWithFixedDelayTests.testRunnableRunsAtMostOnceAfterCancellation(ScheduleWithFixedDelayTests.java:282)
	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:498)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:907)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
	at java.lang.Thread.run(Thread.java:748)

[elasticmachine]

Pinging @elastic/es-core-infra

[cbuescher]

A quick search shows a small number of similar looking failures, but all from last year when 6.x was still before current 6.4. No recent failures on 6.x or master, so this might not be a current issue anymore. Just filing for awareness.

[vladimirdolzhenko]

test looks bogus: race condition (esp. under the load on CI) could happens between count down latch reaches 0 and actual task cancellation

[vladimirdolzhenko]

I was able to reproduce it adding some trolls (who intensively eats cpu)

    public void testRunnableRunsAtMostOnceAfterCancellation() throws Exception {
/////////// troll part starts
        final int trolls = 32;
        final CountDownLatch trollStart = new CountDownLatch(1);
        final AtomicBoolean trollRun = new AtomicBoolean(true);
        final AtomicInteger trollBlackhole = new AtomicInteger();
        final CountDownLatch trollEnd = new CountDownLatch(trolls);
        IntStream.range(0, trolls).mapToObj(i -> new Thread(() -> {
            try {
                double v = 1.0 + randomDouble();
                double v2 = 1.0 + randomDouble();
                trollStart.await();

                // some stupid CPU intensive operations
                while (trollRun.get()) {
                    v *= 1 + v2;
                }
                // it has to be `consumed` somehow - via volatile write is enough
                trollBlackhole.addAndGet((int) v);
            } catch (InterruptedException e) {
                e.printStackTrace();
            } finally {
                trollEnd.countDown();
            }

        },"troll" + i)).forEach(Thread::start);

        trollStart.countDown();
/////////// troll part ends

        final int iterations = scaledRandomIntBetween(1, 12);
        final AtomicInteger counter = new AtomicInteger();
        final CountDownLatch doneLatch = new CountDownLatch(iterations);
        final Runnable countingRunnable = () -> {
            counter.incrementAndGet();
            doneLatch.countDown();
        };

        final long timoutMs = 10L;
        final Cancellable cancellable = threadPool.scheduleWithFixedDelay(countingRunnable, TimeValue.timeValueMillis(timoutMs), Names.GENERIC);
        doneLatch.await();
        cancellable.cancel();
        final int counterValue = counter.get();
        trollRun.set(false);
        trollEnd.await();

        assertThat(counterValue, isOneOf(iterations, iterations + 1));

        if (rarely()) {
            awaitBusy(() -> {
                final int value = counter.get();
                return value == iterations || value == iterations + 1;
            }, 5 * timoutMs, TimeUnit.MILLISECONDS);
        }
    }

definitely the reason is in a heavily loaded environment like CI could be due to parallel tasks

execution line 
// ++ is for counter.incrementAndGet()
// cd is for doneLatch.countDown();

 ----- [ ++ cd ] ----- [ ++ cd ] ----- [ ++ cd ] ----- [ ++ cd ] ----- [ ++ cd ] -----
                                     ^^ doneLatch.await                        ^^ cancel

Out of 200 runs it fails in ~10 cases, even with Expected: one of {<1>, <2>} but: was <8>

It never fails (out of 2000 runs) with timeout = 50 ms with a strong check that task has been executed exactly expected number of times.

We can increase timeout to let's say 100 ms to be even more safe.

Another approach is to track timings of last run and actual cancellation time - it makes test a way ugly.