ClusterPrivilegeTests.testThatSnapshotAndRestore failing in master

[pgomulka]

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+intake/1650/console

Does not reproduce for me locally

REPRODUCE WITH: ./gradlew :x-pack:plugin:security:unitTest \
  -Dtests.seed=1E58C34D450B1482 \
  -Dtests.class=org.elasticsearch.integration.ClusterPrivilegeTests \
  -Dtests.method="testThatSnapshotAndRestore" \
  -Dtests.security.manager=true \
  -Dtests.locale=en-CA \
  -Dtests.timezone=America/Adak \
  -Dcompiler.java=11 \
  -Druntime.java=8

[elasticmachine]

Pinging @elastic/es-core-infra

[pgomulka]

relevant logs

Caused by: org.elasticsearch.client.ResponseException: method [DELETE], host [http://127.0.0.1:9200], URI [/someindex], status line [HTTP/1.1 400 Bad Request]
{"error":{"root_cause":[{"type":"snapshot_in_progress_exception","reason":"Cannot delete indices that are being snapshotted: [[someindex/TYlngLbTQXWFygHGb5qQGA]]. Try again after snapshot finishes or cancel the currently running snapshot."}],"type":"snapshot_in_progress_exception","reason":"Cannot delete indices that are being snapshotted: [[someindex/TYlngLbTQXWFygHGb5qQGA]]. Try again after snapshot finishes or cancel the currently running snapshot."},"status":400}
	at org.elasticsearch.client.RestClient$1.completed(RestClient.java:309)
	at org.elasticsearch.client.RestClient$1.completed(RestClient.java:294)
	at org.apache.http.concurrent.BasicFuture.completed(BasicFuture.java:119)
	at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.responseCompleted(DefaultClientExchangeHandlerImpl.java:177)
	at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.processResponse(HttpAsyncRequestExecutor.java:436)
	at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.inputReady(HttpAsyncRequestExecutor.java:326)
	at org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(DefaultNHttpClientConnection.java:265)
	at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:81)
	at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:39)
	at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:114)
	at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:162)
	at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:337)
	at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315)
	at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:276)

[original-brownbear]

This is still happening in master and easily reproducible with:

  2> REPRODUCE WITH: ./gradlew :x-pack:plugin:security:unitTest -Dtests.seed=3BD2CC63823C26E0 -Dtests.class=org.elasticsearch.integration.ClusterPrivilegeTests -Dtests.method="testThatSnapshotAndRestore" -Dtests.security.manager=true -Dtests.locale=ewo -Dtests.timezone=America/St_Thomas -Dcompiler.java=12 -Druntime.java=12
ERROR   6.09s | ClusterPrivilegeTests.testThatSnapshotAndRestore <<< FAILURES!
   > Throwable #1: org.elasticsearch.client.ResponseException: method [PUT], host [http://127.0.0.1:9200], URI [/_snapshot/my-repo/my-snapshot-d], status line [HTTP/1.1 503 Service Unavailable]
   > {"error":{"root_cause":[{"type":"concurrent_snapshot_execution_exception","reason":"[my-repo:my-snapshot-d]  a snapshot is already running"}],"type":"concurrent_snapshot_execution_exception","reason":"[my-repo:my-snapshot-d]  a snapshot is already running"},"status":503}
   >    at __randomizedtesting.SeedInfo.seed([3BD2CC63823C26E0:9E55B86B524C705F]:0)
   >    at org.elasticsearch.client.RestClient.convertResponse(RestClient.java:260)
   >    at org.elasticsearch.client.RestClient.performRequest(RestClient.java:238)
   >    at org.elasticsearch.client.RestClient.performRequest(RestClient.java:212)
   >    at org.elasticsearch.integration.AbstractPrivilegeTestCase.assertAccessIsAllowed(AbstractPrivilegeTestCase.java:34)
   >    at org.elasticsearch.integration.AbstractPrivilegeTestCase.assertAccessIsAllowed(AbstractPrivilegeTestCase.java:45)
   >    at org.elasticsearch.integration.ClusterPrivilegeTests.testThatSnapshotAndRestore(ClusterPrivilegeTests.java:170)
   >    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   >    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
   >    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
   >    at java.base/java.lang.reflect.Method.invoke(Method.java:567)
   >    at java.base/java.lang.Thread.run(Thread.java:835)

takes like 10 runs on average with this seed. I'm looking into this now, seems like it could be a race between the cluster state check and what the transport API returns where the transport reports SUCCESS before the snapshot is fully cleared from the CS.

[original-brownbear]

Yea the above seems about right, the state reported is success but the CS still has the success entry in it in some cases which leads to this failure.

index 257a0b77692..3a754c7f333 100644
--- a/server/src/main/java/org/elasticsearch/snapshots/SnapshotsService.java
+++ b/server/src/main/java/org/elasticsearch/snapshots/SnapshotsService.java
@@ -275,7 +275,7 @@ public class SnapshotsService extends AbstractLifecycleComponent implements Clus
                         "cannot snapshot while a snapshot deletion is in-progress");
                 }
                 SnapshotsInProgress snapshots = currentState.custom(SnapshotsInProgress.TYPE);
-                if (snapshots == null || snapshots.entries().isEmpty()) {
+                if (snapshots == null || snapshots.entries().stream().noneMatch(e -> e.state().completed() == false)) {
                     // Store newSnapshot here to be processed in clusterStateProcessed
                     List<String> indices = Arrays.asList(indexNameExpressionResolver.concreteIndexNames(currentState,
                                                         request.indicesOptions(), request.indices()));

fixes it practically. I'll open a PR with it shortly as soon as I have worked through the implications and made sure it can't get us into a broken state.

[davidkyle]

Another instance with the same error:

org.elasticsearch.client.ResponseException: method [PUT], host [http://127.0.0.1:9200], URI [/_snapshot/my-repo/my-snapshot-d], status line [HTTP/1.1 503 Service Unavailable]

{"error":{"root_cause":[{"type":"concurrent_snapshot_execution_exception","reason":"[my-repo:my-snapshot-d]  a snapshot is already running"}],"type":"concurrent_snapshot_execution_exception","reason":"[my-repo:my-snapshot-d]  a snapshot is already running"},"status":503}

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+release-tests/653/console

[original-brownbear]

Fix incoming in #40943 :)