[CI] watcher_state: expected [started] but was [starting]

[DaveCTurner]

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.3+multijob-unix-compatibility/os=opensuse/17/console failed claiming

  java.lang.AssertionError: Failure at [watcher/stats/10_basic:16]: stats.0.watcher_state didn't match expected value:
         stats.0.watcher_state: expected [started] but was [starting]

The REPRODUCE LINE does not reproduce this for me:

 ./gradlew :x-pack:qa:smoke-test-watcher-with-security:integTestRunner \
  -Dtests.seed=2F99CB334BB4B4C9 \
  -Dtests.class=org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityClientYamlTestSuiteIT \
  -Dtests.method="test {yaml=watcher/stats/10_basic/Test watcher stats supports emit_stacktraces parameter}" \
  -Dtests.security.manager=true \
  -Dtests.locale=sr-RS \
  -Dtests.timezone=Asia/Singapore

Full stack trace:

  java.lang.AssertionError: Failure at [watcher/stats/10_basic:16]: stats.0.watcher_state didn't match expected value:
         stats.0.watcher_state: expected [started] but was [starting]

  at __randomizedtesting.SeedInfo.seed([2F99CB334BB4B4C9:A7CDF4E9E548D931]:0)
  at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:343)
  at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.test(ESClientYamlSuiteTestCase.java:320)
  at sun.reflect.GeneratedMethodAccessor15.invoke(Unknown Source)
  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)
Caused by: java.lang.AssertionError: stats.0.watcher_state didn't match expected value:
         stats.0.watcher_state: expected [started] but was [starting]

  at org.elasticsearch.test.rest.yaml.section.MatchAssertion.doAssert(MatchAssertion.java:87)
  at org.elasticsearch.test.rest.yaml.section.Assertion.execute(Assertion.java:76)
  at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:336)
  ... 37 more

Might relate to #30118?

[elasticmachine]

Pinging @elastic/es-core-infra

[jtibshirani]

The other test in the file 10_basic also failed recently with the same stacktrace. I've included the information below for both builds on which it failed.

I'm going to mute both tests in this file, as they've each failed 8 times over the last 30 days. It looks like this suite may have a timing issue around start-up, and that these two tests in particular are especially prone to fail. Note that the test failures don't reproduce for me locally.

CI link: https://internal-ci.elastic.co/job/elastic+x-pack-elasticsearch+6.2+release-tests/327/console
Command to reproduce:

./gradlew :x-pack-elasticsearch:qa:smoke-test-watcher-with-security:integTestRunner \
  -Dtests.seed=7645BC3A0254B47 \
  -Dtests.class=org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityClientYamlTestSuiteIT \
  -Dtests.method="test {yaml=watcher/stats/10_basic/Test watcher stats output}" \
  -Dtests.security.manager=true \
  -Dbuild.snapshot=false \
  -Dtests.jvm.argline="-Dbuild.snapshot=false" \
  -Dtests.locale=he \
  -Dtests.timezone=America/Argentina/Salta

CI link: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.3+periodic/92/console
Command to reproduce:

./gradlew :x-pack:qa:smoke-test-watcher-with-security:integTestRunner \
  -Dtests.seed=E7F5BE23B7D49736 \
  -Dtests.class=org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityClientYamlTestSuiteIT \
  -Dtests.method="test {yaml=watcher/stats/10_basic/Test watcher stats output}" \
  -Dtests.security.manager=true \
  -Dtests.locale=el \
  -Dtests.timezone=Africa/Asmera

[spinscale]

indeed they do have a timing issue. This is fixed in #30403/#30118 for master and 6.x branches, which reduces the amount of code executed in an executor when watcher is starting up

[droberts195]

Same problem again in 6.2: https://internal-ci.elastic.co/job/elastic+x-pack-elasticsearch+6.2+multijob-unix-compatibility/933/consoleFull

REPRO command is:

./gradlew :x-pack-elasticsearch:qa:smoke-test-watcher-with-security:integTestRunner \
  -Dtests.seed=3D3CF5F5CB2E3807 \
  -Dtests.class=org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityClientYamlTestSuiteIT \
  -Dtests.method="test {yaml=watcher/stats/10_basic/Test watcher stats supports emit_stacktraces parameter}" \
  -Dtests.security.manager=true \
  -Dtests.locale=sq \
  -Dtests.timezone=Australia/Canberra

I will cherry pick the muting commit back to 6.2.

[droberts195]

Doh, couldn't cherry pick the mute commit as it needs to go in a different repo for 6.2. But I manually copied it over.

[droberts195]

indeed they do have a timing issue. This is fixed in #30403/#30118 for master and 6.x branches

@spinscale are you aware these tests are still muted in master and 6.x? So your fixes for these branches are not currently being tested.