Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

CI: RecoveryWhileUnderLoadIT:testRecoverWhileRelocating failures #24584

Closed
imotov opened this issue May 10, 2017 · 4 comments
Closed

CI: RecoveryWhileUnderLoadIT:testRecoverWhileRelocating failures #24584

imotov opened this issue May 10, 2017 · 4 comments
Assignees
@jasontedor
Labels
>test Issues or PRs that are addressing/adding tests >test-failure Triaged test failures from CI

Comments

@imotov
Copy link
Contributor

imotov commented May 10, 2017

Failed twice so far today:
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-intake/1224/console
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-intake/1226/console

1> [2017-05-10T11:29:32,898][INFO ][o.e.r.RecoveryWhileUnderLoadIT] [RecoveryWhileUnderLoadIT#testRecoverWhileRelocating]: cleaning up after test
  1> [2017-05-10T11:29:42,929][INFO ][o.e.r.RecoveryWhileUnderLoadIT] [testRecoverWhileRelocating]: after test
ERROR    676s J2 | RecoveryWhileUnderLoadIT.testRecoverWhileRelocating <<< FAILURES!
   > Throwable #1: java.lang.AssertionError: timed out waiting for green state
   > 	at org.elasticsearch.test.ESIntegTestCase.ensureColor(ESIntegTestCase.java:944)
   > 	at org.elasticsearch.test.ESIntegTestCase.ensureGreen(ESIntegTestCase.java:910)
   > 	at org.elasticsearch.recovery.RecoveryWhileUnderLoadIT.testRecoverWhileRelocating(RecoveryWhileUnderLoadIT.java:252)
   > 	at java.lang.Thread.run(Thread.java:748)
   > 	Suppressed: java.lang.AssertionError: timeout while waiting for indexing threads to stop
   > Expected: <true>
   >      but: was <false>
   > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
   > 		at org.elasticsearch.test.BackgroundIndexer.stop(BackgroundIndexer.java:279)
   > 		at org.elasticsearch.test.BackgroundIndexer.close(BackgroundIndexer.java:307)
   > 		at org.elasticsearch.recovery.RecoveryWhileUnderLoadIT.testRecoverWhileRelocating(RecoveryWhileUnderLoadIT.java:268)
   > 		... 37 moreThrowable #2: java.lang.AssertionError: expected index shard counter on shard [test][0] on node node_s2 to be 0 but was 1. Current replication tasks on node:
   > {
   >   "tasks" : {
   >     "k-1ujp2ySie63_LzG0OS5g:308" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 308,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s]",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404313505,
   >       "running_time_in_nanos" : 669423966888,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9724",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 309,
   >           "type" : "direct",
   >           "action" : "indices:data/write/bulk[s][p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "requests[1], index[test]",
   >           "start_time_in_millis" : 1494404313505,
   >           "running_time_in_nanos" : 669423933619,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:308"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:937" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 937,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >       "start_time_in_millis" : 1494404616959,
   >       "running_time_in_nanos" : 365969720414,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:10977",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 938,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404616959,
   >           "running_time_in_nanos" : 365969658760,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:937"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:153" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 153,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s][p]",
   >       "status" : {
   >         "phase" : "primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404312625,
   >       "running_time_in_nanos" : 670303304826,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9088"
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:943" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 943,
   >       "type" : "transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=DEFAULT}",
   >       "start_time_in_millis" : 1494404618177,
   >       "running_time_in_nanos" : 364751804014,
   >       "cancellable" : false,
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 945,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404618177,
   >           "running_time_in_nanos" : 364751741780,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:943"
   >         }
   >       ]
   >     }
   >   }
   > }
   > 	at org.elasticsearch.test.InternalTestCluster.lambda$assertShardIndexCounter$5(InternalTestCluster.java:1158)
   > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:716)
   > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:690)
   > 	at org.elasticsearch.test.InternalTestCluster.assertShardIndexCounter(InternalTestCluster.java:1139)
   > 	at org.elasticsearch.test.InternalTestCluster.beforeIndexDeletion(InternalTestCluster.java:1109)
   > 	at org.elasticsearch.test.ESIntegTestCase.beforeIndexDeletion(ESIntegTestCase.java:611)
   > 	at org.elasticsearch.test.ESIntegTestCase.afterInternal(ESIntegTestCase.java:581)
   > 	at org.elasticsearch.test.ESIntegTestCase.cleanUpCluster(ESIntegTestCase.java:2059)
   > 	at java.lang.Thread.run(Thread.java:748)
   > 	Suppressed: java.lang.AssertionError: expected index shard counter on shard [test][0] on node node_s2 to be 0 but was 1. Current replication tasks on node:
   > {
   >   "tasks" : {
   >     "k-1ujp2ySie63_LzG0OS5g:308" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 308,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s]",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404313505,
   >       "running_time_in_nanos" : 659415504791,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9724",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 309,
   >           "type" : "direct",
   >           "action" : "indices:data/write/bulk[s][p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "requests[1], index[test]",
   >           "start_time_in_millis" : 1494404313505,
   >           "running_time_in_nanos" : 659415472851,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:308"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:937" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 937,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >       "start_time_in_millis" : 1494404616959,
   >       "running_time_in_nanos" : 355961260506,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:10977",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 938,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404616959,
   >           "running_time_in_nanos" : 355961200258,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:937"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:153" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 153,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s][p]",
   >       "status" : {
   >         "phase" : "primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404312625,
   >       "running_time_in_nanos" : 660294845655,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9088"
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:943" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 943,
   >       "type" : "transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=DEFAULT}",
   >       "start_time_in_millis" : 1494404618177,
   >       "running_time_in_nanos" : 354743346033,
   >       "cancellable" : false,
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 945,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404618177,
   >           "running_time_in_nanos" : 354743257214,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:943"
   >         }
   >       ]
   >     }
   >   }
   > }
   > 		at org.elasticsearch.test.InternalTestCluster.lambda$assertShardIndexCounter$5(InternalTestCluster.java:1158)
   > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:704)
   > 		... 41 more
   > 	Suppressed: java.lang.AssertionError: expected index shard counter on shard [test][0] on node node_s2 to be 0 but was 1. Current replication tasks on node:
   > {
   >   "tasks" : {
   >     "k-1ujp2ySie63_LzG0OS5g:308" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 308,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s]",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404313505,
   >       "running_time_in_nanos" : 659419680615,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9724",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 309,
   >           "type" : "direct",
   >           "action" : "indices:data/write/bulk[s][p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "requests[1], index[test]",
   >           "start_time_in_millis" : 1494404313505,
   >           "running_time_in_nanos" : 659419647912,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:308"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:937" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 937,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >       "start_time_in_millis" : 1494404616959,
   >       "running_time_in_nanos" : 355965435282,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:10977",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 938,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404616959,
   >           "running_time_in_nanos" : 355965374796,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:937"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:153" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 153,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s][p]",
   >       "status" : {
   >         "phase" : "primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404312625,
   >       "running_time_in_nanos" : 660299020157,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9088"
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:943" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 943,
   >       "type" : "transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=DEFAULT}",
   >       "start_time_in_millis" : 1494404618177,
   >       "running_time_in_nanos" : 354747520637,
   >       "cancellable" : false,
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 945,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404618177,
   >           "running_time_in_nanos" : 354747455706,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:943"
   >         }
   >       ]
   >     }
   >   }
   > }
   > 		at org.elasticsearch.test.InternalTestCluster.lambda$assertShardIndexCounter$5(InternalTestCluster.java:1158)
   > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:704)
   > 		... 41 more
   > 	Suppressed: java.lang.AssertionError: expected index shard counter on shard [test][0] on node node_s2 to be 0 but was 1. Current replication tasks on node:
   > {
   >   "tasks" : {
   >     "k-1ujp2ySie63_LzG0OS5g:308" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 308,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s]",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404313505,
   >       "running_time_in_nanos" : 659422278717,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9724",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 309,
   >           "type" : "direct",
   >           "action" : "indices:data/write/bulk[s][p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "requests[1], index[test]",
   >           "start_time_in_millis" : 1494404313505,
   >           "running_time_in_nanos" : 659422245290,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:308"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:937" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 937,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >       "start_time_in_millis" : 1494404616959,
   >       "running_time_in_nanos" : 355968032119,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:10977",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 938,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404616959,
   >           "running_time_in_nanos" : 355967970276,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:937"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:153" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 153,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s][p]",
   >       "status" : {
   >         "phase" : "primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404312625,
   >       "running_time_in_nanos" : 660301616487,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9088"
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:943" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 943,
   >       "type" : "transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=DEFAULT}",
   >       "start_time_in_millis" : 1494404618177,
   >       "running_time_in_nanos" : 354750115537,
   >       "cancellable" : false,
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 945,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404618177,
   >           "running_time_in_nanos" : 354750054570,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:943"
   >         }
   >       ]
   >     }
   >   }
   > }
   > 		at org.elasticsearch.test.InternalTestCluster.lambda$assertShardIndexCounter$5(InternalTestCluster.java:1158)
   > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:704)
   > 		... 41 more
   > 	Suppressed: java.lang.AssertionError: expected index shard counter on shard [test][0] on node node_s2 to be 0 but was 1. Current replication tasks on node:
   > {
   >   "tasks" : {
   >     "k-1ujp2ySie63_LzG0OS5g:308" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 308,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s]",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404313505,
   >       "running_time_in_nanos" : 659426647761,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9724",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 309,
   >           "type" : "direct",
   >           "action" : "indices:data/write/bulk[s][p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "requests[1], index[test]",
   >           "start_time_in_millis" : 1494404313505,
   >           "running_time_in_nanos" : 659426616682,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:308"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:937" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 937,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >       "start_time_in_millis" : 1494404616959,
   >       "running_time_in_nanos" : 355972403492,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:10977",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 938,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404616959,
   >           "running_time_in_nanos" : 355972341838,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:937"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:153" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 153,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s][p]",
   >       "status" : {
   >         "phase" : "primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404312625,
   >       "running_time_in_nanos" : 660305987958,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9088"
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:943" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 943,
   >       "type" : "transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=DEFAULT}",
   >       "start_time_in_millis" : 1494404618177,
   >       "running_time_in_nanos" : 354754487114,
   >       "cancellable" : false,
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 945,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404618177,
   >           "running_time_in_nanos" : 354754423877,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:943"
   >         }
   >       ]
   >     }
   >   }
   > }
   > 		at org.elasticsearch.test.InternalTestCluster.lambda$assertShardIndexCounter$5(InternalTestCluster.java:1158)
   > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:704)
   > 		... 41 more
   > 	Suppressed: java.lang.AssertionError: expected index shard counter on shard [test][0] on node node_s2 to be 0 but was 1. Current replication tasks on node:
   > {
   >   "tasks" : {
   >     "k-1ujp2ySie63_LzG0OS5g:308" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 308,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s]",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404313505,
   >       "running_time_in_nanos" : 659434965903,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9724",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 309,
   >           "type" : "direct",
   >           "action" : "indices:data/write/bulk[s][p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "requests[1], index[test]",
   >           "start_time_in_millis" : 1494404313505,
   >           "running_time_in_nanos" : 659434932517,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:308"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:937" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 937,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >       "start_time_in_millis" : 1494404616959,
   >       "running_time_in_nanos" : 355980719346,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:10977",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 938,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404616959,
   >           "running_time_in_nanos" : 355980657588,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:937"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:153" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 153,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s][p]",
   >       "status" : {
   >         "phase" : "primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404312625,
   >       "running_time_in_nanos" : 660314303735,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9088"
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:943" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 943,
   >       "type" : "transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=DEFAULT}",
   >       "start_time_in_millis" : 1494404618177,
   >       "running_time_in_nanos" : 354762802881,
   >       "cancellable" : false,
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 945,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404618177,
   >           "running_time_in_nanos" : 354762742099,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:943"
   >         }
   >       ]
   >     }
   >   }
   > }
   > 		at org.elasticsearch.test.InternalTestCluster.lambda$assertShardIndexCounter$5(InternalTestCluster.java:1158)
   > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:704)
   > 		... 41 more
   > 	Suppressed: java.lang.AssertionError: expected index shard counter on shard [test][0] on node node_s2 to be 0 but was 1. Current replication tasks on node:
   > {
   >   "tasks" : {
   >     "k-1ujp2ySie63_LzG0OS5g:308" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 308,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s]",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404313505,
   >       "running_time_in_nanos" : 659451391085,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9724",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 309,
   >           "type" : "direct",
   >           "action" : "indices:data/write/bulk[s][p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "requests[1], index[test]",
   >           "start_time_in_millis" : 1494404313505,
   >           "running_time_in_nanos" : 659451357764,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:308"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:937" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 937,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >       "start_time_in_millis" : 1494404616959,
   >       "running_time_in_nanos" : 355997144642,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:10977",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 938,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404616959,
   >           "running_time_in_nanos" : 355997082991,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:937"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:153" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 153,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s][p]",
   >       "status" : {
   >         "phase" : "primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404312625,
   >       "running_time_in_nanos" : 660330729065,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9088"
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:943" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 943,
   >       "type" : "transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=DEFAULT}",
   >       "start_time_in_millis" : 1494404618177,
   >       "running_time_in_nanos" : 354779228226,
   >       "cancellable" : false,
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 945,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404618177,
   >           "running_time_in_nanos" : 354779167164,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:943"
   >         }
   >       ]
   >     }
   >   }
   > }
   > 		at org.elasticsearch.test.InternalTestCluster.lambda$assertShardIndexCounter$5(InternalTestCluster.java:1158)
   > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:704)
   > 		... 41 more
   > 	Suppressed: java.lang.AssertionError: expected index shard counter on shard [test][0] on node node_s2 to be 0 but was 1. Current replication tasks on node:
   > {
   >   "tasks" : {
   >     "k-1ujp2ySie63_LzG0OS5g:308" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 308,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s]",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404313505,
   >       "running_time_in_nanos" : 659483739574,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9724",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 309,
   >           "type" : "direct",
   >           "action" : "indices:data/write/bulk[s][p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "requests[1], index[test]",
   >           "start_time_in_millis" : 1494404313505,
   >           "running_time_in_nanos" : 659483706498,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:308"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:937" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 937,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >       "start_time_in_millis" : 1494404616959,
   >       "running_time_in_nanos" : 356029493480,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:10977",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 938,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404616959,
   >           "running_time_in_nanos" : 356029431781,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:937"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:153" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 153,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s][p]",
   >       "status" : {
   >         "phase" : "primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404312625,
   >       "running_time_in_nanos" : 660363077918,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9088"
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:943" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 943,
   >       "type" : "transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=DEFAULT}",
   >       "start_time_in_millis" : 1494404618177,
   >       "running_time_in_nanos" : 354811577099,
   >       "cancellable" : false,
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 945,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404618177,
   >           "running_time_in_nanos" : 354811515611,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:943"
   >         }
   >       ]
   >     }
   >   }
   > }
   > 		at org.elasticsearch.test.InternalTestCluster.lambda$assertShardIndexCounter$5(InternalTestCluster.java:1158)
   > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:704)
   > 		... 41 more
   > 	Suppressed: java.lang.AssertionError: expected index shard counter on shard [test][0] on node node_s2 to be 0 but was 1. Current replication tasks on node:
   > {
   >   "tasks" : {
   >     "k-1ujp2ySie63_LzG0OS5g:308" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 308,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s]",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404313505,
   >       "running_time_in_nanos" : 659548099099,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9724",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 309,
   >           "type" : "direct",
   >           "action" : "indices:data/write/bulk[s][p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "requests[1], index[test]",
   >           "start_time_in_millis" : 1494404313505,
   >           "running_time_in_nanos" : 659548065729,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:308"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:937" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 937,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >       "start_time_in_millis" : 1494404616959,
   >       "running_time_in_nanos" : 356093852606,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:10977",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 938,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404616959,
   >           "running_time_in_nanos" : 356093790845,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:937"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:153" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 153,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s][p]",
   >       "status" : {
   >         "phase" : "primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404312625,
   >       "running_time_in_nanos" : 660427437001,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9088"
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:943" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 943,
   >       "type" : "transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=DEFAULT}",
   >       "start_time_in_millis" : 1494404618177,
   >       "running_time_in_nanos" : 354875936029,
   >       "cancellable" : false,
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 945,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404618177,
   >           "running_time_in_nanos" : 354875874868,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:943"
   >         }
   >       ]
   >     }
   >   }
   > }
   > 		at org.elasticsearch.test.InternalTestCluster.lambda$assertShardIndexCounter$5(InternalTestCluster.java:1158)
   > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:704)
   > 		... 41 more
   > 	Suppressed: java.lang.AssertionError: expected index shard counter on shard [test][0] on node node_s2 to be 0 but was 1. Current replication tasks on node:
   > {
   >   "tasks" : {
   >     "k-1ujp2ySie63_LzG0OS5g:308" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 308,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s]",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404313505,
   >       "running_time_in_nanos" : 659676481152,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9724",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 309,
   >           "type" : "direct",
   >           "action" : "indices:data/write/bulk[s][p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "requests[1], index[test]",
   >           "start_time_in_millis" : 1494404313505,
   >           "running_time_in_nanos" : 659676447992,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:308"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:937" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 937,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >       "start_time_in_millis" : 1494404616959,
   >       "running_time_in_nanos" : 356222234774,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:10977",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 938,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404616959,
   >           "running_time_in_nanos" : 356222173124,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:937"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:153" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 153,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s][p]",
   >       "status" : {
   >         "phase" : "primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404312625,
   >       "running_time_in_nanos" : 660555819215,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9088"
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:943" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 943,
   >       "type" : "transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=DEFAULT}",
   >       "start_time_in_millis" : 1494404618177,
   >       "running_time_in_nanos" : 355004318359,
   >       "cancellable" : false,
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 945,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404618177,
   >           "running_time_in_nanos" : 355004255841,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:943"
   >         }
   >       ]
   >     }
   >   }
   > }
   > 		at org.elasticsearch.test.InternalTestCluster.lambda$assertShardIndexCounter$5(InternalTestCluster.java:1158)
   > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:704)
   > 		... 41 more
   > 	Suppressed: java.lang.AssertionError: expected index shard counter on shard [test][0] on node node_s2 to be 0 but was 1. Current replication tasks on node:
   > {
   >   "tasks" : {
   >     "k-1ujp2ySie63_LzG0OS5g:308" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 308,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s]",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404313505,
   >       "running_time_in_nanos" : 659932894105,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9724",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 309,
   >           "type" : "direct",
   >           "action" : "indices:data/write/bulk[s][p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "requests[1], index[test]",
   >           "start_time_in_millis" : 1494404313505,
   >           "running_time_in_nanos" : 659932860711,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:308"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:937" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 937,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >       "start_time_in_millis" : 1494404616959,
   >       "running_time_in_nanos" : 356478647496,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:10977",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 938,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404616959,
   >           "running_time_in_nanos" : 356478585715,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:937"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:153" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 153,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s][p]",
   >       "status" : {
   >         "phase" : "primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404312625,
   >       "running_time_in_nanos" : 660812231904,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9088"
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:943" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 943,
   >       "type" : "transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=DEFAULT}",
   >       "start_time_in_millis" : 1494404618177,
   >       "running_time_in_nanos" : 355260730976,
   >       "cancellable" : false,
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 945,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404618177,
   >           "running_time_in_nanos" : 355260669637,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:943"
   >         }
   >       ]
   >     }
   >   }
   > }
   > 		at org.elasticsearch.test.InternalTestCluster.lambda$assertShardIndexCounter$5(InternalTestCluster.java:1158)
   > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:704)
   > 		... 41 more
   > 	Suppressed: java.lang.AssertionError: expected index shard counter on shard [test][0] on node node_s2 to be 0 but was 1. Current replication tasks on node:
   > {
   >   "tasks" : {
   >     "k-1ujp2ySie63_LzG0OS5g:308" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 308,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s]",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404313505,
   >       "running_time_in_nanos" : 660445361990,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9724",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 309,
   >           "type" : "direct",
   >           "action" : "indices:data/write/bulk[s][p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "requests[1], index[test]",
   >           "start_time_in_millis" : 1494404313505,
   >           "running_time_in_nanos" : 660445328649,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:308"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:937" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 937,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >       "start_time_in_millis" : 1494404616959,
   >       "running_time_in_nanos" : 356991115508,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:10977",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 938,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404616959,
   >           "running_time_in_nanos" : 356991053856,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:937"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:153" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 153,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s][p]",
   >       "status" : {
   >         "phase" : "primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404312625,
   >       "running_time_in_nanos" : 661324700008,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9088"
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:943" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 943,
   >       "type" : "transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=DEFAULT}",
   >       "start_time_in_millis" : 1494404618177,
   >       "running_time_in_nanos" : 355773199097,
   >       "cancellable" : false,
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 945,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404618177,
   >           "running_time_in_nanos" : 355773136886,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:943"
   >         }
   >       ]
   >     }
   >   }
   > }
   > 		at org.elasticsearch.test.InternalTestCluster.lambda$assertShardIndexCounter$5(InternalTestCluster.java:1158)
   > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:704)
   > 		... 41 more
   > 	Suppressed: java.lang.AssertionError: expected index shard counter on shard [test][0] on node node_s2 to be 0 but was 1. Current replication tasks on node:
   > {
   >   "tasks" : {
   >     "k-1ujp2ySie63_LzG0OS5g:308" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 308,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s]",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404313505,
   >       "running_time_in_nanos" : 661469835866,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9724",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 309,
   >           "type" : "direct",
   >           "action" : "indices:data/write/bulk[s][p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "requests[1], index[test]",
   >           "start_time_in_millis" : 1494404313505,
   >           "running_time_in_nanos" : 661469802541,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:308"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:937" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 937,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >       "start_time_in_millis" : 1494404616959,
   >       "running_time_in_nanos" : 358015589388,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:10977",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 938,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404616959,
   >           "running_time_in_nanos" : 358015527996,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:937"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:153" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 153,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s][p]",
   >       "status" : {
   >         "phase" : "primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404312625,
   >       "running_time_in_nanos" : 662349174066,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9088"
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:943" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 943,
   >       "type" : "transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=DEFAULT}",
   >       "start_time_in_millis" : 1494404618177,
   >       "running_time_in_nanos" : 356797673188,
   >       "cancellable" : false,
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 945,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404618177,
   >           "running_time_in_nanos" : 356797610409,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:943"
   >         }
   >       ]
   >     }
   >   }
   > }
   > 		at org.elasticsearch.test.InternalTestCluster.lambda$assertShardIndexCounter$5(InternalTestCluster.java:1158)
   > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:704)
   > 		... 41 more
   > 	Suppressed: java.lang.AssertionError: expected index shard counter on shard [test][0] on node node_s2 to be 0 but was 1. Current replication tasks on node:
   > {
   >   "tasks" : {
   >     "k-1ujp2ySie63_LzG0OS5g:308" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 308,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s]",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404313505,
   >       "running_time_in_nanos" : 663518356086,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9724",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 309,
   >           "type" : "direct",
   >           "action" : "indices:data/write/bulk[s][p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "requests[1], index[test]",
   >           "start_time_in_millis" : 1494404313505,
   >           "running_time_in_nanos" : 663518322761,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:308"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:937" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 937,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >       "start_time_in_millis" : 1494404616959,
   >       "running_time_in_nanos" : 360064109570,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:10977",
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 938,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404616959,
   >           "running_time_in_nanos" : 360064047925,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:937"
   >         }
   >       ]
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:153" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 153,
   >       "type" : "mock-tcp-transport",
   >       "action" : "indices:data/write/bulk[s][p]",
   >       "status" : {
   >         "phase" : "primary"
   >       },
   >       "description" : "requests[1], index[test]",
   >       "start_time_in_millis" : 1494404312625,
   >       "running_time_in_nanos" : 664397694012,
   >       "cancellable" : false,
   >       "parent_task_id" : "u4jynCmQQf-g1szB65ECTg:9088"
   >     },
   >     "k-1ujp2ySie63_LzG0OS5g:943" : {
   >       "node" : "k-1ujp2ySie63_LzG0OS5g",
   >       "id" : 943,
   >       "type" : "transport",
   >       "action" : "indices:admin/seq_no/global_checkpoint_sync",
   >       "status" : {
   >         "phase" : "waiting_on_primary"
   >       },
   >       "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=DEFAULT}",
   >       "start_time_in_millis" : 1494404618177,
   >       "running_time_in_nanos" : 358846193297,
   >       "cancellable" : false,
   >       "children" : [
   >         {
   >           "node" : "k-1ujp2ySie63_LzG0OS5g",
   >           "id" : 945,
   >           "type" : "direct",
   >           "action" : "indices:admin/seq_no/global_checkpoint_sync[p]",
   >           "status" : {
   >             "phase" : "starting"
   >           },
   >           "description" : "GlobalCheckpointSyncAction.Request{shardId=[test][0], timeout=1m, index='test', waitForActiveShards=1}",
   >           "start_time_in_millis" : 1494404618177,
   >           "running_time_in_nanos" : 358846130632,
   >           "cancellable" : false,
   >           "parent_task_id" : "k-1ujp2ySie63_LzG0OS5g:943"
   >         }
   >       ]
   >     }
   >   }
   > }
   > 		at org.elasticsearch.test.InternalTestCluster.lambda$assertShardIndexCounter$5(InternalTestCluster.java:1158)
   > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:704)
   > 		... 41 moreThrowable #3: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=298, name=elasticsearch[node_s0][bulk][T#1], state=RUNNABLE, group=TGRP-RecoveryWhileUnderLoadIT]
   > Caused by: java.lang.AssertionError: expected recovery stage [TRANSLOG] but was [DONE]
   > 	at __randomizedtesting.SeedInfo.seed([A80F7027B3C542F0]:0)
   > 	at org.elasticsearch.index.shard.IndexShard.updateGlobalCheckpointOnReplica(IndexShard.java:1531)
   > 	at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncReplicaAction.onResponse(TransportReplicationAction.java:512)
   > 	at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncReplicaAction.onResponse(TransportReplicationAction.java:478)
   > 	at org.elasticsearch.index.shard.IndexShardOperationsLock.acquire(IndexShardOperationsLock.java:147)
   > 	at org.elasticsearch.index.shard.IndexShard.acquireReplicaOperationLock(IndexShard.java:1876)
   > 	at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncReplicaAction.doRun(TransportReplicationAction.java:587)
   > 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
   > 	at org.elasticsearch.action.support.replication.TransportReplicationAction$ReplicaOperationTransportHandler.messageReceived(TransportReplicationAction.java:461)
   > 	at org.elasticsearch.action.support.replication.TransportReplicationAction$ReplicaOperationTransportHandler.messageReceived(TransportReplicationAction.java:442)
   > 	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:66)
   > 	at org.elasticsearch.transport.TcpTransport$RequestHandler.doRun(TcpTransport.java:1487)
   > 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:638)
   > 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
   > 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
   > 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
   > 	at java.lang.Thread.run(Thread.java:748)
