[Test] Connection timeout in RecoveryIT#testRecoverSyncedFlushIndex on rolling-upgrade

[cbuescher]

This happened on 6.x: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+default-distro-bwc-tests/149/console

07:32:46 ERROR   70.7s | RecoveryIT.testRecoverSyncedFlushIndex <<< FAILURES!
07:32:46    > Throwable #1: org.elasticsearch.client.ResponseException: method [GET], host [http://[::1]:42775], URI [/_cluster/health/recover_synced_flush_index?wait_for_no_relocating_shards=true&level=shards&timeout=70s&wait_for_status=green], status line [HTTP/1.1 408 Request Timeout]
07:32:46   2> NOTE: leaving temporary files on disk at: /var/lib/jenkins/workspace/elastic+elasticsearch+6.x+default-distro-bwc-tests/qa/rolling-upgrade/build/testrun/v6.3.2-SNAPSHOT#oneThirdUpgradedTestRunner/J0/temp/org.elasticsearch.upgrades.RecoveryIT_6C47D2BFDE00AF80-001
07:32:46    > {"cluster_name":"rolling-upgrade","status":"yellow","timed_out":true,"number_of_nodes":3,"number_of_data_nodes":3,"active_primary_shards":1,"active_shards":1,"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":96.84210526315789,"indices":{"recover_synced_flush_index":{"status":"yellow","number_of_shards":1,"number_of_replicas":1,"active_primary_shards":1,"active_shards":1,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1,"shards":{"0":{"status":"yellow","primary_active":true,"active_shards":1,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1}}}}}
07:32:46    > 	at __randomizedtesting.SeedInfo.seed([6C47D2BFDE00AF80:47760F687957DAC9]:0)
07:32:46    > 	at org.elasticsearch.client.RestClient$SyncResponseListener.get(RestClient.java:920)
07:32:46   2> NOTE: test params are: codec=Asserting(Lucene70): {}, docValues:{}, maxPointsInLeafNode=597, maxMBSortInHeap=6.887940697412328, sim=RandomSimilarity(queryNorm=true): {}, locale=es-BO, timezone=Asia/Irkutsk
07:32:46   2> NOTE: Linux 4.16.8-300.fc28.x86_64 amd64/Oracle Corporation 1.8.0_172 (64-bit)/cpus=16,threads=1,free=442107176,total=514850816
07:32:46   2> NOTE: All tests run in this JVM: [RecoveryIT]
07:32:46    > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:227)
07:32:46    > 	at org.elasticsearch.test.rest.ESRestTestCase.ensureGreen(ESRestTestCase.java:513)
07:32:46    > 	at org.elasticsearch.upgrades.RecoveryIT.testRecoverSyncedFlushIndex(RecoveryIT.java:318)
07:32:46    > 	at java.lang.Thread.run(Thread.java:748)
07:32:46    > Caused by: org.elasticsearch.client.ResponseException: method [GET], host [http://[::1]:42775], URI [/_cluster/health/recover_synced_flush_index?wait_for_no_relocating_shards=true&level=shards&timeout=70s&wait_for_status=green], status line [HTTP/1.1 408 Request Timeout]
07:32:46    > {"cluster_name":"rolling-upgrade","status":"yellow","timed_out":true,"number_of_nodes":3,"number_of_data_nodes":3,"active_primary_shards":1,"active_shards":1,"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":96.84210526315789,"indices":{"recover_synced_flush_index":{"status":"yellow","number_of_shards":1,"number_of_replicas":1,"active_primary_shards":1,"active_shards":1,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1,"shards":{"0":{"status":"yellow","primary_active":true,"active_shards":1,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1}}}}}
07:32:46    > 	at org.elasticsearch.client.RestClient$1.completed(RestClient.java:540)
07:32:46    > 	at org.elasticsearch.client.RestClient$1.completed(RestClient.java:529)
07:32:46    > 	at org.apache.http.concurrent.BasicFuture.completed(BasicFuture.java:119)
07:32:46    > 	at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.responseCompleted(DefaultClientExchangeHandlerImpl.java:177)
07:32:46    > 	at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.processResponse(HttpAsyncRequestExecutor.java:436)
07:32:46    > 	at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.inputReady(HttpAsyncRequestExecutor.java:326)
07:32:46    > 	at org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(DefaultNHttpClientConnection.java:265)
07:32:46    > 	at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:81)
07:32:46    > 	at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:39)
07:32:46    > 	at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:114)
07:32:46    > 	at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:162)
07:32:46    > 	at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:337)
07:32:46    > 	at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315)
07:32:46    > 	at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:276)
07:32:46    > 	at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
07:32:46    > 	at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:588)
07:32:46    > 	... 1 more

