[CI] Rolling upgrade mixed cluster tests timeout waiting for green cluster health

[jaymode]

The rolling upgrade tests failed on the 5.5 branch due to the call to the cluster health API not returning anything after 30 seconds in the mixed_cluster/10_basic/Index data and search on the mixed cluster test.

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+5.5+bwc-tests/18/console

REPRODUCE WITH: gradle :qa:rolling-upgrade:v5.0.2#mixedClusterTestRunner -Dtests.seed=48F336D5A9FD5B28 -Dtests.class=org.elasticsearch.upgrades.UpgradeClusterClientYamlTestSuiteIT -Dtests.method="test {p0=mixed_cluster/10_basic/Index data and search on the mixed cluster}" -Dtests.security.manager=true -Dtests.locale=de-AT -Dtests.timezone=Africa/Maseru -Dtests.rest.suite=mixed_cluster
ERROR   30.5s | UpgradeClusterClientYamlTestSuiteIT.test {p0=mixed_cluster/10_basic/Index data and search on the mixed cluster} <<< FAILURES!
   > Throwable #1: java.lang.RuntimeException: Failure at [mixed_cluster/10_basic:3]: listener timeout after waiting for [30000] ms
   > 	at __randomizedtesting.SeedInfo.seed([48F336D5A9FD5B28:C0A7090F070136D0]:0)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:343)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.test(ESClientYamlSuiteTestCase.java:325)
   > 	at java.lang.Thread.run(Thread.java:748)
   > Caused by: java.io.IOException: listener timeout after waiting for [30000] ms
   > 	at org.elasticsearch.client.RestClient$SyncResponseListener.get(RestClient.java:660)
   > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:219)
   > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:191)
   > 	at org.elasticsearch.test.rest.yaml.ClientYamlTestClient.callApi(ClientYamlTestClient.java:173)
   > 	at org.elasticsearch.test.rest.yaml.ClientYamlTestExecutionContext.callApiInternal(ClientYamlTestExecutionContext.java:161)
   > 	at org.elasticsearch.test.rest.yaml.ClientYamlTestExecutionContext.callApi(ClientYamlTestExecutionContext.java:93)
   > 	at org.elasticsearch.test.rest.yaml.section.DoSection.execute(DoSection.java:221)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:341)
   > 	... 38 more

One enhancement that may help for future failure debugging is to change the timeout of either the cluster health request or the rest client so that the cluster health call times out on the server and we get a response rather than the test just aborting due to the rest client timeout.

@abeyad assigning to you based on the git history.

[jimczi]

Another instance:
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=ubuntu/1124

REPRODUCE WITH: gradle :qa:rolling-upgrade:v5.0.2#mixedClusterTestRunner -Dtests.seed=48F336D5A9FD5B28 -Dtests.class=org.elasticsearch.upgrades.UpgradeClusterClientYamlTestSuiteIT -Dtests.method="test {p0=mixed_cluster/10_basic/Index data and search on the mixed cluster}" -Dtests.security.manager=true -Dtests.locale=de-AT -Dtests.timezone=Africa/Maseru -Dtests.rest.suite=mixed_cluster
ERROR   30.5s | UpgradeClusterClientYamlTestSuiteIT.test {p0=mixed_cluster/10_basic/Index data and search on the mixed cluster} <<< FAILURES!
   > Throwable #1: java.lang.RuntimeException: Failure at [mixed_cluster/10_basic:3]: listener timeout after waiting for [30000] ms
   > 	at __randomizedtesting.SeedInfo.seed([48F336D5A9FD5B28:C0A7090F070136D0]:0)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:343)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.test(ESClientYamlSuiteTestCase.java:325)
   > 	at java.lang.Thread.run(Thread.java:748)
   > Caused by: java.io.IOException: listener timeout after waiting for [30000] ms
   > 	at org.elasticsearch.client.RestClient$SyncResponseListener.get(RestClient.java:660)
   > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:219)
   > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:191)
   > 	at org.elasticsearch.test.rest.yaml.ClientYamlTestClient.callApi(ClientYamlTestClient.java:173)
   > 	at org.elasticsearch.test.rest.yaml.ClientYamlTestExecutionContext.callApiInternal(ClientYamlTestExecutionContext.java:161)
   > 	at org.elasticsearch.test.rest.yaml.ClientYamlTestExecutionContext.callApi(ClientYamlTestExecutionContext.java:93)
   > 	at org.elasticsearch.test.rest.yaml.section.DoSection.execute(DoSection.java:221)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:341)
   > 	... 38 more

