IndexWithShadowReplicasIT.testIndexWithFewDocuments fails

[javanna]

IndexWithShadowReplicasIT.testIndexWithFewDocuments fails every few days in our CI. Happens in both 5.x and master.

From https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-darwin-compatibility/479/console:

ERROR   3.31s J0 | IndexWithShadowReplicasIT.testIndexWithFewDocuments <<< FAILURES!
   > Throwable #1: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=1570, name=elasticsearch[node_t0][__mock_network_thread][T#7], state=RUNNABLE, group=TGRP-IndexWithShadowReplicasIT]
   > 	at __randomizedtesting.SeedInfo.seed([4FDB1AE2E4E7D59C:A847CECC0DF52B87]:0)
   > Caused by: java.lang.AssertionError: setting value but not in fetching mode
   > 	at __randomizedtesting.SeedInfo.seed([4FDB1AE2E4E7D59C]:0)
   > 	at org.elasticsearch.gateway.AsyncShardFetch$NodeEntry.doneFetching(AsyncShardFetch.java:372)
   > 	at org.elasticsearch.gateway.AsyncShardFetch.processAsyncFetch(AsyncShardFetch.java:206)
   > 	at org.elasticsearch.gateway.AsyncShardFetch$1.onResponse(AsyncShardFetch.java:275)
   > 	at org.elasticsearch.gateway.AsyncShardFetch$1.onResponse(AsyncShardFetch.java:272)
   > 	at org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:85)
   > 	at org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:81)
   > 	at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.finishHim(TransportNodesAction.java:261)
   > 	at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.onOperation(TransportNodesAction.java:236)
   > 	at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.access$100(TransportNodesAction.java:160)
   > 	at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:213)
   > 	at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:205)
   > 	at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleResponse(TransportService.java:1030)
   > 	at org.elasticsearch.transport.TcpTransport$2.doRun(TcpTransport.java:1379)
   > 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
   > 	at org.elasticsearch.common.util.concurrent.EsExecutors$1.execute(EsExecutors.java:110)
   > 	at org.elasticsearch.transport.TcpTransport.handleResponse(TcpTransport.java:1371)
   > 	at org.elasticsearch.transport.TcpTransport.messageReceived(TcpTransport.java:1340)
   > 	at org.elasticsearch.transport.MockTcpTransport.readMessage(MockTcpTransport.java:172)
   > 	at org.elasticsearch.transport.MockTcpTransport.access$900(MockTcpTransport.java:73)
   > 	at org.elasticsearch.transport.MockTcpTransport$MockChannel$1.lambda$doRun$90(MockTcpTransport.java:359)
   > 	at org.elasticsearch.common.util.CancellableThreads.executeIO(CancellableThreads.java:105)
   > 	at org.elasticsearch.transport.MockTcpTransport$MockChannel$1.doRun(MockTcpTransport.java:359)
   > 	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:745)

Although we are going to remove shadow replicas in master, we should have a look at the failures and see whether there's anything that needs fixing in 5.x.

[javanna]

one more failure, this time from 5.x: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+5.x+multijob-darwin-compatibility/364

[dakrone]

For master, shadow replicas are going away entirely in #23906, I'll take a look at the 5.x failure

[dakrone]

I marked it as AwaitsFix in master until it is removed also

[ywelsch]

OK, I think I know what's going on:

• Async shard fetching is started for all 3 nodes (node_t0, node_t1, node_t2) :

[2017-04-09T12:01:26,948][TRACE][o.e.g.GatewayAllocator$InternalReplicaShardAllocator] [node_t0] [test][0] fetching [shard_store] from [{node_t2}{YzGiBQKJQZSF-m9vJklUJw}{Jv31eJhcRFapDP8BpNprvg}{127.0.0.1}{127.0.0.1:9482}, {node_t0}{MzEFZ1OiRkmhUyhzBZIKug}{jc19yNiyQFSaFGU74Yxy1g}{127.0.0.1}{127.0.0.1:9480}, {node_t1}{JPMaUNu3SY-r_wuVThJr0w}{BKmWE4tRTJOf62nrbVtaCQ}{127.0.0.1}{127.0.0.1:9481}]