@imotov imotov added >test-failure Triaged test failures from CI >test Issues or PRs that are addressing/adding tests labels May 10, 2017
@dakrone
Copy link
Member

dakrone commented May 10, 2017

In case you are looking for another way to reproduce this:

gradle :qa:backwards-5.0:integTestRunner -Dtests.seed=1AD9A34C15808120 -Dtests.class=org.elasticsearch.backwards.IndexingIT -Dtests.method="testSeqNoCheckpoints" -Dtests.security.manager=true -Dtests.locale=el-CY -Dtests.timezone=America/Chicago

reproduces the AssertionError every time for me

@jasontedor
Copy link
Member

jasontedor commented May 10, 2017 •
edited
Loading

I have a seed 8EDEFF2FB626DA09 that I'm using for RelocationIT that reproduces it reliably for me.

@jasontedor
Copy link
Member

Here's an explanation of what is happening:

  1. primary relocation is taking place

the cluster state looks like this:

version: 8
state uuid: otVyR4vtSHudMtHuFANsNA
from_diff: false
meta data version: 5
   [test/yYo6C-u_QsmZUXhga1ZF8Q]: v[4]
      0: p_term [1], isa_ids [OZ-wRD9hSPqdnjMpBx5G0Q]
nodes: 
   {node_t0}{5aITFQiaRWuewPHxcH6JAg}{LQfasJgLSvGQNEwRlVZuzA}{127.0.0.1}{127.0.0.1:9400}, master
   {node_t1}{rjWSeOQ9T92KbzoGaLXIlg}{yJlBzhGhS6mQLI4mP1a3Zg}{127.0.0.1}{127.0.0.1:9401}, local