[dimitris-athanasiou]

Another instance: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+periodic/3249/console

REPRODUCE WITH: gradle :qa:rolling-upgrade:v5.6.0-SNAPSHOT#mixedClusterTestRunner -Dtests.seed=BF13612A12738489 -Dtests.class=org.elasticsearch.upgrades.UpgradeClusterClientYamlTestSuiteIT -Dtests.method="test {p0=mixed_cluster/10_basic/Index data and search on the mixed cluster}" -Dtests.security.manager=true -Dtests.locale=es-SV -Dtests.timezone=America/Panama -Dtests.rest.suite=mixed_cluster
FAILURE 30.1s | UpgradeClusterClientYamlTestSuiteIT.test {p0=mixed_cluster/10_basic/Index data and search on the mixed cluster} <<< FAILURES!
   > Throwable #1: java.lang.AssertionError: Failure at [mixed_cluster/10_basic:3]: expected [2xx] status code but api [cluster.health] returned [408 Request Timeout] [{"cluster_name":"rolling-upgrade","status":"yellow","timed_out":true,"number_of_nodes":2,"number_of_data_nodes":2,"active_primary_shards":10,"active_shards":14,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1,"delayed_unassigned_shards":0,"number_of_pending_tasks":0,"number_of_in_flight_fetch":0,"task_max_waiting_in_queue_millis":0,"active_shards_percent_as_number":93.33333333333333}]
   > 	at __randomizedtesting.SeedInfo.seed([BF13612A12738489:37475EF0BC8FE971]:0)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:348)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.test(ESClientYamlSuiteTestCase.java:328)
   > 	at java.lang.Thread.run(Thread.java:748)
   > Caused by: java.lang.AssertionError: expected [2xx] status code but api [cluster.health] returned [408 Request Timeout] [{"cluster_name":"rolling-upgrade","status":"yellow","timed_out":true,"number_of_nodes":2,"number_of_data_nodes":2,"active_primary_shards":10,"active_shards":14,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1,"delayed_unassigned_shards":0,"number_of_pending_tasks":0,"number_of_in_flight_fetch":0,"task_max_waiting_in_queue_millis":0,"active_shards_percent_as_number":93.33333333333333}]
   > 	at org.elasticsearch.test.rest.yaml.section.DoSection.execute(DoSection.java:238)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:344)
   > 	... 38 more

[dimitris-athanasiou]

And another: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+5.5+bwc-tests/41/console

[tlrx]

And another: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+g1gc/3261/console

See
consoleText.txt

[spinscale]

One more https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+5.x+bwc-tests/65/console

See console.txt

[spinscale]

One more https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+aggressive-opts/282/console

See plain text output

