[CI] SnapshotRepoTestKitClientYamlTestSuiteIT test {p0=/10_analyze/Timeout with large blobs} failing

[dimitris-athanasiou]

Build scan:
https://gradle-enterprise.elastic.co/s/lprftbo45hvvk/tests/:x-pack:plugin:snapshot-repo-test-kit:qa:rest:yamlRestTest/org.elasticsearch.repositories.blobstore.testkit.rest.SnapshotRepoTestKitClientYamlTestSuiteIT/test%20%7Bp0=%2F10_analyze%2FTimeout%20with%20large%20blobs%7D

Reproduction line:
./gradlew ':x-pack:plugin:snapshot-repo-test-kit:qa:rest:yamlRestTest' --tests "org.elasticsearch.repositories.blobstore.testkit.rest.SnapshotRepoTestKitClientYamlTestSuiteIT.test {p0=/10_analyze/Timeout with large blobs}" -Dtests.seed=AA798EB1F664F981 -Dtests.configure_test_clusters_with_one_processor=true -Dtests.locale=sr-Latn -Dtests.timezone=Africa/Porto-Novo -Druntime.java=17

Applicable branches:
8.5

Reproduces locally?:
Didn't try

Failure history:
https://gradle-enterprise.elastic.co/scans/tests?tests.container=org.elasticsearch.repositories.blobstore.testkit.rest.SnapshotRepoTestKitClientYamlTestSuiteIT&tests.test=test%20%7Bp0%3D/10_analyze/Timeout%20with%20large%20blobs%7D

Failure excerpt:

java.lang.RuntimeException: Failure at [/10_analyze:164]: 60.000 milliseconds timeout on connection http-outgoing-6 [ACTIVE]

  at __randomizedtesting.SeedInfo.seed([AA798EB1F664F981:222DB16B58989479]:0)
  at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:512)
  at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.test(ESClientYamlSuiteTestCase.java:479)
  at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-2)
  at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
  at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:568)
  at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1758)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:946)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:982)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:996)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.tests.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:44)
  at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
  at org.apache.lucene.tests.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:45)
  at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
  at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:390)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:843)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:490)
  at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:955)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:840)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:891)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:902)
  at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.tests.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:38)
  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.tests.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
  at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
  at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
  at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
  at org.apache.lucene.tests.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:47)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:390)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl.lambda$forkTimeoutingTask$0(ThreadLeakControl.java:850)
  at java.lang.Thread.run(Thread.java:833)

  Caused by: java.net.SocketTimeoutException: 60.000 milliseconds timeout on connection http-outgoing-6 [ACTIVE]

    at org.elasticsearch.client.RestClient.extractAndWrapCause(RestClient.java:917)
    at org.elasticsearch.client.RestClient.performRequest(RestClient.java:300)
    at org.elasticsearch.client.RestClient.performRequest(RestClient.java:303)
    at org.elasticsearch.client.RestClient.performRequest(RestClient.java:288)
    at org.elasticsearch.test.rest.yaml.ClientYamlTestClient.callApi(ClientYamlTestClient.java:204)
    at org.elasticsearch.test.rest.yaml.ClientYamlTestExecutionContext.callApiInternal(ClientYamlTestExecutionContext.java:186)
    at org.elasticsearch.test.rest.yaml.ClientYamlTestExecutionContext.callApi(ClientYamlTestExecutionContext.java:106)
    at org.elasticsearch.test.rest.yaml.section.DoSection.execute(DoSection.java:344)
    at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.executeSection(ESClientYamlSuiteTestCase.java:499)
    at org.elasticsearch.test.rest.yaml.ESClientYamlSuiteTestCase.test(ESClientYamlSuiteTestCase.java:479)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-2)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:568)
    at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1758)
    at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:946)
    at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:982)
    at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:996)
    at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
    at org.apache.lucene.tests.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:44)
    at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
    at org.apache.lucene.tests.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:45)
    at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
    at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
    at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
    at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:390)
    at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:843)
    at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:490)
    at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:955)
    at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:840)
    at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:891)
    at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:902)
    at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
    at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
    at org.apache.lucene.tests.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:38)
    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.tests.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
    at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
    at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
    at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
    at org.apache.lucene.tests.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:47)
    at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
    at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:390)
    at com.carrotsearch.randomizedtesting.ThreadLeakControl.lambda$forkTimeoutingTask$0(ThreadLeakControl.java:850)
    at java.lang.Thread.run(Thread.java:833)

    Caused by: java.net.SocketTimeoutException: 60.000 milliseconds timeout on connection http-outgoing-6 [ACTIVE]

      at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.timeout(HttpAsyncRequestExecutor.java:387)
      at org.apache.http.impl.nio.client.InternalIODispatch.onTimeout(InternalIODispatch.java:98)
      at org.apache.http.impl.nio.client.InternalIODispatch.onTimeout(InternalIODispatch.java:40)
      at org.apache.http.impl.nio.reactor.AbstractIODispatch.timeout(AbstractIODispatch.java:175)
      at org.apache.http.impl.nio.reactor.BaseIOReactor.sessionTimedOut(BaseIOReactor.java:261)
      at org.apache.http.impl.nio.reactor.AbstractIOReactor.timeoutCheck(AbstractIOReactor.java:502)
      at org.apache.http.impl.nio.reactor.BaseIOReactor.validate(BaseIOReactor.java:211)
      at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:280)
      at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
      at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:591)
      at java.lang.Thread.run(Thread.java:833)