routing_table (version 4):
-- index [[test/yYo6C-u_QsmZUXhga1ZF8Q]]
----shard_id [test][0]
--------[test][0], node[5aITFQiaRWuewPHxcH6JAg], relocating [rjWSeOQ9T92KbzoGaLXIlg], [P], s[RELOCATING], a[id=OZ-wRD9hSPqdnjMpBx5G0Q, rId=7tew_CiPStWhpG7QaDOBcg], expected_shard_size[197]

routing_nodes:
-----node_id[5aITFQiaRWuewPHxcH6JAg][V]
--------[test][0], node[5aITFQiaRWuewPHxcH6JAg], relocating [rjWSeOQ9T92KbzoGaLXIlg], [P], s[RELOCATING], a[id=OZ-wRD9hSPqdnjMpBx5G0Q, rId=7tew_CiPStWhpG7QaDOBcg], expected_shard_size[197]
-----node_id[rjWSeOQ9T92KbzoGaLXIlg][V]
--------[test][0], node[rjWSeOQ9T92KbzoGaLXIlg], relocating [5aITFQiaRWuewPHxcH6JAg], [P], recovery_source[peer recovery], s[INITIALIZING], a[id=7tew_CiPStWhpG7QaDOBcg, rId=OZ-wRD9hSPqdnjMpBx5G0Q], expected_shard_size[197]
---- unassigned
  1. a new cluster state removing the relocation source arrives on relocation target who starts applying it:
version: 9
state uuid: I_4joS0zS9aDYw8GfPGuRw
from_diff: false
meta data version: 6
   [test/yYo6C-u_QsmZUXhga1ZF8Q]: v[5]
      0: p_term [1], isa_ids [7tew_CiPStWhpG7QaDOBcg]
nodes: 
   {node_t0}{5aITFQiaRWuewPHxcH6JAg}{LQfasJgLSvGQNEwRlVZuzA}{127.0.0.1}{127.0.0.1:9400}, local, master
   {node_t1}{rjWSeOQ9T92KbzoGaLXIlg}{yJlBzhGhS6mQLI4mP1a3Zg}{127.0.0.1}{127.0.0.1:9401}
routing_table (version 5):
-- index [[test/yYo6C-u_QsmZUXhga1ZF8Q]]
----shard_id [test][0]
--------[test][0], node[rjWSeOQ9T92KbzoGaLXIlg], [P], s[STARTED], a[id=7tew_CiPStWhpG7QaDOBcg]

routing_nodes:
-----node_id[5aITFQiaRWuewPHxcH6JAg][V]
-----node_id[rjWSeOQ9T92KbzoGaLXIlg][V]
--------[test][0], node[rjWSeOQ9T92KbzoGaLXIlg], [P], s[STARTED], a[id=7tew_CiPStWhpG7QaDOBcg]
---- unassigned
  1. in the course of applying that cluster state, the primary removes the relocation source from its in-sync IDs, the global checkpoint is now based only on the relocation target
  2. the relocation target is not yet done applying the cluster state
  3. an indexing request arrives, it can go to the relocation source or to the relocation target, either way it lands on the relocation target who has not yet finished applying the cluster state
  4. since the relocation target has not yet finished applying the cluster state, the relocation target will replicate this request to the relocation source
  5. remember, the relocation source is no longer in the in-sync IDs
  6. when the relocation target completes the indexing request locally, it advances its local checkpoint which advances the global checkpoint
  7. the replication request to the relocation source carries with it the now advanced global checkpoint
  8. the relocation source proceeds to update its knowledge of the global checkpoint based on the inlined global checkpoint from the replication request
  9. the global checkpoint has advanced past the local checkpoint on the relocation source, the assertion explodes