[danielmitterdorfer]

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+5.5+bwc-tests/62/console

  > Throwable #1: java.lang.AssertionError: Failure at [mixed_cluster/10_basic:3]: expected [2xx] status code but api [cluster.health] returned [408 Request Timeout] [{"cluster_name":"rolling-upgrade","status":"yellow","timed_out":true,"number_of_nodes":2,"number_of_data_nodes":2,"active_primary_shards":10,"active_shards":14,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1,"delayed_unassigned_shards":0,"number_of_pending_tasks":0,"number_of_in_flight_fetch":0,"task_max_waiting_in_queue_millis":0,"active_shards_percent_as_number":93.33333333333333}]
   > 	at __randomizedtesting.SeedInfo.seed([FDE37FFF5F4967BC:75B74025F1B50A44]:0)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:345)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.test(ESClientYamlSuiteTestCase.java:325)
   > 	at java.lang.Thread.run(Thread.java:748)
   > Caused by: java.lang.AssertionError: expected [2xx] status code but api [cluster.health] returned [408 Request Timeout] [{"cluster_name":"rolling-upgrade","status":"yellow","timed_out":true,"number_of_nodes":2,"number_of_data_nodes":2,"active_primary_shards":10,"active_shards":14,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1,"delayed_unassigned_shards":0,"number_of_pending_tasks":0,"number_of_in_flight_fetch":0,"task_max_waiting_in_queue_millis":0,"active_shards_percent_as_number":93.33333333333333}]
   > 	at org.elasticsearch.test.rest.yaml.section.DoSection.execute(DoSection.java:238)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:341)
   > 	... 38 more

[droberts195]

Two more:

• https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+5.x+bwc-tests/89/consoleFull

  1> [2017-06-30T07:09:03,141][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] Stash dump on failure [{
  1>   "stash" : {
  1>     "body" : {
  1>       "cluster_name" : "rolling-upgrade",
  1>       "status" : "yellow",
  1>       "timed_out" : true,
  1>       "number_of_nodes" : 2,
  1>       "number_of_data_nodes" : 2,
  1>       "active_primary_shards" : 10,
  1>       "active_shards" : 14,
  1>       "relocating_shards" : 0,
  1>       "initializing_shards" : 0,
  1>       "unassigned_shards" : 1,
  1>       "delayed_unassigned_shards" : 0,
  1>       "number_of_pending_tasks" : 0,
  1>       "number_of_in_flight_fetch" : 0,
  1>       "task_max_waiting_in_queue_millis" : 0,
  1>       "active_shards_percent_as_number" : 93.33333333333333
  1>     }
  1>   }
  1> }]
  2> REPRODUCE WITH: gradle :qa:rolling-upgrade:v5.0.0#mixedClusterTestRunner -Dtests.seed=AE7950E263BD4070 -Dtests.class=org.elasticsearch.upgrades.UpgradeClusterClientYamlTestSuiteIT -Dtests.method="test {p0=mixed_cluster/10_basic/Index data and search on the mixed cluster}" -Dtests.security.manager=true -Dtests.locale=ar-IQ -Dtests.timezone=Asia/Thimphu -Dtests.rest.suite=mixed_cluster
FAILURE 30.5s | UpgradeClusterClientYamlTestSuiteIT.test {p0=mixed_cluster/10_basic/Index data and search on the mixed cluster} <<< FAILURES!
   > Throwable #1: java.lang.AssertionError: Failure at [mixed_cluster/10_basic:3]: expected [2xx] status code but api [cluster.health] returned [408 Request Timeout] [{"cluster_name":"rolling-upgrade","status":"yellow","timed_out":true,"number_of_nodes":2,"number_of_data_nodes":2,"active_primary_shards":10,"active_shards":14,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1,"delayed_unassigned_shards":0,"number_of_pending_tasks":0,"number_of_in_flight_fetch":0,"task_max_waiting_in_queue_millis":0,"active_shards_percent_as_number":93.33333333333333}]
   > 	at __randomizedtesting.SeedInfo.seed([AE7950E263BD4070:262D6F38CD412D88]:0)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:345)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.test(ESClientYamlSuiteTestCase.java:325)
   > 	at java.lang.Thread.run(Thread.java:748)
   > Caused by: java.lang.AssertionError: expected [2xx] status code but api [cluster.health] returned [408 Request Timeout] [{"cluster_name":"rolling-upgrade","status":"yellow","timed_out":true,"number_of_nodes":2,"number_of_data_nodes":2,"active_primary_shards":10,"active_shards":14,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1,"delayed_unassigned_shards":0,"number_of_pending_tasks":0,"number_of_in_flight_fetch":0,"task_max_waiting_in_queue_millis":0,"active_shards_percent_as_number":93.33333333333333}]
   > 	at org.elasticsearch.test.rest.yaml.section.DoSection.execute(DoSection.java:238)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:341)
   > 	... 38 more

