[CI] Suite Timeout in ML DeleteExpiredDataIT

[tvernum]

Build scan:

• https://gradle-enterprise.elastic.co/s/w4q6k52ivcyim
• https://gradle-enterprise.elastic.co/s/c2eo2ktge4j4q

Repro line:
./gradlew ':x-pack:plugin:ml:qa:native-multi-node-tests:javaRestTest' --tests "org.elasticsearch.xpack.ml.integration.DeleteExpiredDataIT"

Reproduces locally?:
Yes

Applicable branches:
master
7.x

Failure history:

• Build Stats

Seems to have started today, but could relate to #63134

Failure excerpt:

java.lang.Exception: Test abandoned because suite timeout was reached. 

REPRODUCE WITH: ./gradlew ':x-pack:plugin:ml:qa:native-multi-node-tests:javaRestTest' \
  --tests "org.elasticsearch.xpack.ml.integration.DeleteExpiredDataIT.testDeleteExpiredDataNoThrottle" \
  -Dtests.seed=5E1BF249F797FA74 -Dtests.security.manager=true \
  -Dtests.locale=es-DO -Dtests.timezone=Kwajalein -Druntime.java=11

[elasticmachine]

Pinging @elastic/ml-core (:ml)

[tvernum]

I'm going to mute testDeleteExpiredDataNoThrottle on master and 7.x

testDeleteExpiredDataWithStandardThrottle seems to be OK (despite being the test that was recently unmuted in #63134)

[droberts195]

This failed once last week with the dreaded "All shards failed". But that is very intermittent and didn't cause a timeout.

The first timeout occurred in the 1st PR build of #63349. In fact it took 5 attempts (2nd failure, 3rd failure, 4th failure) at rerunning the PR CI to get green checks, and all the PR CI failures were for this same test. Then after that PR was merged there have been masses of failures. The first failure on master was in the intake build of #63349.

So, although it seems bizarre, something in Lucene 8.7.0-snapshot-66c49a35402 seems to be causing this. It may still be something bad the ML code is doing that Lucene now takes offence at, but there's definitely an interaction.

[droberts195]

The code that's locking up in the test client is this:

        SearchResponse searchResponse;
        if (scrollId == null) {
            searchResponse = initScroll();
        } else {
            SearchScrollRequest searchScrollRequest = new SearchScrollRequest(scrollId).scroll(CONTEXT_ALIVE_DURATION);
            searchResponse = client.searchScroll(searchScrollRequest).actionGet(); // <-- lockup here
        }

So it's continuing a scroll that's different to before. Since these are external cluster tests I need to look separately at what's happening server side when this happens. There are no error messages in the server-side logs.

[mayya-sharipova]

@droberts195 Sorry for the trouble. We have fixed a bug in Lucene, and currently building a new Lucene snapshot for ugprade.

[droberts195]

I watched this going wrong on my laptop and my best guess would be that the scroll goes into an infinite loop, thinking it's never finished.

During the 20 minute timeout 2 JVMs burn a lot of CPU:

4576  java         72.0 08:12.28 139/1  1    445   881M   0B    0B   4099 4099 running  *0[1]          0.00000 0.00000    512  291423   1066  39644     19752
4700  java         47.7 04:56.94 107    1    346   639M+  0B    0B   4099 4099 sleeping *0[1]          0.00000 0.00000    512  215442+  434   23041+    11486+

In that example PID 4576 is one of the 3 external cluster nodes and PID 4700 is the test client. So there's actually a lot of back-and-forth of communications between client and server even though the client appeared deadlocked from just looking at the Gradle scan.

There is no deadlock on the server side. Sometimes you can see evidence of the search taking place on the server side, e.g.:

"elasticsearch[javaRestTest-1][search][T#11]" #103 daemon prio=5 os_prio=31 cpu=936.73ms elapsed=121.17s tid=0x00007f91d3d0a800 nid=0x1ef03 runnable  [0x000070000cdc4000]
   java.lang.Thread.State: RUNNABLE
        at org.elasticsearch.search.query.QueryPhase.searchWithCollector(QueryPhase.java:336)
        at org.elasticsearch.search.query.QueryPhase.executeInternal(QueryPhase.java:296)
        at org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:148)
        at org.elasticsearch.search.SearchService.lambda$executeFetchPhase$2(SearchService.java:562)
        at org.elasticsearch.search.SearchService$$Lambda$6238/0x00000008012ebc40.get(Unknown Source)
        at org.elasticsearch.search.SearchService$$Lambda$5242/0x000000080110c440.get(Unknown Source)
        at org.elasticsearch.action.ActionRunnable.lambda$supply$0(ActionRunnable.java:58)
        at org.elasticsearch.action.ActionRunnable$$Lambda$5243/0x000000080110c840.accept(Unknown Source)
        at org.elasticsearch.action.ActionRunnable$2.doRun(ActionRunnable.java:73)
        at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
        at org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:44)
        at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:733)
        at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11/ThreadPoolExecutor.java:1128)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11/ThreadPoolExecutor.java:628)
        at java.lang.Thread.run(java.base@11/Thread.java:834)

However, these stacks appear and disappear during the 20 minutes - there isn't one that locks up.

So, it very much looks like some change with the sorting means the scroll never finishes.