[elasticsearchmachine]

Pinging @elastic/es-distributed (Team:Distributed)

[iverase]

Another case: https://gradle-enterprise.elastic.co/s/2pamawhuanbci

It did reproduce in 8.5, not in main.

./gradlew ':x-pack:plugin:snapshot-repo-test-kit:qa:rest:yamlRestTest' --tests "org.elasticsearch.repositories.blobstore.testkit.rest.SnapshotRepoTestKitClientYamlTestSuiteIT.test {p0=/10_analyze/Timeout with large blobs}" -Dtests.seed=64BAE55589EF002C -Dtests.configure_test_clusters_with_one_processor=true -Dtests.locale=ja -Dtests.timezone=Antarctica/Troll

[davidkyle]

Another on 8.5: https://gradle-enterprise.elastic.co/s/fyrv4zrzsa3ay

All the failures listed here are single processor node tests and the error is a timeout, could there be a deadlock somewhere?

[joegallo]

https://gradle-enterprise.elastic.co/s/g3jobz7mh2sr6

[cbuescher]

More today on 8.5:
https://gradle-enterprise.elastic.co/s/shhgwoqtslrvi
https://gradle-enterprise.elastic.co/s/shhgwoqtslrvi

[kingherc]

Did a bisect on the PRs to figure out where the fix was introduced. Seems that the specific line of https://github.com/elastic/elasticsearch/pull/90282/files#diff-2835e151b1e7435ff4760a9263e0ecbc359597a9ff02005fc7fec099d38549e6R206 from @original-brownbear fixed this test in main, which does not exist in 8.5. Will drill down more. Just mentioning it for now in case @original-brownbear also has an opinion on the importance of that PR for 8.5.

[kingherc]

Seems that the issue was uncovered when #89234 of @fcofdez introduced a new CI pipeline to do tests with a single processor. Unfortunately the fix mentioned above from @original-brownbear is only in main and not in 8.5, but I believe the issue existed even before the new pipeline was introduced (we just never did have the suitable CI pipeline to uncover it).

[kingherc]

OK, I figured out what is going on in 8.5. Because of the single core, the SNAPSHOT thread pool has 1 worker thread. During this test, the snapshot worker is stuck in the RateLimiter:

"elasticsearch[yamlRestTest-0][snapshot][T#1]" #56 daemon prio=5 os_prio=0 cpu=29.10ms elapsed=16.35s tid=0x00007f0884161ec0 nid=582768 waiting on condition  [0x00007f0950dfb000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(java.base@18.0.2/Native Method)
	at java.lang.Thread.sleep(java.base@18.0.2/Thread.java:337)
	at org.apache.lucene.store.RateLimiter$SimpleRateLimiter.pause(org.apache.lucene.core@9.3.0/RateLimiter.java:147)
	at org.elasticsearch.index.snapshots.blobstore.RateLimitingInputStream.maybePause(org.elasticsearch.server@8.5.0-SNAPSHOT/RateLimitingInputStream.java:44)
	at org.elasticsearch.index.snapshots.blobstore.RateLimitingInputStream.read(org.elasticsearch.server@8.5.0-SNAPSHOT/RateLimitingInputStream.java:64)
	at java.io.FilterInputStream.read(java.base@18.0.2/FilterInputStream.java:105)
	at org.elasticsearch.core.Streams.copy(org.elasticsearch.base@8.5.0-SNAPSHOT/Streams.java:44)
	at org.elasticsearch.core.Streams.copy(org.elasticsearch.base@8.5.0-SNAPSHOT/Streams.java:71)
	at org.elasticsearch.common.blobstore.fs.FsBlobContainer.writeToPath(org.elasticsearch.server@8.5.0-SNAPSHOT/FsBlobContainer.java:327)
	at org.elasticsearch.common.blobstore.fs.FsBlobContainer.writeBlob(org.elasticsearch.server@8.5.0-SNAPSHOT/FsBlobContainer.java:231)
	at org.elasticsearch.repositories.blobstore.testkit.BlobAnalyzeAction$BlobAnalysis.lambda$writeRandomBlob$5(BlobAnalyzeAction.java:335)
	at org.elasticsearch.repositories.blobstore.testkit.BlobAnalyzeAction$BlobAnalysis$$Lambda$6625/0x0000000801c17398.get(Unknown Source)
	at org.elasticsearch.action.ActionListener.completeWith(org.elasticsearch.server@8.5.0-SNAPSHOT/ActionListener.java:462)
	at org.elasticsearch.repositories.blobstore.testkit.BlobAnalyzeAction$BlobAnalysis.writeRandomBlob(BlobAnalyzeAction.java:307)
	at org.elasticsearch.repositories.blobstore.testkit.BlobAnalyzeAction$BlobAnalysis.run(BlobAnalyzeAction.java:277)
	at org.elasticsearch.repositories.blobstore.testkit.BlobAnalyzeAction$TransportAction.doExecute(BlobAnalyzeAction.java:190)
	at org.elasticsearch.repositories.blobstore.testkit.BlobAnalyzeAction$TransportAction.doExecute(BlobAnalyzeAction.java:160)
	at org.elasticsearch.action.support.TransportAction$RequestFilterChain.proceed(org.elasticsearch.server@8.5.0-SNAPSHOT/TransportAction.java:86)
...
	at java.lang.Thread.run(java.base@18.0.2/Thread.java:833)

This is because of the test settings, the thread tries to write a 2GB blob with the exotic rate limit of 1byte/sec rate, so there really is no chance to respond to a timeout/cancel.

When the org.elasticsearch.transport.TransportResponseHandler#handleException() method fails after the 1s timeout, it tries to send the response via the same thread pool:

transportService.getThreadPool().executor(ThreadPool.Names.SNAPSHOT).execute(ActionRunnable.wrap(listener, l -> {
...
                    sendResponse(listingStartTimeNanos, deleteStartTimeNanos);
                }));

Which is not sent since there is no thread available in the thread pool (the single thread is busy in the RateLimiter). And thus the 60sec http timeout happens.

This is all very rare to happen in main since the snapshot thread pool has 10 threads, and one of them will likely send the response. I have tried to reproduce it with 10 concurrent blob writes, but have not so far been successful in reproducing this, so I believe it's extremely hard to have this issue in main.

However, just in case, I would recommend also in main to maybe send the response via the SAME thread pool rather than the SNAPSHOT one. @original-brownbear what do you think?

For the 8.5, and all previous releases where this issue exists (we just happened to catch this now), we could either:

• Backport @original-brownbear 's PR that increases the threadpool to 10 threads to previous applicable releases.
• Send the response via SAME thread pool.
• Simply ignore this corner case and not do anything in previous releases -- if you feel this is a very exotic corner case.

@original-brownbear , what do you recommend?