[CI] SearchableSnapshotActionIT testSearchableSnapshotsInHotPhasePinnedToHotNodes failing

[elasticsearchmachine]

Build Scans:

• elasticsearch-periodic-platform-support #7266 / oraclelinux-9_platform-support-unix
• elasticsearch-pull-request #64774 / checkpart5_release-tests
• elasticsearch-periodic #7223 / single-processor-node-tests
• elasticsearch-periodic-platform-support #7245 / ubuntu-2404_platform-support-unix

Reproduction Line:

./gradlew ":x-pack:plugin:ilm:qa:multi-node:javaRestTest" --tests "org.elasticsearch.xpack.ilm.actions.SearchableSnapshotActionIT.testSearchableSnapshotsInHotPhasePinnedToHotNodes" -Dtests.seed=23428F9DB66FBCCC -Dtests.locale=nl-CW -Dtests.timezone=America/Indianapolis -Druntime.java=24

Applicable branches:
main

Reproduces locally?:
N/A

Failure History:
See dashboard

Failure Message:

java.lang.AssertionError: 
Expected: is <{"phase":"hot","action":"complete","name":"complete"}>
     but: was <{"phase":"null","action":"null","name":"null"}>

Issue Reasons:

• [main] 4 failures in test testSearchableSnapshotsInHotPhasePinnedToHotNodes (2.0% fail rate in 204 executions)
• [main] 2 failures in pipeline elasticsearch-periodic-platform-support (50.0% fail rate in 4 executions)

Note:
This issue was created using new test triage automation. Please report issues or feedback to es-delivery.

[elasticsearchmachine]

This has been muted on branch main

Mute Reasons:

• [main] 4 failures in test testSearchableSnapshotsInHotPhasePinnedToHotNodes (2.0% fail rate in 204 executions)
• [main] 2 failures in pipeline elasticsearch-periodic-platform-support (50.0% fail rate in 4 executions)

Build Scans:

• elasticsearch-periodic-platform-support #7266 / oraclelinux-9_platform-support-unix
• elasticsearch-pull-request #64774 / checkpart5_release-tests
• elasticsearch-periodic #7223 / single-processor-node-tests
• elasticsearch-periodic-platform-support #7245 / ubuntu-2404_platform-support-unix

[elasticsearchmachine]

Pinging @elastic/es-data-management (Team:Data Management)

[nielsbauman]

My first guess would be that this is related to #122885. I'll have a better look later.

EDIT: after further investigation, it looks like it's unrelated to that PR after all - see my comment below.

[nielsbauman]

I've been looking at this for some time, and I think I have some idea of what happened, but I'm not 100% sure. I mainly looked at the only build failure that renders for me (Gradle Enterprise is having some issues ATM), which is the PR build linked in the OP. I'm posting my intermediate findings here for now:

The test failed because ILM truly did get stuck - i.e. it wasn't an API that was returning outdated/wrong information. Right until the end of the test, we see that the first backing index is in the wait-for-index-color-step as part of the searchable_snapshot action whereas the test expects ILM to just complete the action without issues. After mounting the searchable snapshot, ILM is waiting for the restored- index to be GREEN.

Interestingly, though, the index did turn green way before the end of the test (note the timestamp differences):

[2025-03-26T11:00:29,732][INFO ][o.e.c.r.a.AllocationService] [javaRestTest-3] current.health="GREEN" message="Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[restored-.ds-logs-aolgqmqtwy-2025.03.26-000001][0]]])." previous.health="YELLOW" reason="shards started [[restored-.ds-logs-aolgqmqtwy-2025.03.26-000001][0]]"
...
[2025-03-26T11:01:02,273][TRACE][o.e.x.i.IndexLifecycleRunner] [javaRestTest-3] [.ds-logs-aolgqmqtwy-2025.03.26-000001] retrieved current step key: {"phase":"hot","action":"searchable_snapshot","name":"wait-for-index-color"}

Right before the restored index turned GREEN, we run the wait-for-index-color step for the first time:

[2025-03-26T11:00:29,730][TRACE][o.e.x.i.IndexLifecycleRunner] [javaRestTest-3] [.ds-logs-aolgqmqtwy-2025.03.26-000001] maybe running step (WaitForIndexColorStep) after state change: {"phase":"hot","action":"searchable_snapshot","name":"wait-for-index-color"}
[2025-03-26T11:00:29,730][DEBUG][o.e.x.i.IndexLifecycleRunner] [javaRestTest-3] [.ds-logs-aolgqmqtwy-2025.03.26-000001] running policy with current-step [{"phase":"hot","action":"searchable_snapshot","name":"wait-for-index-color"}]

Looking at where that running policy with current-step ... line is logged in the code (here), I see we enqueue an ExecuteStepsUpdateTask. What's confusing me is that I would have expected to see a waiting for cluster state step condition log from this line, but we don't - not until this step is re-executed at the end of the test when we start cleaning up and thus triggering cluster state updates again. In fact, I don't see any log from this task. Looking at ExecuteStepsUpdateTask#doExecute, the only code path I see that would result in the task silently completing (as in, without any logs), is when currentStep.equals(registeredCurrentStep) is false here. I see one retrieved current step key log all on its own

[2025-03-26T11:00:29,765][TRACE][o.e.x.i.IndexLifecycleRunner] [javaRestTest-3] [.ds-logs-aolgqmqtwy-2025.03.26-000001] retrieved current step key: {"phase":"hot","action":"searchable_snapshot","name":"wait-for-index-color"}

and I think that's the one from ExecuteStepsUpdateTask#doExecute here. I'm not very familiar with the Step object or the PolicyStepsRegistry, so I'm not sure how the condition in that if-statement failed.

While this task is queued/doing God knows what, the index is in IndexLifecycleRunner#busyIndices, causing ILM to (silently!) skip processing this task for incoming cluster state updates here. In this case, one of those skipped cluster state updates is the cluster state update that sets the index health to GREEN. Since tests have very little activity going on, there are no subsequent cluster state updates to trigger a retry on the step. That last part is something we can fix by artificially introducing cluster state changes in the test - as we do in various other tests in this test suite - and I think that's what we'll end up having to do here.

[nielsbauman]

#125789 also seems to be caused by ILM being stuck due to an absence of cluster state updates. I also see we have a dedicated method in this class for triggering cluster state updates:

elasticsearch/x-pack/plugin/ilm/qa/multi-node/src/javaRestTest/java/org/elasticsearch/xpack/ilm/actions/SearchableSnapshotActionIT.java

Lines 1100 to 1107 in 0c50403

	/**
	* Cause a bit of cluster activity using an empty reroute call in case the `wait-for-index-colour` ILM step missed the
	* notification that partial-index is now GREEN.
	*/
	private void triggerStateChange() throws IOException {
	Request rerouteRequest = new Request("POST", "/_cluster/reroute");
	client().performRequest(rerouteRequest);
	}

That gives me some more confidence that both these tests are indeed caused by a quiet cluster.