• Node node_t1 is restarted while async fetching is going on

[2017-04-09T12:01:26,969][INFO ][o.e.c.s.ClusterService   ] [node_t0] removed {{node_t1}{JPMaUNu3SY-r_wuVThJr0w}{BKmWE4tRTJOf62nrbVtaCQ}{127.0.0.1}{127.0.0.1:9481},}, reason: zen-disco-node-failed({node_t1}{JPMaUNu3SY-r_wuVThJr0w}{BKmWE4tRTJOf62nrbVtaCQ}{127.0.0.1}{127.0.0.1:9481}), reason(transport disconnected)[{node_t1}{JPMaUNu3SY-r_wuVThJr0w}{BKmWE4tRTJOf62nrbVtaCQ}{127.0.0.1}{127.0.0.1:9481} transport disconnected]

• In the cluster state update where node_t1 is removed, it's NodeEntry is being removed from the cache field in the AsyncShardFetch class.

• While node_t1 rejoins, a new NodeEntry is added to the cache field in the AsyncShardFetch is added and another fetching attempt is made for node_t1:

[2017-04-09T12:01:26,984][TRACE][o.e.g.GatewayAllocator$InternalReplicaShardAllocator] [node_t0] [test][0] fetching [shard_store] from [{node_t1}{JPMaUNu3SY-r_wuVThJr0w}{nT-bJ889Rb2_eIpe_TjrPw}{127.0.0.1}{127.0.0.1:9481}]
// The zen-disco-node-join message happens later here but the shard_store fetching is caused by the join.
[2017-04-09T12:01:26,985][INFO ][o.e.c.s.ClusterService   ] [node_t0] added {{node_t1}{JPMaUNu3SY-r_wuVThJr0w}{nT-bJ889Rb2_eIpe_TjrPw}{127.0.0.1}{127.0.0.1:9481},}, reason: zen-disco-node-join[{node_t1}{JPMaUNu3SY-r_wuVThJr0w}{nT-bJ889Rb2_eIpe_TjrPw}{127.0.0.1}{127.0.0.1:9481}]

• As the cache field is keyed by the persistent node id, the cache does not distinguish between old node_t1 and new node_t1.

• We have now two responses coming back for node_t1 (first a successful one, then a failure):

[2017-04-09T12:01:27,014][TRACE][o.e.g.GatewayAllocator$InternalReplicaShardAllocator] [node_t0] [test][0] marking JPMaUNu3SY-r_wuVThJr0w as done for [shard_store], result is [[[{node_t1}{JPMaUNu3SY-r_wuVThJr0w}{nT-bJ889Rb2_eIpe_TjrPw}{127.0.0.1}{127.0.0.1:9481}][StoreFilesMetaData{, shardId=[test][0], metadataSnapshot{size=4, syncId=null}}]]]
...

[2017-04-09T12:01:27,026][TRACE][o.e.g.GatewayAllocator$InternalReplicaShardAllocator] [node_t0] [test][0] processing failure FailedNodeException[Failed node [JPMaUNu3SY-r_wuVThJr0w]]; nested: NodeNotConnectedException[[node_t1][127.0.0.1:9481] Node not connected]; for [shard_store]
...


1> [2017-04-09T12:01:27,026][WARN ][o.e.g.GatewayAllocator$InternalReplicaShardAllocator] [node_t0] [test][0]: failed to list shard for shard_store on node [JPMaUNu3SY-r_wuVThJr0w]
  1> org.elasticsearch.action.FailedNodeException: Failed node [JPMaUNu3SY-r_wuVThJr0w]
  1> 	at ...

• This trips the assertion

Caused by: java.lang.AssertionError: setting value but not in fetching mode
   > 	at __randomizedtesting.SeedInfo.seed([4FDB1AE2E4E7D59C]:0)
   > 	at org.elasticsearch.gateway.AsyncShardFetch$NodeEntry.doneFetching(AsyncShardFetch.java:372)
   > 	at org.elasticsearch.gateway.AsyncShardFetch.processAsyncFetch(AsyncShardFetch.java:206)

@dakrone We can discuss solutions if you like.

[ywelsch]

Closed by #24434