[CI] SecurityIndexManagerIntegTests testConcurrentOperationsTryingToCreateSecurityIndexAndAlias failing

[dakrone]

Build scan:
https://gradle-enterprise.elastic.co/s/l4c6qgotbl5ze/tests/:x-pack:plugin:security:internalClusterTest/org.elasticsearch.xpack.security.support.SecurityIndexManagerIntegTests/testConcurrentOperationsTryingToCreateSecurityIndexAndAlias

Reproduction line:
./gradlew ':x-pack:plugin:security:internalClusterTest' --tests "org.elasticsearch.xpack.security.support.SecurityIndexManagerIntegTests.testConcurrentOperationsTryingToCreateSecurityIndexAndAlias" -Dtests.seed=180AB7D00204CCBD -Dtests.locale=pt -Dtests.timezone=Europe/Ljubljana -Druntime.java=16 -Dtests.fips.enabled=true

Applicable branches:
7.13

Reproduces locally?:
No

Failure history:
https://gradle-enterprise.elastic.co/scans/tests?tests.container=org.elasticsearch.xpack.security.support.SecurityIndexManagerIntegTests&tests.test=testConcurrentOperationsTryingToCreateSecurityIndexAndAlias

Failure excerpt:

java.lang.AssertionError: (No message provided)

  at __randomizedtesting.SeedInfo.seed([180AB7D00204CCBD:83D1AEEC12F72A7E]:0)
  at org.junit.Assert.fail(Assert.java:86)
  at org.junit.Assert.assertTrue(Assert.java:41)
  at org.junit.Assert.assertTrue(Assert.java:52)
  at org.elasticsearch.xpack.security.support.SecurityIndexManagerIntegTests.testConcurrentOperationsTryingToCreateSecurityIndexAndAlias(SecurityIndexManagerIntegTests.java:78)
  at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-2)
  at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
  at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:567)
  at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1750)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:938)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:974)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:988)
  at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
  at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
  at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
  at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
  at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
  at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:947)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:832)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:883)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:894)
  at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48)
  at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
  at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
  at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
  at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
  at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
  at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
  at java.lang.Thread.run(Thread.java:831)

[elasticmachine]

Pinging @elastic/es-security (Team:Security)

[ywangd]

This is a rare failure. This test method failed couple times in last year. But only this particular one failed at asserting all users are created:

elasticsearch/x-pack/plugin/security/src/internalClusterTest/java/org/elasticsearch/xpack/security/support/SecurityIndexManagerIntegTests.java

Line 78 in 16424d2

assertTrue(future.actionGet().created());

All the other failures are about asserting the threads are properly prepared in time:

elasticsearch/x-pack/plugin/security/src/internalClusterTest/java/org/elasticsearch/xpack/security/support/SecurityIndexManagerIntegTests.java

Line 75 in 16424d2

assertThat(exceptions, Matchers.empty());

The later one makes more sense because it suggests an overwhelmed JVM (indeed the errors are either TimeoutException or BrokenBarrierException), which can certainly happen for an internal cluster test that uses many threads (up to 4 times of the total available processors).

The former one is more puzzling because it means an user is "updated" instead of "created". Indeed, the logs also show this is the case:

  1> [2021-06-04T17:16:46,685][INFO ][o.e.x.s.a.u.TransportPutUserAction] [node_s6] updated user [user31]
  1> [2021-06-04T17:16:46,717][INFO ][o.e.c.m.MetadataDeleteIndexService] [node_s0] [.security-7/OnH2ALFfQjivgmWs3rf7sQ] deleting index
  1> [2021-06-04T17:16:46,744][INFO ][o.e.x.s.a.u.TransportPutUserAction] [node_s6] updated user [user48]
  1> [2021-06-04T17:16:46,754][ERROR][o.e.x.s.a.u.TransportPutUserAction] [node_s6] failed to put user [user43]
  1> org.elasticsearch.index.IndexNotFoundException: no such index [.security-7]
  1>    at org.elasticsearch.action.support.replication.TransportReplicationAction$ReroutePhase.doRun(TransportReplicationAction.java:712) [elasticsearch-7.13.2-SNAPSHOT.jar:7.13.2-SNAPSHOT]

I think this is what happend in the above log:

1. Somehow node_s6 thinks user31 is updated instead of created. This fails the assertion.
2. Since the assertion is tripped, the test is basically over and tearing down starts to happen. That is why node_s0 begins to delete the security index.
3. Since the security is deleted when indexing is on its way, we have serveral failed to put user ... error messages.

So step 1 is still the key to all the cascading failures. It seems that indexing a new document can very rarely report back DocWriteReseponse.Result.UPDATED instead of CREATED. According to @DaveCTurner, this is possible:

if the coordinating node has to retry for some reason but the original request succeeded then the retry will see the doc already exists

Coincidentally, node_s6 is a coordinating only node, so it could have a better chance of running into this issue. Also note that the updated user message is almost 1 min later than the first added user message and 1 min corresponds to the default timeout of indexing. There could something going on which leads to node_s6 decides to retry after a long period of waiting.

Overall the root cause is most likely an overwhelmed JVM. This specific failure has a 7-node internal cluster, 76 threads each trying to create a user at the same time. Also note that the failure only seems to happen in FIPS jobs. I don't think it really is FIPS related, but rather things are a bit slower in FIPS mode, e.g. TLS in enabled (Or is BC PBDKF2 slower than sun's version?) Also the failures never happen on master, which could just be by chance.

I think a potential fix is to reduce the concurrency so that the test uses half (instead of all) of the availableProcessors and bound the number of requests to 50 instead of 100. The number 100 is already a result of reducing the concurrency previously. So this issue is probably not entirely new (but the exact errors could be different).