UpgradeClusterClientYamlTestSuiteIT fails intermittently

[alpar-t]

Discovered while building #30367 Failed

Reproducible using :

./gradlew :x-pack:qa:rolling-upgrade:with-system-key:v6.4.0-SNAPSHOT#mixedClusterTestRunner
-Dtests.seed=D2CB09031F59783F
-Dtests.class=org.elasticsearch.upgrades.UpgradeClusterClientYamlTestSuiteIT
-Dtests.security.manager=true -Dtests.locale=en-BB -Dtests.timezone=Australia/ACT
-Dtests.rest.suite=mixed_cluster

Saw different failures while trying to reproduce it in isolation:

 2> REPRODUCE WITH: ./gradlew :x-pack:qa:rolling-upgrade:with-system-key:v6.4.0-SNAPSHOT#mixedClusterTestRunner -Dtests.seed=D2CB09031F59783F -Dtests.class=org.elasticsearch.upgrades.UpgradeClusterClientYamlTestSuiteIT -Dtests.method="test {p0=mixed_cluster/30_ml_jobs_crud/Test get old cluster job}" -Dtests.security.manager=true -Dtests.locale=en-BB -Dtests.timezone=Australia/ACT -Dtests.rest.suite=mixed_cluster
FAILURE 1.40s | UpgradeClusterClientYamlTestSuiteIT.test {p0=mixed_cluster/30_ml_jobs_crud/Test get old cluster job} <<< FAILURES!
   > Throwable #1: java.lang.AssertionError: Failure at [mixed_cluster/30_ml_jobs_crud:33]: field [jobs.0.node] doesn't have a true value
   > Expected: not null
   >      but: was null
   >    at __randomizedtesting.SeedInfo.seed([D2CB09031F59783F:5A9F36D9B1A515C7]:0)
   >    at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:343)
   >    at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.test(ESClientYamlSuiteTestCase.java:320)
   >    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   >    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
   >    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
   >    at java.base/java.lang.reflect.Method.invoke(Method.java:564)
   >    at java.base/java.lang.Thread.run(Thread.java:844)
   > Caused by: java.lang.AssertionError: field [jobs.0.node] doesn't have a true value
   > Expected: not null
   >      but: was null
   >    at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
   >    at org.elasticsearch.test.rest.yaml.section.IsTrueAssertion.doAssert(IsTrueAssertion.java:55)
   >    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

and

> Task :x-pack:qa:rolling-upgrade:with-system-key:v6.4.0-SNAPSHOT#oldClusterTestRunner
==> Test Summary: 1 suite, 10 tests, 1 ignored (1 assumption)
   [junit4] JVM J0:     1.08 ..    22.93 =    21.85s
   [junit4] Execution time total: 22 seconds
   [junit4] Tests summary: 1 suite, 10 tests, 1 ignored (1 assumption)

> Task :x-pack:qa:rolling-upgrade:with-system-key:v6.4.0-SNAPSHOT#mixedClusterTestRunner
   [junit4] <JUnit4> says ciao! Master seed: D2CB09031F59783F
==> Test Info: seed=D2CB09031F59783F; jvm=1; suite=1