This sadly doesn't reproduce locally:

./gradlew :qa:rolling-upgrade:v6.3.2-SNAPSHOT#oneThirdUpgradedTestRunner -Dtests.seed=6C47D2BFDE00AF80 -Dtests.class=org.elasticsearch.upgrades.RecoveryIT -Dtests.method="testRecoverSyncedFlushIndex" -Dtests.security.manager=true -Dtests.locale=es-BO -Dtests.timezone=Asia/Irkutsk -Dtests.distribution=zip

[elasticmachine]

Pinging @elastic/es-distributed

[ywelsch]

The logs are unfortunately lost on this one, so we will have to wait for another failure of this. Closing until such a failure happens again.

[tlrx]

RecoveryIT.testRecoverSyncedFlushIndex failed again today on CI:

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.7+bwc-tests/86/consoleFull

It reproduces using:

./gradlew :qa:rolling-upgrade:v6.6.0#oneThirdUpgradedTestRunner -Dtests.seed=7C050A5AAA4A67D1 -Dtests.class=org.elasticsearch.upgrades.RecoveryIT -Dtests.method="testRecoverSyncedFlushIndex" -Dtests.security.manager=true -Dtests.locale=vi -Dtests.timezone=America/Indiana/Petersburg -Dcompiler.java=11 -Druntime.java=8

