rolling upgrade fails test {p0=upgraded_cluster/10_basic/Continue scroll after upgrade}

[alpar-t]

Example:
https://gradle-enterprise.elastic.co/s/25kkewilzdsps/tests/jyp47bhnp6lbq-mbgvjsajqkfsa

Seems to affect both 7.x and master

[elasticmachine]

Pinging @elastic/es-search

[markharwood]

I took a look at this and couldn't get it to reproduce reliably.

It may be a timeout issue if the test machine is running very slow.
The test logic tries to pick up a scroll id that was left by a previous test. The timeout for the scroll is 5 minutes so if things are running especially slow then this may be insufficient and we see the errors relating to a loss of search context. We could look at increasing the timeout setting for this scroll?

[jtibshirani]

It looks like @ywelsch recently merged a change to prevent shard relocations from happening during the upgrade (#48525). Could a shard reallocation have caused the 'search context missing' error? This seems plausible to me, but I am not a scroll expert -- perhaps @markharwood or @jimczi would be able to weigh in?

[ywelsch]

I think this was fixed by #48525. No more failures of this test after that fix was merged. Closing this.

[jtibshirani]

@ywelsch the test was immediately disabled, so unfortunately we don't have good information about the failure rate. I will try reenabling it, and we can reopen this issue if it fails again.

As a note, I looked through the full build log more carefully and saw that before the scroll failure, a bunch of tasks have piled up:

java.lang.AssertionError: there are still running tasks:
    {time_in_queue=2.3s, time_in_queue_millis=2339, source=shard-failed, executing=true, priority=HIGH, insert_order=444}
    {time_in_queue=1m, time_in_queue_millis=62781, source=finish persistent task (success), executing=false, priority=NORMAL, insert_order=357}
    {time_in_queue=1m, time_in_queue_millis=61210, source=update task state, executing=false, priority=NORMAL, insert_order=359}
    {time_in_queue=1m, time_in_queue_millis=62211, source=update task state, executing=false, priority=NORMAL, insert_order=358}
    {time_in_queue=57.8s, time_in_queue_millis=57827, source=cluster_reroute(reroute after starting shards), executing=false, priority=NORMAL, insert_order=366}
    {time_in_queue=1m, time_in_queue_millis=60212, source=update task state, executing=false, priority=NORMAL, insert_order=360}
    {time_in_queue=59.2s, time_in_queue_millis=59212, source=update task state, executing=false, priority=NORMAL, insert_order=361}
    {time_in_queue=58.2s, time_in_queue_millis=58211, source=update task state, executing=false, priority=NORMAL, insert_order=362}
    {time_in_queue=50.2s, time_in_queue_millis=50211, source=update task state, executing=false, priority=NORMAL, insert_order=378}
    {time_in_queue=53.2s, time_in_queue_millis=53210, source=update task state, executing=false, priority=NORMAL, insert_order=372}
    {time_in_queue=57.2s, time_in_queue_millis=57212, source=update task state, executing=false, priority=NORMAL, insert_order=368}
    {time_in_queue=56.2s, time_in_queue_millis=56211, source=update task state, executing=false, priority=NORMAL, insert_order=369}
    {time_in_queue=55.2s, time_in_queue_millis=55210, source=update task state, executing=false, priority=NORMAL, insert_order=370}
...

[jtibshirani]

The test was reenabled:

• d4ad75e (master)
• 73c4120 (7.x)
• ba2dc49 (7.5)

[ywelsch]

@jtibshirani good catch. I had missed that the test was still disabled. Let's reenable this both on master and 7.x and see if it is reoccurring (and reopen this issue then if necessary).

[dliappis]

@ywelsch this seems to be failing again, e.g. on master in https://gradle-enterprise.elastic.co/s/xxmcg4qhvabtw

[ywelsch]

It looks like Mark's theory here is correct. I've looked through the node logs to find the events where the scroll was approximately started and the one where it was continued. Both are 5:30 apart, i.e. just above the 5 minute scroll timeout:

[2019-12-13T09:17:30,289][INFO ][o.e.c.m.MetaDataCreateIndexService] [v8.0.0-2] [upgraded_scroll] creating index, cause [api], templates [], shards [1]/[0], mappings []
...
[2019-12-13T09:23:03,402][DEBUG][o.e.a.s.TransportSearchScrollAction] [v8.0.0-0] [126] Failed to execute query phase
org.elasticsearch.transport.RemoteTransportException: [v8.0.0-0][127.0.0.1:41727][indices:data/read/search[phase/query+fetch/scroll]]
Caused by: org.elasticsearch.search.SearchContextMissingException: No search context found for id [126]

@jtibshirani can you adjust the scroll timeout in the test?

[jtibshirani]

Will do, thanks to you both for the debugging help.

[jtibshirani]

I've now bumped the keep-alive time from 5 to 10 minutes. I'll leave this open for a couple weeks, then close it out if we don't see more failures pop up.

[jtibshirani]

I haven't seen new failures since we bumped the keep-alive time, so I will close this out.