Logs that support this hypothesis:

Indexing request arrives on relocation source:

[2017-05-11T07:49:49,159][TRACE][o.e.a.b.TransportShardBulkAction] [node_t0] send action [indices:data/write/bulk[s][p]] to local primary [[test][0]][{node_t0}{5aITFQiaRWuewPHxcH6JAg}{LQfasJgLSvGQNEwRlVZuzA}{127.0.0.1}{127.0.0.1:9400}] for request [BulkShardRequest [[test][0]] containing [index {[test][type1][840], source[{"test":"value840","text":" êêêê ᗧᑠᗋᐄᙕᗶᑙᙘᑲ \uD800\uDFB3\uD800\uDFBB\uD800\uDFA5\uD800\uDFBE ⯻⮥⮃⯝⭘⬛⭄⮓⭋ ⅘ ℔ ê ᳯ᳢᳗᳸ ἯἨῼἡᾛ ģĞĉħĐĪŌ ⟵⟷⟴ ﹭﹢﹘﹢﹕﹕﹥ \uDB8D\uDE7C","id":840}]}]] with cluster state version [8] to [5aITFQiaRWuewPHxcH6JAg]

Indexing request is rerouted to relocation garget

[2017-05-11T07:49:49,160][TRACE][o.e.a.b.TransportShardBulkAction] [node_t1] [[test][0]] op [indices:data/write/bulk[s]] completed on primary for request [BulkShardRequest [[test][0]] containing [index {[test][type1][838], source[{"test":"value838","text":" êêê ⇤⇅⇨ ︩︡︢ NJ ⴮⴯ⴡⴛⴢⴀⴙⴜⴏⴋ ᦋᦾᦗ ၞာ ﶻﶩ \uD809\uDC76\uD809\uDC03\uD809\uDC5E\uD809\uDC68\uD809\uDC08\uD809\uDC1B\uD809\uDC1C\uD809\uDC19 ১ ㆕㆓㆝ ႆငအ႖ဋံကႀၮၘ ᏷ ▔▍▒▝▀▍▜ ⶷ⷊ \uD802\uDC0A\uD802\uDC11","id":838}]} and 1 more items]]