Suite: org.elasticsearch.upgrades.UpgradeClusterClientYamlTestSuiteIT
  1> [2018-05-08T21:32:10,505][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/40_ml_datafeed_crud/Put job and datafeed in mixed cluster}]: before test
  1> [2018-05-08T21:32:10,636][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] initializing REST clients against [http://[::1]:33111]
  1> [2018-05-08T21:32:11,479][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] initializing yaml client, minimum es version: [6.4.0] master version: [6.4.0] hosts: [http://[::1]:33111]
  1> [2018-05-08T21:32:12,210][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/40_ml_datafeed_crud/Put job and datafeed in mixed cluster}]: after test
  1> [2018-05-08T21:32:12,234][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/20_security/Verify user and role in mixed cluster}]: before test
  1> [2018-05-08T21:32:12,965][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/20_security/Verify user and role in mixed cluster}]: after test
  1> [2018-05-08T21:32:12,974][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/10_basic/Index data and search on the mixed cluster}]: before test
  1> [2018-05-08T21:32:13,795][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/10_basic/Index data and search on the mixed cluster}]: after test
  1> [2018-05-08T21:32:13,805][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/30_ml_jobs_crud/Test get old cluster job}]: before test
  1> [2018-05-08T21:32:14,042][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] Stash dump on test failure [{
  1>   "stash" : {
  1>     "body" : {
  1>       "count" : 1,
  1>       "jobs" : [
  1>         {
  1>           "job_id" : "old-cluster-job",
  1>           "data_counts" : {
  1>             "job_id" : "old-cluster-job",
  1>             "processed_record_count" : 0,
  1>             "processed_field_count" : 0,
  1>             "input_bytes" : 0,
  1>             "input_field_count" : 0,
  1>             "invalid_date_count" : 0,
  1>             "missing_field_count" : 0,
  1>             "out_of_order_timestamp_count" : 0,
  1>             "empty_bucket_count" : 0,
  1>             "sparse_bucket_count" : 0,
  1>             "bucket_count" : 0,
  1>             "input_record_count" : 0
  1>           },
  1>           "model_size_stats" : {
  1>             "job_id" : "old-cluster-job",
  1>             "result_type" : "model_size_stats",
  1>             "model_bytes" : 146088,
  1>             "total_by_field_count" : 4,
  1>             "total_over_field_count" : 0,
  1>             "total_partition_field_count" : 2,
  1>             "bucket_allocation_failures_count" : 0,
  1>             "memory_status" : "ok",
  1>             "log_time" : 1525779101000,
  1>             "timestamp" : 1403481600000
  1>           },
  1>           "state" : "closed"
  1>         }
  1>       ]
  1>     }
  1>   }
  1> }]
  1> [2018-05-08T21:32:14,168][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/30_ml_jobs_crud/Test get old cluster job}]: after test
  2> REPRODUCE WITH: ./gradlew :x-pack:qa:rolling-upgrade:with-system-key:v6.4.0-SNAPSHOT#mixedClusterTestRunner -Dtests.seed=D2CB09031F59783F -Dtests.class=org.elasticsearch.upgrades.UpgradeClusterClientYamlTestSuiteIT -Dtests.method="test {p0=mixed_cluster/30_ml_jobs_crud/Test get old cluster job}" -Dtests.security.manager=true -Dtests.locale=en-BB -Dtests.timezone=Australia/ACT -Dtests.rest.suite=mixed_cluster
FAILURE 0.38s | UpgradeClusterClientYamlTestSuiteIT.test {p0=mixed_cluster/30_ml_jobs_crud/Test get old cluster job} <<< FAILURES!
   > Throwable #1: java.lang.AssertionError: Failure at [mixed_cluster/30_ml_jobs_crud:19]: jobs.0.data_counts.processed_record_count didn't match expected value:
   > jobs.0.data_counts.processed_record_count: expected [2] but was [0]
   >    at __randomizedtesting.SeedInfo.seed([D2CB09031F59783F:5A9F36D9B1A515C7]:0)
   >    at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:343)
   >    at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.test(ESClientYamlSuiteTestCase.java:320)
   >    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   >    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
   >    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
   >    at java.base/java.lang.reflect.Method.invoke(Method.java:564)
   >    at java.base/java.lang.Thread.run(Thread.java:844)
   > Caused by: java.lang.AssertionError: jobs.0.data_counts.processed_record_count didn't match expected value:
   > jobs.0.data_counts.processed_record_count: expected [2] but was [0]
   >    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
  1> [2018-05-08T21:32:14,183][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/50_token_auth/Get the indexed token and use if to authenticate}]: before test
  1> [2018-05-08T21:32:14,671][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] There are still tasks running after this test that might break subsequent tests [internal:index/shard/recovery/prepare_translog, internal:index/shard/recovery/start_recovery, internal:index/shard/recovery/translog_ops].
  1> [2018-05-08T21:32:14,671][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/50_token_auth/Get the indexed token and use if to authenticate}]: after test
  1> [2018-05-08T21:32:14,704][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/30_ml_jobs_crud/Test get job with rules}]: before test
  1> [2018-05-08T21:32:15,014][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] There are still tasks running after this test that might break subsequent tests [internal:index/shard/recovery/start_recovery, internal:index/shard/recovery/translog_ops].
  1> [2018-05-08T21:32:15,014][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/30_ml_jobs_crud/Test get job with rules}]: after test
  1> [2018-05-08T21:32:15,045][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/20_security/verify users for default password migration in mixed cluster}]: before test
  1> [2018-05-08T21:32:15,431][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/20_security/verify users for default password migration in mixed cluster}]: after test
  1> [2018-05-08T21:32:15,440][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/10_basic/Start scroll in mixed cluster for upgraded}]: before test
  1> [2018-05-08T21:32:17,380][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/10_basic/Start scroll in mixed cluster for upgraded}]: after test
  1> [2018-05-08T21:32:17,398][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/10_basic/Basic scroll mixed}]: before test
  1> [2018-05-08T21:32:18,322][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/10_basic/Basic scroll mixed}]: after test
  1> [2018-05-08T21:32:18,337][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/30_ml_jobs_crud/Create a job in the mixed cluster and write some data}]: before test
  1> [2018-05-08T21:32:19,989][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/30_ml_jobs_crud/Create a job in the mixed cluster and write some data}]: after test
  1> [2018-05-08T21:32:19,995][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/40_ml_datafeed_crud/Test old cluster datafeed}]: before test
  1> [2018-05-08T21:32:20,135][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] [test {p0=mixed_cluster/40_ml_datafeed_crud/Test old cluster datafeed}]: after test
  2> NOTE: leaving temporary files on disk at: /home/alpar.torok/elasticsearch/x-pack/qa/rolling-upgrade/with-system-key/build/testrun/v6.4.0-SNAPSHOT#mixedClusterTestRunner/J0/temp/org.elasticsearch.upgrades.UpgradeClusterClientYamlTestSuiteIT_D2CB09031F59783F-001
  2> NOTE: test params are: codec=Asserting(Lucene70): {}, docValues:{}, maxPointsInLeafNode=203, maxMBSortInHeap=6.586752071408995, sim=RandomSimilarity(queryNorm=false): {}, locale=en-BB, timezone=Australia/ACT
  2> NOTE: Linux 4.15.0-1006-gcp amd64/Oracle Corporation 10.0.1 (64-bit)/cpus=8,threads=1,free=500541920,total=536870912
  2> NOTE: All tests run in this JVM: [UpgradeClusterClientYamlTestSuiteIT]