10:10:16 1> [2019-02-27T05:09:03,606][INFO ][o.e.u.RecoveryIT ] [testRecoverSyncedFlushIndex] before test 10:10:16 1> [2019-02-27T05:10:13,634][INFO ][o.e.u.RecoveryIT ] [testRecoverSyncedFlushIndex] after test 10:10:16 2> REPRODUCE WITH: ./gradlew :qa:rolling-upgrade:v6.6.0#oneThirdUpgradedTestRunner -Dtests.seed=7C050A5AAA4A67D1 -Dtests.class=org.elasticsearch.upgrades.RecoveryIT -Dtests.method="testRecoverSyncedFlushIndex" -Dtests.security.manager=true -Dtests.locale=vi -Dtests.timezone=America/Indiana/Petersburg -Dcompiler.java=11 -Druntime.java=8 10:10:16 ERROR 70.0s | RecoveryIT.testRecoverSyncedFlushIndex <<< FAILURES! 10:10:16 2> NOTE: leaving temporary files on disk at: /var/lib/jenkins/workspace/elastic+elasticsearch+6.7+bwc-tests/qa/rolling-upgrade/build/testrun/v6.6.0#oneThirdUpgradedTestRunner/J0/temp/org.elasticsearch.upgrades.RecoveryIT_7C050A5AAA4A67D1-001 10:10:16 > Throwable #1: org.elasticsearch.client.ResponseException: method [GET], host [http://[::1]:34493], URI [/_cluster/health/recover_synced_flush_index?wait_for_no_relocating_shards=true&level=shards&timeout=70s&wait_for_status=green], status line [HTTP/1.1 408 Request Timeout] 10:10:16 > {"cluster_name":"rolling-upgrade","status":"yellow","timed_out":true,"number_of_nodes":3,"number_of_data_nodes":3,"active_primary_shards":1,"active_shards":1,"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":96.0,"indices":{"recover_synced_flush_index":{"status":"yellow","number_of_shards":1,"number_of_replicas":1,"active_primary_shards":1,"active_shards":1,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1,"shards":{"0":{"status":"yellow","primary_active":true,"active_shards":1,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1}}}}} 10:10:16 2> NOTE: test params are: codec=Asserting(Lucene70), sim=RandomSimilarity(queryNorm=true): {}, locale=vi, timezone=America/Indiana/Petersburg 10:10:16 2> NOTE: Linux 4.15.0-1027-gcp amd64/Oracle Corporation 1.8.0_202 (64-bit)/cpus=16,threads=1,free=383006912,total=514850816 10:10:16 > at __randomizedtesting.SeedInfo.seed([7C050A5AAA4A67D1:5734D78D0D1D1298]:0) 10:10:16 > at org.elasticsearch.client.RestClient$SyncResponseListener.get(RestClient.java:936) 10:10:16 > at org.elasticsearch.client.RestClient.performRequest(RestClient.java:233) 10:10:16 2> NOTE: All tests run in this JVM: [IndexingIT, RecoveryIT] 10:10:16 > at org.elasticsearch.test.rest.ESRestTestCase.ensureGreen(ESRestTestCase.java:775) 10:10:16 > at org.elasticsearch.upgrades.RecoveryIT.testRecoverSyncedFlushIndex(RecoveryIT.java:318) 10:10:16 > at java.lang.Thread.run(Thread.java:748) 10:10:16 > Caused by: org.elasticsearch.client.ResponseException: method [GET], host [http://[::1]:34493], URI [/_cluster/health/recover_synced_flush_index?wait_for_no_relocating_shards=true&level=shards&timeout=70s&wait_for_status=green], status line [HTTP/1.1 408 Request Timeout] 10:10:16 > {"cluster_name":"rolling-upgrade","status":"yellow","timed_out":true,"number_of_nodes":3,"number_of_data_nodes":3,"active_primary_shards":1,"active_shards":1,"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":96.0,"indices":{"recover_synced_flush_index":{"status":"yellow","number_of_shards":1,"number_of_replicas":1,"active_primary_shards":1,"active_shards":1,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1,"shards":{"0":{"status":"yellow","primary_active":true,"active_shards":1,"relocating_shards":0,"initializing_shards":0,"unassigned_shards":1}}}}} 10:10:16 > at org.elasticsearch.client.RestClient$1.completed(RestClient.java:552) 10:10:16 > at org.elasticsearch.client.RestClient$1.completed(RestClient.java:537) 10:10:16 > at org.apache.http.concurrent.BasicFuture.completed(BasicFuture.java:119) 10:10:16 > at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.responseCompleted(DefaultClientExchangeHandlerImpl.java:177) 10:10:16 > at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.processResponse(HttpAsyncRequestExecutor.java:436) 10:10:16 > at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.inputReady(HttpAsyncRequestExecutor.java:326) 10:10:16 > at org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(DefaultNHttpClientConnection.java:265) 10:10:16 > at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:81) 10:10:16 > at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:39) 10:10:16 > at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:114) 10:10:16 > at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:162) 10:10:16 > at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:337) 10:10:16 > at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315) 10:10:16 > at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:276) 10:10:16 > at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104) 10:10:16 > at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:588) 10:10:16 > ... 1 more

Sadly I can't connect to the worker to grab the logs.

[dnhatn]

I am on it today.

[dnhatn]

I suspect this is a bug in allocation but could not figure it out after spending on some good time. Some important events in the test.

1. node-0 is the master, the index recover_synced_flush_index has primary on node-1, and replica on node-2.

2. Before we shut down node-0 to upgrade, we relocate the primary of recover_synced_flush_index from node-1 to node-0. And node-0 is stopped before we can move the relocating target to started

3. node-1 is elected as the master and failing the relocating target on node-0, then move the relocating source on node-1 back to started.