• https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-intake/1517/consoleFull

  1> [2017-06-30T23:02:44,847][INFO ][o.e.u.UpgradeClusterClientYamlTestSuiteIT] Stash dump on failure [{
  2> REPRODUCE WITH: gradle :qa:rolling-upgrade:v5.6.0-SNAPSHOT#mixedClusterTestRunner -Dtests.seed=F5D863A2CAA73CD4 -Dtests.class=org.elasticsearch.upgrades.UpgradeClusterClientYamlTestSuiteIT -Dtests.method="test {p0=mixed_cluster/10_basic/Index data and search on the mixed cluster}" -Dtests.security.manager=true -Dtests.locale=ar-BH -Dtests.timezone=Asia/Ulan_Bator -Dtests.rest.suite=mixed_cluster
  1>   "stash" : {
  1>     "body" : {
  1>       "cluster_name" : "rolling-upgrade",
  1>       "status" : "yellow",
  1>       "timed_out" : true,
  1>       "number_of_nodes" : 2,
  1>       "number_of_data_nodes" : 2,
  1>       "active_primary_shards" : 10,
  1>       "active_shards" : 14,
  1>       "relocating_shards" : 0,
  1>       "initializing_shards" : 0,
  1>       "unassigned_shards" : 1,
  1>       "delayed_unassigned_shards" : 0,
  1>       "number_of_pending_tasks" : 0,
  1>       "number_of_in_flight_fetch" : 0,
  1>       "task_max_waiting_in_queue_millis" : 0,
  1>       "active_shards_percent_as_number" : 93.33333333333333
  1>     }
  1>   }
  1> }]
FAILURE 30.5s | UpgradeClusterClientYamlTestSuiteIT.test {p0=mixed_cluster/10_basic/Index data and search on the mixed cluster} <<< FAILURES!
   > Throwable #1: java.lang.AssertionError: Failure at [mixed_cluster/10_basic:3]: expected [2xx] status code but api [cluster.health] returned [408 Request Timeout] [{"cluster_name":"rolling-upgrade","status":"yellow","timed_out":true,"number_of_nodes":2,"number_of_data_nodes":2,"active_primary_shards":10,"active_shards":14,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1,"delayed_unassigned_shards":0,"number_of_pending_tasks":0,"number_of_in_flight_fetch":0,"task_max_waiting_in_queue_millis":0,"active_shards_percent_as_number":93.33333333333333}]
   > 	at __randomizedtesting.SeedInfo.seed([F5D863A2CAA73CD4:7D8C5C78645B512C]:0)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:348)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.test(ESClientYamlSuiteTestCase.java:328)
   > 	at java.lang.Thread.run(Thread.java:748)
   > Caused by: java.lang.AssertionError: expected [2xx] status code but api [cluster.health] returned [408 Request Timeout] [{"cluster_name":"rolling-upgrade","status":"yellow","timed_out":true,"number_of_nodes":2,"number_of_data_nodes":2,"active_primary_shards":10,"active_shards":14,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1,"delayed_unassigned_shards":0,"number_of_pending_tasks":0,"number_of_in_flight_fetch":0,"task_max_waiting_in_queue_millis":0,"active_shards_percent_as_number":93.33333333333333}]
   > 	at org.elasticsearch.test.rest.yaml.section.DoSection.execute(DoSection.java:238)
   > 	at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:344)
   > 	... 38 more