Completed [1/1] in 9.96s, 11 tests, 1 failure <<< FAILURES! 

First failure reproduced 3 times for, the second one only once, and got 3 successful runs as well.

[elasticmachine]

Pinging @elastic/es-distributed

[jasontedor]

These look like ML issues, I am reassigning.

[elasticmachine]

Pinging @elastic/ml-core

[davidkyle]

Failures have been spotted on the 6.x and master branches. All failures on master occurred upgrading from 6.4 and on 6.x upgrading from 6.2.1, 6.2.3, 6.2.5 and 6.3.0.

I pulled the logs for one instance a unfortunately they don't provide much insight without debug level logging.

mixedcluster.log
oldcluster.log
upgradedcluster.log

[droberts195]

I think the problem is one that we've had intermittently for ages. I imagine something has recently changed elsewhere in ES or the test infrastructure that makes it more likely that a bug that has existed basically forever to be triggered.

To summarise we've had two theories about what might cause this:

1. Our results index has async durability. We've done testing in the past that shows this dramatically improves performance for our usage pattern. And it's usually reasonable because in the event of a complete node failure losing a result in the translog is no worse than losing a result that existed in memory but hadn't yet been submitted for indexing. But what we're doing wrong is that our flush and close endpoints are supposed to guarantee that when they return everything prior to the call is safely persisted. So ideally our flush and close endpoints should do something that ensures the translog is synced in addition to what they currently do before returning.
2. When we write our results documents we're not waiting for acknowledgement from all replicas, only the primary. In the case of these rolling upgrade tests it's possible that the primary shard of our results index is on the node that gets taken out of the cluster to be replaced with one running the upgraded version. If our results document had not made it to the replica then it won't exist in the upgraded cluster. As with (1), in general this is fine, as a recent result could have been lost in memory if a node was brutally removed from the cluster. But with flush and close we're not giving the guarantee we should be. Ideally before returning from a flush or close we'd do something that ensured every document indexed to the results index for the job had been written to both primary and replica.

I suspect in the case of the tests (2) is more likely, because fsync would only have an impact in the case of OS or hardware failure, not abrupt shutdown of a user-space program. However, to meet the guarantees of ML's flush and close for real-world failures we need to find ways to fix both problems without degrading performance in cases where flush and close are called rarely.

[ywelsch]

When we write our results documents we're not waiting for acknowledgement from all replicas, only the primary

How is that possible? I'm not aware of any option in ES that would allow you to only wait on acknowledgement from the primary.