[2019-02-27T10:08:48,612][DEBUG][o.e.c.r.a.AllocationService] [node-1] [recover_synced_flush_index][0] failing shard [recover_synced_flush_index][0], node[HZ9A5r6xT2Cewlb3YqIg8g], relocating [W0zYyliTQsmieW42pX6mYw], [P], recovery_source[peer recovery], s[INITIALIZING], a[id=sJILiyxiTlWMYj70-z5Irw, rId=KATt9QvpSIOykrBXyfEJjA] with unassigned info ([reason=NODE_LEFT], at[2019-02-27T10:08:48.612Z], delayed=true, details[node_left[HZ9A5r6xT2Cewlb3YqIg8g]], allocation_status[no_attempt])

4. The relocating source on node-1 is marked already as relocated; it has to fail itself because it can't move back to started.

[2019-02-27T10:08:48,802][WARN ][o.e.i.c.IndicesClusterStateService] [node-1] [[recover_synced_flush_index][0]] marking and sending shard failed due to [failed updating shard routing entry]
org.elasticsearch.index.shard.IndexShardRelocatedException: CurrentState[STARTED] Shard is marked as relocated, cannot safely move to state STARTED

5. The relocating source on node-1 sends another shard-failure request.

[2019-02-27T10:08:48,935][DEBUG][o.e.c.a.s.ShardStateAction] [node-1] [recover_synced_flush_index][0] received shard failed for shard id [[recover_synced_flush_index][0]], allocation id [KATt9QvpSIOykrBXyfEJjA], primary term [0], message [master {node-1}{W0zYyliTQsmieW42pX6mYw}{V6CIni9vSFOGaBNzNP-2jw}{127.0.0.1}{127.0.0.1:36807}{gen=old, testattr=test} has not removed previously failed shard. resending shard failure], markAsStale [true]
[2019-02-27T10:08:48,935][DEBUG][o.e.i.c.IndicesClusterStateService] [node-1] [[recover_with_soft_deletes/X_XCi9RpQpKeKpdGj5MhoA]] creating index

6. The master fails the relocating source

[2019-02-27T10:08:48,969][DEBUG][o.e.c.r.a.AllocationService] [node-1] [recover_synced_flush_index][0] failing shard [recover_synced_flush_index][0], node[W0zYyliTQsmieW42pX6mYw], [P], s[STARTED], a[id=KATt9QvpSIOykrBXyfEJjA] with unassigned info ([reason=ALLOCATION_FAILED], at[2019-02-27T10:08:48.968Z], failed_attempts[1], delayed=false, details[failed shard on node [W0zYyliTQsmieW42pX6mYw]: failed updating shard routing entry, failure IndexShardRelocatedException[CurrentState[STARTED] Shard is marked as relocated, cannot safely move to state STARTED]], allocation_status[no_attempt])

7. We execute several reroutes afterward, but the index recover_synced_flush_index remains unassigned.

I looked at RoutingNodes, AllocationService and Gateway code but yield no fruit. Perhaps it's a timeout issue, but this failure looks suspicious to me. @ywelsch Can you please continue the investigation?

Logs:
node-0.log
node-1.log
node-2.log
upgraded-node-0.log
recovery_with_synced_flush.txt

[ywelsch]

I checked all the logs on this and cannot see why the replica is not being allocated, even after 70 seconds. Beside running this with TRACE logging (which is tricky as it means running all tests with TRACE logging), I wonder if we should extend ensureGreen in ESTestTestCase similar to how we do it in ESIntegTestCase, by querying the cluster state and possibly the allocation explain API for that index to get a better understanding of why the shard is not getting allocated.

[dnhatn]

I wonder if we should extend ensureGreen in ESTestTestCase similar to how we do it in ESIntegTestCase, by querying the cluster state and possibly the allocation explain API for that index to get a better understanding of why the shard is not getting allocated.

+1. I will do this.