Elasticsearch: Race condition in RolloverAction causes failures

[gwbrown]

There are still scenarios in which RolloverAction can incorrectly cause the index to be moved to the Error Step, particularly at low polling intervals, such as those we use in our tests. During a rollover, there is a gap between each of these steps:

1. The creation of the new index.
2. The alias being swapped to the new index.
3. The RolloverInfo being added to the original index.

https://github.com/elastic/elasticsearch/pull/35168 prevented errors in the case where two RolloverSteps fired simultaneously for the same index, and one completed step 1 above before the other. However, an error can still occur if two RolloverSteps (R1 and R2) fire simultaneously in this case:

1. R1 completes step 1.
2. R2 issues a rollover request, fails with ResourceAlreadyExistsException and moves to the next step.
3. R2 finishes, and moves on to running UpdateRolloverLifecycleDateStep. R2 fails because R1 has not yet completed step 3 (i.e. has not yet attached the RolloverInfo) and the index moves to the error step.
4. R1 completes steps 2 and 3.

This is the root cause of https://github.com/elastic/elasticsearch/issues/35244

Proposed Solution

@colings86, @talevy and I discussed this briefly. The solution we came up with is to add a step (say, VerifyRolloverStep), which checks that the alias no longer points to the original index and that the RolloverInfo has been attached to the original index before moving on to UpdateRolloverLifecycleDateStep.

However, there is no way to detect the difference between "There is a Rollover request in flight that has not yet completed, so we should wait" and "Someone manually created a subsequent index, and we should move to the error step" - therefore, if someone manually creates a subsequent index, the policy would simply wait at VerifyRolloverStep forever. To resolve this, VerifyRolloverStep should implement a timeout, based on step_time, to wait some length of time significantly longer than we believe a rollover should take to complete (10 minutes?) which will allow us to notify the user that something has, in fact, gone wrong.

[elasticmachine]

Pinging @elastic/es-core-infra

[gwbrown]

I intend to work on this, I assigned everyone on ILM for visibility.

[talevy]

I'm on board with this plan! Personally, I think it would be safe for this timeout to be rather small since we should just be waiting on the time it takes two cluster-state updates to complete. Since there is no reason to risk things, setting the timeout to 10 minutes sounds like a reasonably safe thing to do.

[gwbrown]

Fixed by #35524

[javanna]

heya @gwbrown I still see similar failures once in a while on my CI, could it be the same problem as before? I can't repro with the same seed unfortunately, it looks like a timing issue.

REPRODUCE WITH: ./gradlew :x-pack:plugin:ilm:qa:multi-node:integTestRunner --tests "org.elasticsearch.xpack.indexlifecycle.ChangePolicyforIndexIT.testChangePolicyForIndex" -Dtests.seed=1B8BDEDB443ABCA2 -Dtests.security.manager=true -Dtests.locale=en-DK -Dtests.timezone=Africa/Dakar -Dcompiler.java=12 -Druntime.java=12
02:06:22   2> org.junit.ComparisonFailure: expected:<[completed]> but was:<[warm]>
02:06:22         at __randomizedtesting.SeedInfo.seed([1B8BDEDB443ABCA2:FA9A8A9A897F6F52]:0)
02:06:22         at org.junit.Assert.assertEquals(Assert.java:115)
02:06:22         at org.junit.Assert.assertEquals(Assert.java:144)
02:06:22         at org.elasticsearch.xpack.indexlifecycle.ChangePolicyforIndexIT.assertStep(ChangePolicyforIndexIT.java:140)
02:06:22         at org.elasticsearch.xpack.indexlifecycle.ChangePolicyforIndexIT.lambda$testChangePolicyForIndex$2(ChangePolicyforIndexIT.java:115)
02:06:22         at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:862)
02:06:22         at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836)
02:06:22         at org.elasticsearch.xpack.indexlifecycle.ChangePolicyforIndexIT.testChangePolicyForIndex(ChangePolicyforIndexIT.java:115)

[gwbrown]

@javanna That wouldn't be this issue, this would cause failures while in the hot phase, while the policy has progressed to warm in your case. I don't see any failures* for this test on build-stats for this, I suspect it's just the assertBusy timing out - that can happen on slower systems for the ILM tests generally. I'm not sure what to recommend for you, unfortunately.

*: There's a couple IOExceptions in late march, but those are errors creating an index so I doubt it's related.