[CI] SearchableSnapshotActionIT testConvertingSearchableSnapshotFromFullToPartial failing

[elasticsearchmachine]

Build Scans:

• elasticsearch-periodic-platform-support #11337 / windows-2022_checkpart5_platform-support-windows
• elasticsearch-periodic-platform-support #11333 / windows-2022_checkpart5_platform-support-windows

Reproduction Line:

gradlew ":x-pack:plugin:ilm:qa:multi-node:javaRestTest" --tests "org.elasticsearch.xpack.ilm.actions.SearchableSnapshotActionIT.testResumingSearchableSnapshotFromPartialToFull" -Dtests.seed=1B768AD599FA8694 -Dtests.locale=ga -Dtests.timezone=America/Nassau -Druntime.java=25

Applicable branches:
main

Reproduces locally?:
N/A

Failure History:
See dashboard

Failure Message:

java.lang.AssertionError: timed out waiting for green state for index [partial-restored-myindex-ydzu] cluster state [{
  "cluster_name" : "test-cluster",
  "cluster_uuid" : "zCDoVTmvQpi7RDoJEnlhiA",
  "version" : 500,
  "state_uuid" : "gAEhH0CtQRGB0ajFnF39uA",
  "master_node" : "GARGCv3oTweseig14B3n-g",
  "blocks" : {
    "indices" : {
      "restored-myindex-ydzu" : {
        "8" : {
          "description" : "index write (api)",
          "retryable" : false,
          "levels" : [
            "write"
          ]
        }
      }
    }
  },
  "nodes" : {
    "F9aBC-nWQaqwaF5rPF9GpA" : {
      "name" : "test-cluster-3",
      "ephemeral_id" : "_NzPsBBLRCWKz8Uod3PYcA",
      "transport_address" : "127.0.0.1:62105",
      "external_id" : "test-cluster-3",
      "attributes" : {
        "testattr" : "test",
        "xpack.installed" : "true"
      },
      "roles" : [
        "data",
        "data_cold",
        "data_content",
        "data_frozen",
        "data_hot",
        "data_wa
[truncated]

Issue Reasons:

• [main] 2 consecutive failures in step windows-2022_checkpart5_platform-support-windows
• [main] 2 failures in test testConvertingSearchableSnapshotFromFullToPartial (2.3% fail rate in 86 executions)
• [main] 2 failures in step windows-2022_checkpart5_platform-support-windows (100.0% fail rate in 2 executions)
• [main] 2 failures in pipeline elasticsearch-periodic-platform-support (100.0% fail rate in 2 executions)

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

[elasticsearchmachine]

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

[nielsbauman]

All of #137151, #137152, #137153, #137156, and #137166 were opened at the same time and failed with the same exception, so they're likely all related.

Both #136744 and #137111 were merged two days ago and relate to the searchable snapshot ILM tests. I'm fairly certain that the latter couldn't have an impact on all these other tests, whereas the former touches the whole test suite.

Running the tests locally, I noticed logs from ILMHistoryStore, which should have been disabled with:

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

Lines 41 to 42 in df67e27

	// The TRACE logs of the history store are too verbose and not useful, so we set it to INFO
	.setting("logger.org.elasticsearch.xpack.ilm.history.ILMHistoryStore", "INFO")

I'm sure they were disabled before #136744 was merged:

elasticsearch/x-pack/plugin/ilm/qa/multi-node/build.gradle

Lines 38 to 39 in 94d330f

	// The TRACE logs of the history store are too verbose and not useful, so we set it to INFO
	setting 'logger.org.elasticsearch.xpack.ilm.history.ILMHistoryStore', 'INFO'

and I double checked that by reverting that PR locally and rerunning the test; the ILMHistoryStore didn't show up anymore.

That leaves me to think that the other settings configured in IlmESRestTestCase might not be registering either, some of which definitely have an impact on the speed of the test, such as:

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

Line 54 in df67e27

.setting("cluster.routing.rebalance.enable", "none")

@mosche could you have a look at why these settings don't seem to be configured? I propose that we first ensure all settings are working properly, then close these issues and see if they pop up again.

[mosche]

@mosche could you have a look at why these settings don't seem to be configured? I propose that we first ensure all settings are working properly, then close these issues and see if they pop up again.

@nielsbauman settings are working, otherwise this wouldn't log at TRACE level. cluster.routing.rebalance.enable: None is definitely applied. Attempting to set two dependent loggers at once is a sketchy thing to do, it depends on ordering which is always fragile and not a given here. I'm surprised that worked before. Setting the level for logger.org.elasticsearch.xpack.ilm will remove all child loggers. Depending on ordering, this will impact ILMHistoryStore logging.

I do see the value of being able to reliably configure dependent loggers. I'll discuss with the team if this is something we should guarantee.

Though, one question to ask in the first place is why this needs logging at TRACE level at all. Is this really necessary?

[nielsbauman]

Thanks @mosche. You're absolutely right; somehow I didn't realize that those TRACE logs were actually a confirmation that the settings were working...

Though, one question to ask in the first place is why this needs logging at TRACE level at all. Is this really necessary?

Yeah, it's really necessary in this case. We've had plenty of nasty concurrency bugs already where these TRACE logs were a lifesaver.

It's unfortunate that both your and my PRs got merged on the same day, that makes the investigation harder. I also haven't been able to reproduce this on Linux VMs. I'll try on Windows VMs.

In any case, I'll take it further from here on. Thanks for having a look, @mosche!