Rolling-upgrade RecoveryIT tests are broken

[DaveCTurner]

The 6.x intake builds have been broken for most of today, with clusters failing to pass their wait conditions properly:

[ant:echo] ==> [Thu Nov 15 05:56:30 UTC 2018] checking health: http://[::1]:35001/_cluster/health?wait_for_nodes=>=1&wait_for_status=yellow
     [echo] ==> [Thu Nov 15 05:56:30 UTC 2018] checking health: http://[::1]:35001/_cluster/health?wait_for_nodes=>=1&wait_for_status=yellow
[ant:get] Getting: http://[::1]:35001/_cluster/health?wait_for_nodes=>=1&wait_for_status=yellow
      [get] Getting: http://[::1]:35001/_cluster/health?wait_for_nodes=>=1&wait_for_status=yellow
[ant:get] To: /var/lib/jenkins/workspace/elastic+elasticsearch+6.x+intake/qa/rolling-upgrade/build/cluster/v5.6.14#upgradedClusterTestCluster node0/cwd/wait.success
      [get] To: /var/lib/jenkins/workspace/elastic+elasticsearch+6.x+intake/qa/rolling-upgrade/build/cluster/v5.6.14#upgradedClusterTestCluster node0/cwd/wait.success

[ant:get] Error opening connection java.io.IOException: Server returned HTTP response code: 408 for URL: http://[::1]:35001/_cluster/health?wait_for_nodes=>=1&wait_for_status=yellow
      [get] Error opening connection java.io.IOException: Server returned HTTP response code: 408 for URL: http://[::1]:35001/_cluster/health?wait_for_nodes=>=1&wait_for_status=yellow
[ant:get] Error opening connection java.io.IOException: Server returned HTTP response code: 408 for URL: http://[::1]:35001/_cluster/health?wait_for_nodes=>=1&wait_for_status=yellow

This is from https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+intake/197/console although there are lots of other similar failures.

There's nothing obvious to me in the node logs themselves - the 3-node cluster looks to have formed fine. It does seem to reproduce locally, and @original-brownbear and I have been looking at this for a few hours without too much success. I will mute this test suite.

[DaveCTurner]

It is perhaps notable that all of the failures I can see have been in the two-thirds upgraded cluster or the fully-upgraded cluster. We've also seen cases where the cluster does form but then times out in a subsequent health check:

ERROR   70.6s | RecoveryIT.testRecoveryWithConcurrentIndexing <<< FAILURES!
   > Throwable #1: org.elasticsearch.client.ResponseException: method [GET], host [http://[::1]:44918], URI [/_cluster/health/recovery_with_concurrent_indexing?wait_for_no_relocating_shards=true&level=shards&timeout=70s&wait_for_status=green], status line [HTTP/1.1 408 Request Timeout]
   > {"cluster_name":"rolling-upgrade","status":"yellow","timed_out":true,"number_of_nodes":3,"number_of_data_nodes":3,"active_primary_shards":1,"active_shards":2,"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":98.68421052631578,"indices":{"recovery_with_concurrent_indexing":{"status":"yellow","number_of_shards":1,"number_of_replicas":2,"active_primary_shards":1,"active_shards":2,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1,"shards":{"0":{"status":"yellow","primary_active":true,"active_shards":2,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1}}}}}
   > 	at __randomizedtesting.SeedInfo.seed([DA5FC8F3EE50997:8DF438DCBC41D75D]:0)
   > 	at org.elasticsearch.client.RestClient$SyncResponseListener.get(RestClient.java:926)
   > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:229)
   > 	at org.elasticsearch.test.rest.ESRestTestCase.ensureGreen(ESRestTestCase.java:711)
   > 	at org.elasticsearch.upgrades.RecoveryIT.testRecoveryWithConcurrentIndexing(RecoveryIT.java:141)
   > 	at java.lang.Thread.run(Thread.java:748)
   > Caused by: org.elasticsearch.client.ResponseException: method [GET], host [http://[::1]:44918], URI [/_cluster/health/recovery_with_concurrent_indexing?wait_for_no_relocating_shards=true&level=shards&timeout=70s&wait_for_status=green], status line [HTTP/1.1 408 Request Timeout]
   > {"cluster_name":"rolling-upgrade","status":"yellow","timed_out":true,"number_of_nodes":3,"number_of_data_nodes":3,"active_primary_shards":1,"active_shards":2,"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":98.68421052631578,"indices":{"recovery_with_concurrent_indexing":{"status":"yellow","number_of_shards":1,"number_of_replicas":2,"active_primary_shards":1,"active_shards":2,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1,"shards":{"0":{"status":"yellow","primary_active":true,"active_shards":2,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1}}}}}
   > 	at org.elasticsearch.client.RestClient$1.completed(RestClient.java:546)
   > 	at org.elasticsearch.client.RestClient$1.completed(RestClient.java:531)
   > 	at org.apache.http.concurrent.BasicFuture.completed(BasicFuture.java:119)
   > 	at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.responseCompleted(DefaultClientExchangeHandlerImpl.java:177)
   > 	at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.processResponse(HttpAsyncRequestExecutor.java:436)
   > 	at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.inputReady(HttpAsyncRequestExecutor.java:326)
   > 	at org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(DefaultNHttpClientConnection.java:265)
   > 	at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:81)
   > 	at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:39)
   > 	at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:114)
   > 	at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:162)
   > 	at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:337)
   > 	at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315)
   > 	at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:276)
   > 	at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
   > 	at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:588)
   > 	... 1 more

(from https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+intake/186/console)

Unfortunately the first few failures in the sequence of broken builds on 6.x seem unrelated to this one, with more changes having been pushed on top of the red CI, so it's hard to narrow down the point at which things started to break. Looking at the changes, I wonder if perhaps #34902 or #35332 could have this sort of effect?

Anyhow, muted in 188de54.

[DaveCTurner]

Ok I reverted 0c5e87f (#35332) and that seemed to clear it up. Letting @tlrx know.

Edit: I do not mean I reverted this in 6.x, just on my local machine.

[tlrx]

@DaveCTurner Sorry to hear that, this is concerning. I'm looking at this.

[tlrx]

Also muted the test in master in f9aff7b

[tlrx]

Thanks @DaveCTurner, your preliminary investigation helped a lot. I reverted #35332 from master in d3d7c01 and 6.x in c70b8ac and unmuted the test.