Relocation target executes the index operation acting as primary:

[2017-05-11T07:49:49,162][TRACE][o.e.i.s.IndexShard       ] [node_t1] [test][0] index [type1][840] (seq# [-2])

It was in the middle of applying a new cluster state:

[2017-05-11T07:49:49,163][TRACE][o.e.c.s.ClusterApplierService] [node_t1] calling [org.elasticsearch.ingest.PipelineStore@556da757] with change to version [9]
[2017-05-11T07:49:49,163][TRACE][o.e.c.s.ClusterApplierService] [node_t1] calling [org.elasticsearch.ingest.PipelineExecutionService@75d80884] with change to version [9]
[2017-05-11T07:49:49,164][TRACE][o.e.c.s.ClusterApplierService] [node_t1] calling [org.elasticsearch.gateway.GatewayAllocator$$Lambda$1046/562476091@6472f09e] with change to version [9]
[2017-05-11T07:49:49,164][TRACE][o.e.c.s.ClusterApplierService] [node_t1] calling [org.elasticsearch.repositories.RepositoriesService@d2d01f5] with change to version [9]
[2017-05-11T07:49:49,164][TRACE][o.e.c.s.ClusterApplierService] [node_t1] calling [org.elasticsearch.action.ingest.IngestActionForwarder@35425818] with change to version [9]
[2017-05-11T07:49:49,164][TRACE][o.e.c.s.ClusterApplierService] [node_t1] calling [org.elasticsearch.snapshots.RestoreService@6bfa1c] with change to version [9]
[2017-05-11T07:49:49,164][TRACE][o.e.c.s.ClusterApplierService] [node_t1] calling [org.elasticsearch.tasks.TaskManager@73ee0c8f] with change to version [9]

It can advance the global checkpoint because it is now only tracking one allocation ID (the relocation target, itself):

[2017-05-11T07:49:49,164][TRACE][o.e.i.s.GlobalCheckpointTracker] [node_t1] [test][0] global checkpoint updated to [839]

The operation completes on the relocation target:

[2017-05-11T07:49:49,164][TRACE][o.e.a.b.TransportShardBulkAction] [node_t1] [[test][0]] op [indices:data/write/bulk[s]] completed on primary for request [BulkShardRequest [[test][0]] containing [index {[test][type1][840], source[{"test":"value840","text":" êêêê ᗧᑠᗋᐄᙕᗶᑙᙘᑲ \uD800\uDFB3\uD800\uDFBB\uD800\uDFA5\uD800\uDFBE ⯻⮥⮃⯝⭘⬛⭄⮓⭋ ⅘ ℔ ê ᳯ᳢᳗᳸ ἯἨῼἡᾛ ģĞĉħĐĪŌ ⟵⟷⟴ ﹭﹢﹘﹢﹕﹕﹥ \uDB8D\uDE7C","id":840}]}]]

The relocation target sends the request to the relocation source:

[2017-05-11T07:49:49,166][TRACE][o.e.a.b.TransportShardBulkAction] [node_t1] [[test][0]] sending op [indices:data/write/bulk[s]] to replica [test][0], node[5aITFQiaRWuewPHxcH6JAg], relocating [rjWSeOQ9T92KbzoGaLXIlg], [P], s[RELOCATING], a[id=OZ-wRD9hSPqdnjMpBx5G0Q, rId=7tew_CiPStWhpG7QaDOBcg], expected_shard_size[197] for request [BulkShardRequest [[test][0]] containing [index {[test][type1][840], source[{"test":"value840","text":" êêêê ᗧᑠᗋᐄᙕᗶᑙᙘᑲ \uD800\uDFB3\uD800\uDFBB\uD800\uDFA5\uD800\uDFBE ⯻⮥⮃⯝⭘⬛⭄⮓⭋ ⅘ ℔ ê ᳯ᳢᳗᳸ ἯἨῼἡᾛ ģĞĉħĐĪŌ ⟵⟷⟴ ﹭﹢﹘﹢﹕﹕﹥ \uDB8D\uDE7C","id":840}]}]]

Confirmation that the relocation target is no longer tracking the relocation source:

[2017-05-11T07:49:49,167][TRACE][o.e.i.s.GlobalCheckpointTracker] [node_t1] [test][0] ignored local checkpoint [838] of [OZ-wRD9hSPqdnjMpBx5G0Q], allocation ID is not tracked

And now the assertion can explode:

[2017-05-11T07:49:49,167][TRACE][o.e.i.s.IndexShard       ] [node_t0] [test][0] expected recovery stage [TRANSLOG] but was [DONE], global checkpoint [839], local checkpoint [838]

I will discuss with @bleskes and @ywelsch the situation here, but for now this assertion has to go.

@jasontedor
Copy link
Member

Closed by fbf532a

@jasontedor jasontedor mentioned this issue Jul 12, 2017
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jasontedor jasontedor

Labels
>test Issues or PRs that are addressing/adding tests >test-failure Triaged test failures from CI
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@dakrone @imotov @jasontedor