Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[CI] IndexRecoveryIT testRerouteRecovery failing #99941

Closed
andreidan opened this issue Sep 27, 2023 · 5 comments · Fixed by #100788
Closed

[CI] IndexRecoveryIT testRerouteRecovery failing #99941

andreidan opened this issue Sep 27, 2023 · 5 comments · Fixed by #100788
Assignees
Labels
:Distributed/Recovery Anything around constructing a new shard, either from a local or a remote source. low-risk An open issue or test failure that is a low risk to future releases Team:Distributed Meta label for distributed team >test-failure Triaged test failures from CI

Comments

@andreidan
Copy link
Contributor

andreidan commented Sep 27, 2023

Build scan:
https://gradle-enterprise.elastic.co/s/d3cfn2jnvzye4/tests/:server:internalClusterTest/org.elasticsearch.indices.recovery.IndexRecoveryIT/testRerouteRecovery

Reproduction line:

./gradlew ':server:internalClusterTest' --tests "org.elasticsearch.indices.recovery.IndexRecoveryIT.testRerouteRecovery" -Dtests.seed=D90D29B7DAB2BC89 -Dtests.locale=fr-LU -Dtests.timezone=Australia/Lord_Howe -Druntime.java=21

Applicable branches:
main

Reproduces locally?:
Didn't try
UPDATE:
Does not reproduces locally on my Mac, but does on a remote cloud host running

./gradlew ':server:internalClusterTest' --tests "org.elasticsearch.indices.recovery.IndexRecoveryIT.testRerouteRecovery" -Dtests.iters=100 -Dtests.failfast=true

Failure history:
https://gradle-enterprise.elastic.co/scans/tests?tests.container=org.elasticsearch.indices.recovery.IndexRecoveryIT&tests.test=testRerouteRecovery

Failure excerpt:

java.lang.AssertionError: node A throttling should increase
Expected: a value greater than <0L>
     but: <0L> was equal to <0L>

  at __randomizedtesting.SeedInfo.seed([D90D29B7DAB2BC89:74A69AE3EFEADECB]:0)
  at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
  at org.junit.Assert.assertThat(Assert.java:956)
  at org.elasticsearch.indices.recovery.IndexRecoveryIT.lambda$testRerouteRecovery$2(IndexRecoveryIT.java:519)
  at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:1196)
  at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:1169)
  at org.elasticsearch.indices.recovery.IndexRecoveryIT.testRerouteRecovery(IndexRecoveryIT.java:510)
  at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
  at java.lang.reflect.Method.invoke(Method.java:580)
  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:48)
  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:1583)

@andreidan andreidan added :Distributed/Recovery Anything around constructing a new shard, either from a local or a remote source. >test-failure Triaged test failures from CI labels Sep 27, 2023
@elasticsearchmachine
Copy link
Collaborator

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

@elasticsearchmachine elasticsearchmachine added the Team:Distributed Meta label for distributed team label Sep 27, 2023
@DiannaHohensee DiannaHohensee self-assigned this Sep 27, 2023
@mark-vieira
Copy link
Contributor

Muted in #100209

@DiannaHohensee
Copy link
Contributor

Consistently in the failure cases, I can see fewer data files found for recovery

Failed run:

  1> [2023-10-06T09:52:25,309][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: recovering [_0.cfe] from peer, does not exist in remote
  1> [2023-10-06T09:52:25,309][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: recovering [_0.si] from peer, does not exist in remote
  1> [2023-10-06T09:52:25,309][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: recovering [_0.cfs] from peer, does not exist in remote
  1> [2023-10-06T09:52:25,309][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: recovering [segments_3] from peer, does not exist in remote
  1> [2023-10-06T09:52:25,309][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: total_size[190.5kb], recovering_files [4] with total_size [190.5kb] from peer, recovering_files [0] with total_size [0b] from snapshot, reusing_files [0] with total_size [0b]

Successful run:

    [2023-10-05T22:01:28,013][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: recovering [_0.cfe] from peer, does not exist in remote
    [2023-10-05T22:01:28,013][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: recovering [_0.si] from peer, does not exist in remote
    [2023-10-05T22:01:28,013][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: recovering [_0.cfs] from peer, does not exist in remote
    [2023-10-05T22:01:28,013][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: recovering [_1.cfs] from peer, does not exist in remote
    [2023-10-05T22:01:28,013][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: recovering [_1.cfe] from peer, does not exist in remote
    [2023-10-05T22:01:28,013][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: recovering [_1.si] from peer, does not exist in remote
    [2023-10-05T22:01:28,013][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: recovering [_1_1_Lucene90_0.dvm] from peer, does not exist in remote
    [2023-10-05T22:01:28,014][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: recovering [_1_1_Lucene90_0.dvd] from peer, does not exist in remote
    [2023-10-05T22:01:28,014][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: recovering [_1_1.fnm] from peer, does not exist in remote
    [2023-10-05T22:01:28,014][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: recovering [segments_3] from peer, does not exist in remote
    [2023-10-05T22:01:28,015][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: total_size[143.6kb], recovering_files [10] with total_size [143.6kb] from peer, recovering_files [0] with total_size [0b] from snapshot, reusing_files [0] with total_size [0b]

In a successful run, mostly stats commands are running while waiting for throttling stats to increase. And the code finishes in short order.

    [2023-10-05T22:01:28,015][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node A recoveryStats.throttleTime().millis(): 0
    [2023-10-05T22:01:28,015][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: total_size[143.6kb], recovering_files [10] with total_size [143.6kb] from peer, recovering_files [0] with total_size [0b] from snapshot, reusing_files [0] with total_size [0b]
    [2023-10-05T22:01:28,017][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [16][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
    [2023-10-05T22:01:28,017][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [16][cluster:monitor/nodes/stats[n]] received request
    [2023-10-05T22:01:28,017][TRACE][o.e.t.T.tracer           ] [node_t1] [15][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{gHeOZ778TLuFr9Vr0ctqpA}{f_XnaFW2TRmo1wq-8Vg0yg}{node_t0}{127.0.0.1}{127.0.0.1:13421}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
    [2023-10-05T22:01:28,017][TRACE][o.e.t.T.tracer           ] [node_t0] [15][cluster:monitor/nodes/stats[n]] received request
    [2023-10-05T22:01:28,017][TRACE][o.e.t.T.tracer           ] [node_t1] [16][cluster:monitor/nodes/stats[n]] sent response
    [2023-10-05T22:01:28,017][TRACE][o.e.t.T.tracer           ] [node_t1] [16][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
    [2023-10-05T22:01:28,018][TRACE][o.e.t.T.tracer           ] [node_t0] [15][cluster:monitor/nodes/stats[n]] sent response
    [2023-10-05T22:01:28,018][TRACE][o.e.t.T.tracer           ] [node_t1] [15][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{gHeOZ778TLuFr9Vr0ctqpA}{f_XnaFW2TRmo1wq-8Vg0yg}{node_t0}{127.0.0.1}{127.0.0.1:13421}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
    [2023-10-05T22:01:28,019][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 0
    [2023-10-05T22:01:28,019][TRACE][o.e.t.T.tracer           ] [node_t0] [88][internal:index/shard/recovery/filesInfo] sent to [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
    [2023-10-05T22:01:28,019][TRACE][o.e.t.T.tracer           ] [node_t1] [88][internal:index/shard/recovery/filesInfo] received request
    [2023-10-05T22:01:28,021][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [89][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{gHeOZ778TLuFr9Vr0ctqpA}{f_XnaFW2TRmo1wq-8Vg0yg}{node_t0}{127.0.0.1}{127.0.0.1:13421}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
    [2023-10-05T22:01:28,021][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [89][cluster:monitor/nodes/stats[n]] received request
    [2023-10-05T22:01:28,022][TRACE][o.e.t.T.tracer           ] [node_t0] [89][cluster:monitor/nodes/stats[n]] sent response
    [2023-10-05T22:01:28,022][TRACE][o.e.t.T.tracer           ] [node_t0] [89][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{gHeOZ778TLuFr9Vr0ctqpA}{f_XnaFW2TRmo1wq-8Vg0yg}{node_t0}{127.0.0.1}{127.0.0.1:13421}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
    [2023-10-05T22:01:28,022][TRACE][o.e.t.T.tracer           ] [node_t1] [88][internal:index/shard/recovery/filesInfo] sent response
    [2023-10-05T22:01:28,022][TRACE][o.e.t.T.tracer           ] [node_t0] [90][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
    [2023-10-05T22:01:28,022][TRACE][o.e.t.T.tracer           ] [node_t1] [90][cluster:monitor/nodes/stats[n]] received request
    [2023-10-05T22:01:28,022][TRACE][o.e.t.T.tracer           ] [node_t0] [88][internal:index/shard/recovery/filesInfo] received response from [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
    [2023-10-05T22:01:28,023][TRACE][o.e.t.T.tracer           ] [node_t1] [90][cluster:monitor/nodes/stats[n]] sent response
    [2023-10-05T22:01:28,023][TRACE][o.e.t.T.tracer           ] [node_t0] [90][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
    [2023-10-05T22:01:28,024][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node A recoveryStats.throttleTime().millis(): 0
    [2023-10-05T22:01:28,028][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [91][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{gHeOZ778TLuFr9Vr0ctqpA}{f_XnaFW2TRmo1wq-8Vg0yg}{node_t0}{127.0.0.1}{127.0.0.1:13421}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
    [2023-10-05T22:01:28,028][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [91][cluster:monitor/nodes/stats[n]] received request
    [2023-10-05T22:01:28,029][TRACE][o.e.t.T.tracer           ] [node_t0] [91][cluster:monitor/nodes/stats[n]] sent response
    [2023-10-05T22:01:28,029][TRACE][o.e.t.T.tracer           ] [node_t0] [91][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{gHeOZ778TLuFr9Vr0ctqpA}{f_XnaFW2TRmo1wq-8Vg0yg}{node_t0}{127.0.0.1}{127.0.0.1:13421}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
    [2023-10-05T22:01:28,029][TRACE][o.e.t.T.tracer           ] [node_t0] [93][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
    [2023-10-05T22:01:28,029][TRACE][o.e.t.T.tracer           ] [node_t1] [93][cluster:monitor/nodes/stats[n]] received request
    [2023-10-05T22:01:28,029][TRACE][o.e.t.T.tracer           ] [node_t0] [92][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
    [2023-10-05T22:01:28,029][TRACE][o.e.t.T.tracer           ] [node_t1] [92][internal:index/shard/recovery/file_chunk] received request
    [2023-10-05T22:01:28,030][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
    [2023-10-05T22:01:28,030][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, done pausing
    [2023-10-05T22:01:28,031][TRACE][o.e.t.T.tracer           ] [node_t1] [93][cluster:monitor/nodes/stats[n]] sent response
    [2023-10-05T22:01:28,031][TRACE][o.e.t.T.tracer           ] [node_t0] [93][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
    [2023-10-05T22:01:28,032][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node A recoveryStats.throttleTime().millis(): 0
    [2023-10-05T22:01:28,033][TRACE][o.e.t.T.tracer           ] [node_t1] [92][internal:index/shard/recovery/file_chunk] sent response
    [2023-10-05T22:01:28,034][TRACE][o.e.t.T.tracer           ] [node_t0] [92][internal:index/shard/recovery/file_chunk] received response from [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
    [2023-10-05T22:01:28,039][TRACE][o.e.t.T.tracer           ] [node_t0] [94][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
    [2023-10-05T22:01:28,040][TRACE][o.e.t.T.tracer           ] [node_t1] [94][internal:index/shard/recovery/file_chunk] received request
    [2023-10-05T22:01:28,040][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
    [2023-10-05T22:01:28,040][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [18][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
    [2023-10-05T22:01:28,041][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [18][cluster:monitor/nodes/stats[n]] received request
    [2023-10-05T22:01:28,041][TRACE][o.e.t.T.tracer           ] [node_t1] [17][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{gHeOZ778TLuFr9Vr0ctqpA}{f_XnaFW2TRmo1wq-8Vg0yg}{node_t0}{127.0.0.1}{127.0.0.1:13421}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
    [2023-10-05T22:01:28,041][TRACE][o.e.t.T.tracer           ] [node_t0] [17][cluster:monitor/nodes/stats[n]] received request
    [2023-10-05T22:01:28,041][TRACE][o.e.t.T.tracer           ] [node_t1] [18][cluster:monitor/nodes/stats[n]] sent response
    [2023-10-05T22:01:28,041][TRACE][o.e.t.T.tracer           ] [node_t1] [18][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
    [2023-10-05T22:01:28,041][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, done pausing
    [2023-10-05T22:01:28,042][TRACE][o.e.t.T.tracer           ] [node_t0] [17][cluster:monitor/nodes/stats[n]] sent response
    [2023-10-05T22:01:28,042][TRACE][o.e.t.T.tracer           ] [node_t1] [17][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{gHeOZ778TLuFr9Vr0ctqpA}{f_XnaFW2TRmo1wq-8Vg0yg}{node_t0}{127.0.0.1}{127.0.0.1:13421}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
    [2023-10-05T22:01:28,042][TRACE][o.e.t.T.tracer           ] [node_t1] [94][internal:index/shard/recovery/file_chunk] sent response
    [2023-10-05T22:01:28,042][TRACE][o.e.t.T.tracer           ] [node_t0] [94][internal:index/shard/recovery/file_chunk] received response from [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
    [2023-10-05T22:01:28,043][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 0
    [2023-10-05T22:01:28,060][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [20][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
    [2023-10-05T22:01:28,060][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [20][cluster:monitor/nodes/stats[n]] received request
    [2023-10-05T22:01:28,060][TRACE][o.e.t.T.tracer           ] [node_t1] [19][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{gHeOZ778TLuFr9Vr0ctqpA}{f_XnaFW2TRmo1wq-8Vg0yg}{node_t0}{127.0.0.1}{127.0.0.1:13421}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
    [2023-10-05T22:01:28,060][TRACE][o.e.t.T.tracer           ] [node_t0] [19][cluster:monitor/nodes/stats[n]] received request
    [2023-10-05T22:01:28,060][TRACE][o.e.t.T.tracer           ] [node_t1] [20][cluster:monitor/nodes/stats[n]] sent response
    [2023-10-05T22:01:28,060][TRACE][o.e.t.T.tracer           ] [node_t1] [20][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
    [2023-10-05T22:01:28,061][TRACE][o.e.t.T.tracer           ] [node_t0] [19][cluster:monitor/nodes/stats[n]] sent response
    [2023-10-05T22:01:28,061][TRACE][o.e.t.T.tracer           ] [node_t1] [19][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{gHeOZ778TLuFr9Vr0ctqpA}{f_XnaFW2TRmo1wq-8Vg0yg}{node_t0}{127.0.0.1}{127.0.0.1:13421}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
    [2023-10-05T22:01:28,061][TRACE][o.e.t.T.tracer           ] [node_t0] [95][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{z73TUShHQo-4OJhXCOL6cA}{fHUmN1DLTxKaJBFbf0GMTQ}{node_t1}{127.0.0.1}{127.0.0.1:13422}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
    [2023-10-05T22:01:28,062][TRACE][o.e.t.T.tracer           ] [node_t1] [95][internal:index/shard/recovery/file_chunk] received request
    [2023-10-05T22:01:28,062][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
    [2023-10-05T22:01:28,062][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 1
    [2023-10-05T22:01:28,062][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node A recoveryStats.throttleTime().millis(): 4
    [2023-10-05T22:01:28,062][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery passed failure point ~~~~
    [2023-10-05T22:01:28,062][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] --> speeding up recoveries

For a failed run, however, stats commands are relatively infrequent, and the stats commands seem to stall for roughly 6 seconds. Somehow Node A shows increasing throttling stats, but Node B never does.

  1> [2023-10-06T09:52:25,312][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B nodeBThrottling: 0
  1> [2023-10-06T09:52:25,312][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node A nodeAThrottling: 0
  1> [2023-10-06T09:52:25,312][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] --> checking throttling increases
  1> [2023-10-06T09:52:25,312][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [47][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,312][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [47][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,312][TRACE][o.e.t.T.tracer           ] [node_t0] [46][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,312][TRACE][o.e.t.T.tracer           ] [node_t1] [46][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,312][TRACE][o.e.t.T.tracer           ] [node_t0] [47][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,312][TRACE][o.e.t.T.tracer           ] [node_t0] [47][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,312][TRACE][o.e.t.T.tracer           ] [node_t1] [46][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,312][TRACE][o.e.t.T.tracer           ] [node_t0] [46][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,313][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node A recoveryStats.throttleTime().millis(): 0
  1> [2023-10-06T09:52:25,314][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [49][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,314][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [49][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,314][TRACE][o.e.t.T.tracer           ] [node_t0] [48][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,314][TRACE][o.e.t.T.tracer           ] [node_t1] [48][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,314][TRACE][o.e.t.T.tracer           ] [node_t0] [49][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,314][TRACE][o.e.t.T.tracer           ] [node_t0] [49][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,314][TRACE][o.e.t.T.tracer           ] [node_t1] [48][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,314][TRACE][o.e.t.T.tracer           ] [node_t0] [48][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,315][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node A recoveryStats.throttleTime().millis(): 0
  1> [2023-10-06T09:52:25,317][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [15][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,317][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [15][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,317][TRACE][o.e.t.T.tracer           ] [node_t1] [15][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,317][TRACE][o.e.t.T.tracer           ] [node_t1] [15][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,317][TRACE][o.e.t.T.tracer           ] [node_t1] [16][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,317][TRACE][o.e.t.T.tracer           ] [node_t0] [16][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,318][TRACE][o.e.t.T.tracer           ] [node_t0] [16][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,318][TRACE][o.e.t.T.tracer           ] [node_t1] [16][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,318][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 0
  1> [2023-10-06T09:52:25,322][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [17][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,322][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [17][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,323][TRACE][o.e.t.T.tracer           ] [node_t1] [18][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,323][TRACE][o.e.t.T.tracer           ] [node_t1] [17][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,323][TRACE][o.e.t.T.tracer           ] [node_t0] [18][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,323][TRACE][o.e.t.T.tracer           ] [node_t1] [17][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,323][TRACE][o.e.t.T.tracer           ] [node_t0] [18][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,323][TRACE][o.e.t.T.tracer           ] [node_t1] [18][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,323][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 0
  1> [2023-10-06T09:52:25,327][TRACE][o.e.t.T.tracer           ] [node_t0] [50][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
  1> [2023-10-06T09:52:25,328][TRACE][o.e.t.T.tracer           ] [node_t1] [50][internal:index/shard/recovery/file_chunk] received request
  1> [2023-10-06T09:52:25,328][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
  1> [2023-10-06T09:52:25,328][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, done pausing
  1> [2023-10-06T09:52:25,328][TRACE][o.e.t.T.tracer           ] [node_t1] [50][internal:index/shard/recovery/file_chunk] sent response
  1> [2023-10-06T09:52:25,328][TRACE][o.e.t.T.tracer           ] [node_t0] [50][internal:index/shard/recovery/file_chunk] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,332][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [19][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,332][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [19][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,332][TRACE][o.e.t.T.tracer           ] [node_t1] [19][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,332][TRACE][o.e.t.T.tracer           ] [node_t1] [19][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,332][TRACE][o.e.t.T.tracer           ] [node_t1] [20][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,332][TRACE][o.e.t.T.tracer           ] [node_t0] [20][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,332][TRACE][o.e.t.T.tracer           ] [node_t0] [20][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,332][TRACE][o.e.t.T.tracer           ] [node_t1] [20][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,333][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 0
  1> [2023-10-06T09:52:25,349][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [21][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,349][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [21][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,349][TRACE][o.e.t.T.tracer           ] [node_t1] [21][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,349][TRACE][o.e.t.T.tracer           ] [node_t1] [21][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,349][TRACE][o.e.t.T.tracer           ] [node_t1] [22][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,349][TRACE][o.e.t.T.tracer           ] [node_t0] [22][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,349][TRACE][o.e.t.T.tracer           ] [node_t0] [22][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,349][TRACE][o.e.t.T.tracer           ] [node_t1] [22][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,350][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 0
  1> [2023-10-06T09:52:25,362][TRACE][o.e.t.T.tracer           ] [node_t0] [51][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
  1> [2023-10-06T09:52:25,362][TRACE][o.e.t.T.tracer           ] [node_t1] [51][internal:index/shard/recovery/file_chunk] received request
  1> [2023-10-06T09:52:25,362][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
  1> [2023-10-06T09:52:25,362][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, done pausing
  1> [2023-10-06T09:52:25,363][TRACE][o.e.t.T.tracer           ] [node_t1] [51][internal:index/shard/recovery/file_chunk] sent response
  1> [2023-10-06T09:52:25,363][TRACE][o.e.t.T.tracer           ] [node_t0] [51][internal:index/shard/recovery/file_chunk] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,382][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [53][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,382][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [53][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,382][TRACE][o.e.t.T.tracer           ] [node_t0] [52][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,382][TRACE][o.e.t.T.tracer           ] [node_t1] [52][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,382][TRACE][o.e.t.T.tracer           ] [node_t0] [53][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,382][TRACE][o.e.t.T.tracer           ] [node_t0] [53][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,383][TRACE][o.e.t.T.tracer           ] [node_t1] [52][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,383][TRACE][o.e.t.T.tracer           ] [node_t0] [52][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,383][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node A recoveryStats.throttleTime().millis(): 51
  1> [2023-10-06T09:52:25,383][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 0
  1> [2023-10-06T09:52:25,448][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [55][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,448][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [55][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,448][TRACE][o.e.t.T.tracer           ] [node_t0] [54][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,448][TRACE][o.e.t.T.tracer           ] [node_t1] [54][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,448][TRACE][o.e.t.T.tracer           ] [node_t0] [55][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,448][TRACE][o.e.t.T.tracer           ] [node_t0] [55][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,449][TRACE][o.e.t.T.tracer           ] [node_t1] [54][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,449][TRACE][o.e.t.T.tracer           ] [node_t0] [54][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,449][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node A recoveryStats.throttleTime().millis(): 51
  1> [2023-10-06T09:52:25,449][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 0
  1> [2023-10-06T09:52:25,578][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [23][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,578][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [23][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,578][TRACE][o.e.t.T.tracer           ] [node_t1] [23][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,578][TRACE][o.e.t.T.tracer           ] [node_t1] [23][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,578][TRACE][o.e.t.T.tracer           ] [node_t1] [24][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,578][TRACE][o.e.t.T.tracer           ] [node_t0] [24][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,579][TRACE][o.e.t.T.tracer           ] [node_t0] [24][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,579][TRACE][o.e.t.T.tracer           ] [node_t1] [24][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,579][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 0
  1> [2023-10-06T09:52:25,835][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [25][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,835][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [25][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,836][TRACE][o.e.t.T.tracer           ] [node_t1] [25][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,836][TRACE][o.e.t.T.tracer           ] [node_t1] [25][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,836][TRACE][o.e.t.T.tracer           ] [node_t1] [26][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:25,836][TRACE][o.e.t.T.tracer           ] [node_t0] [26][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:25,836][TRACE][o.e.t.T.tracer           ] [node_t0] [26][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:25,836][TRACE][o.e.t.T.tracer           ] [node_t1] [26][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:25,837][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 0
  1> [2023-10-06T09:52:26,349][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [58][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:26,349][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [58][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:26,349][TRACE][o.e.t.T.tracer           ] [node_t0] [57][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:26,350][TRACE][o.e.t.T.tracer           ] [node_t1] [57][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:26,350][TRACE][o.e.t.T.tracer           ] [node_t0] [58][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:26,350][TRACE][o.e.t.T.tracer           ] [node_t0] [58][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:26,350][TRACE][o.e.t.T.tracer           ] [node_t1] [57][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:26,350][TRACE][o.e.t.T.tracer           ] [node_t0] [57][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:26,350][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node A recoveryStats.throttleTime().millis(): 51
  1> [2023-10-06T09:52:26,351][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 0
  1> [2023-10-06T09:52:26,362][TRACE][o.e.t.T.tracer           ] [node_t0] [59][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
  1> [2023-10-06T09:52:26,362][TRACE][o.e.t.T.tracer           ] [node_t1] [59][internal:index/shard/recovery/file_chunk] received request
  1> [2023-10-06T09:52:26,362][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
  1> [2023-10-06T09:52:26,363][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, done pausing
  1> [2023-10-06T09:52:26,363][TRACE][o.e.t.T.tracer           ] [node_t1] [59][internal:index/shard/recovery/file_chunk] sent response
  1> [2023-10-06T09:52:26,363][TRACE][o.e.t.T.tracer           ] [node_t0] [59][internal:index/shard/recovery/file_chunk] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:27,362][TRACE][o.e.t.T.tracer           ] [node_t0] [61][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
  1> [2023-10-06T09:52:27,362][TRACE][o.e.t.T.tracer           ] [node_t1] [61][internal:index/shard/recovery/file_chunk] received request
  1> [2023-10-06T09:52:27,362][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
  1> [2023-10-06T09:52:27,363][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, done pausing
  1> [2023-10-06T09:52:27,363][TRACE][o.e.t.T.tracer           ] [node_t1] [61][internal:index/shard/recovery/file_chunk] sent response
  1> [2023-10-06T09:52:27,363][TRACE][o.e.t.T.tracer           ] [node_t0] [61][internal:index/shard/recovery/file_chunk] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:27,375][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [63][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:27,375][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [63][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:27,375][TRACE][o.e.t.T.tracer           ] [node_t0] [62][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:27,375][TRACE][o.e.t.T.tracer           ] [node_t1] [62][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:27,375][TRACE][o.e.t.T.tracer           ] [node_t0] [63][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:27,375][TRACE][o.e.t.T.tracer           ] [node_t0] [63][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:27,376][TRACE][o.e.t.T.tracer           ] [node_t1] [62][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:27,376][TRACE][o.e.t.T.tracer           ] [node_t0] [62][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:27,376][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node A recoveryStats.throttleTime().millis(): 2050
  1> [2023-10-06T09:52:27,376][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 0
  1> [2023-10-06T09:52:28,362][TRACE][o.e.t.T.tracer           ] [node_t0] [65][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
  1> [2023-10-06T09:52:28,362][TRACE][o.e.t.T.tracer           ] [node_t1] [65][internal:index/shard/recovery/file_chunk] received request
  1> [2023-10-06T09:52:28,362][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
  1> [2023-10-06T09:52:28,363][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, done pausing
  1> [2023-10-06T09:52:28,363][TRACE][o.e.t.T.tracer           ] [node_t1] [65][internal:index/shard/recovery/file_chunk] sent response
  1> [2023-10-06T09:52:28,363][TRACE][o.e.t.T.tracer           ] [node_t0] [65][internal:index/shard/recovery/file_chunk] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:29,362][TRACE][o.e.t.T.tracer           ] [node_t0] [67][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
  1> [2023-10-06T09:52:29,362][TRACE][o.e.t.T.tracer           ] [node_t1] [67][internal:index/shard/recovery/file_chunk] received request
  1> [2023-10-06T09:52:29,362][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
  1> [2023-10-06T09:52:29,363][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, done pausing
  1> [2023-10-06T09:52:29,363][TRACE][o.e.t.T.tracer           ] [node_t1] [67][internal:index/shard/recovery/file_chunk] sent response
  1> [2023-10-06T09:52:29,363][TRACE][o.e.t.T.tracer           ] [node_t0] [67][internal:index/shard/recovery/file_chunk] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:29,425][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [69][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:29,425][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [69][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:29,425][TRACE][o.e.t.T.tracer           ] [node_t0] [68][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:29,425][TRACE][o.e.t.T.tracer           ] [node_t1] [68][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:29,425][TRACE][o.e.t.T.tracer           ] [node_t0] [69][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:29,425][TRACE][o.e.t.T.tracer           ] [node_t0] [69][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:29,425][TRACE][o.e.t.T.tracer           ] [node_t1] [68][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:29,425][TRACE][o.e.t.T.tracer           ] [node_t0] [68][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:29,426][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node A recoveryStats.throttleTime().millis(): 4050
  1> [2023-10-06T09:52:29,426][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 0
  1> [2023-10-06T09:52:30,362][TRACE][o.e.t.T.tracer           ] [node_t0] [71][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
  1> [2023-10-06T09:52:30,362][TRACE][o.e.t.T.tracer           ] [node_t1] [71][internal:index/shard/recovery/file_chunk] received request
  1> [2023-10-06T09:52:30,362][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
  1> [2023-10-06T09:52:30,363][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, done pausing
  1> [2023-10-06T09:52:30,363][TRACE][o.e.t.T.tracer           ] [node_t1] [71][internal:index/shard/recovery/file_chunk] sent response
  1> [2023-10-06T09:52:30,363][TRACE][o.e.t.T.tracer           ] [node_t0] [71][internal:index/shard/recovery/file_chunk] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:31,362][TRACE][o.e.t.T.tracer           ] [node_t0] [73][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
  1> [2023-10-06T09:52:31,362][TRACE][o.e.t.T.tracer           ] [node_t1] [73][internal:index/shard/recovery/file_chunk] received request
  1> [2023-10-06T09:52:31,363][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
  1> [2023-10-06T09:52:31,363][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, done pausing
  1> [2023-10-06T09:52:31,363][TRACE][o.e.t.T.tracer           ] [node_t1] [73][internal:index/shard/recovery/file_chunk] sent response
  1> [2023-10-06T09:52:31,363][TRACE][o.e.t.T.tracer           ] [node_t0] [73][internal:index/shard/recovery/file_chunk] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:32,362][TRACE][o.e.t.T.tracer           ] [node_t0] [75][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
  1> [2023-10-06T09:52:32,362][TRACE][o.e.t.T.tracer           ] [node_t1] [75][internal:index/shard/recovery/file_chunk] received request
  1> [2023-10-06T09:52:32,362][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
  1> [2023-10-06T09:52:32,363][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, done pausing
  1> [2023-10-06T09:52:32,363][TRACE][o.e.t.T.tracer           ] [node_t1] [75][internal:index/shard/recovery/file_chunk] sent response
  1> [2023-10-06T09:52:32,363][TRACE][o.e.t.T.tracer           ] [node_t0] [75][internal:index/shard/recovery/file_chunk] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:33,362][TRACE][o.e.t.T.tracer           ] [node_t0] [77][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
  1> [2023-10-06T09:52:33,362][TRACE][o.e.t.T.tracer           ] [node_t1] [77][internal:index/shard/recovery/file_chunk] received request
  1> [2023-10-06T09:52:33,362][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
  1> [2023-10-06T09:52:33,363][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, done pausing
  1> [2023-10-06T09:52:33,363][TRACE][o.e.t.T.tracer           ] [node_t1] [77][internal:index/shard/recovery/file_chunk] sent response
  1> [2023-10-06T09:52:33,363][TRACE][o.e.t.T.tracer           ] [node_t0] [77][internal:index/shard/recovery/file_chunk] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:34,362][TRACE][o.e.t.T.tracer           ] [node_t0] [79][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
  1> [2023-10-06T09:52:34,362][TRACE][o.e.t.T.tracer           ] [node_t1] [79][internal:index/shard/recovery/file_chunk] received request
  1> [2023-10-06T09:52:34,363][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
  1> [2023-10-06T09:52:34,363][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, done pausing
  1> [2023-10-06T09:52:34,363][TRACE][o.e.t.T.tracer           ] [node_t1] [79][internal:index/shard/recovery/file_chunk] sent response
  1> [2023-10-06T09:52:34,363][TRACE][o.e.t.T.tracer           ] [node_t0] [79][internal:index/shard/recovery/file_chunk] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:35,294][TRACE][o.e.t.T.tracer           ] [node_t0] [81][internal:index/shard/recovery/file_chunk] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
  1> [2023-10-06T09:52:35,294][TRACE][o.e.t.T.tracer           ] [node_t1] [81][internal:index/shard/recovery/file_chunk] received request
  1> [2023-10-06T09:52:35,295][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, about to pause
  1> [2023-10-06T09:52:35,295][INFO ][o.e.i.r.PeerRecoveryTargetService] [node_t1] ~~~PeerRecoveryTargetService, handleRequest, rate limiter activated, done pausing
  1> [2023-10-06T09:52:35,295][TRACE][o.e.t.T.tracer           ] [node_t1] [81][internal:index/shard/recovery/file_chunk] sent response
  1> [2023-10-06T09:52:35,295][TRACE][o.e.t.T.tracer           ] [node_t0] [81][internal:index/shard/recovery/file_chunk] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:35,296][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] cloning primary's retention lease for target node ID [Pp7H-a8JS022UvMuN2zg6g]
  1> [2023-10-06T09:52:35,297][TRACE][o.e.t.T.tracer           ] [node_t0] [82][indices:admin/seq_no/retention_lease_sync[p]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:35,297][TRACE][o.e.t.T.tracer           ] [node_t0] [82][indices:admin/seq_no/retention_lease_sync[p]] received request
  1> [2023-10-06T09:52:35,297][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] cloned primary's retention lease as [RetentionLease{id='peer_recovery/Pp7H-a8JS022UvMuN2zg6g', retainingSequenceNumber=0, timestamp=1696596755125, source='peer recovery'}]
  1> [2023-10-06T09:52:35,298][TRACE][o.e.t.T.tracer           ] [node_t0] [82][indices:admin/seq_no/retention_lease_sync[p]] sent response
  1> [2023-10-06T09:52:35,298][TRACE][o.e.t.T.tracer           ] [node_t0] [82][indices:admin/seq_no/retention_lease_sync[p]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:35,298][TRACE][o.e.t.T.tracer           ] [node_t0] [83][internal:index/shard/recovery/clean_files] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:35,298][TRACE][o.e.t.T.tracer           ] [node_t1] [83][internal:index/shard/recovery/clean_files] received request
  1> [2023-10-06T09:52:35,305][TRACE][o.e.t.T.tracer           ] [node_t1] [83][internal:index/shard/recovery/clean_files] sent response
  1> [2023-10-06T09:52:35,305][TRACE][o.e.t.T.tracer           ] [node_t0] [83][internal:index/shard/recovery/clean_files] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:35,305][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: took [0s]
  1> [2023-10-06T09:52:35,306][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: prepare remote engine for translog
  1> [2023-10-06T09:52:35,306][TRACE][o.e.t.T.tracer           ] [node_t0] [84][internal:index/shard/recovery/prepare_translog] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
  1> [2023-10-06T09:52:35,306][TRACE][o.e.t.T.tracer           ] [node_t1] [84][internal:index/shard/recovery/prepare_translog] received request
  1> [2023-10-06T09:52:35,315][TRACE][o.e.t.T.tracer           ] [node_t1] [84][internal:index/shard/recovery/prepare_translog] sent response
  1> [2023-10-06T09:52:35,315][TRACE][o.e.t.T.tracer           ] [node_t0] [84][internal:index/shard/recovery/prepare_translog] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:35,316][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase1]: remote engine start took [10ms]
  1> [2023-10-06T09:52:35,317][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] snapshot for recovery; current size is [0]
  1> [2023-10-06T09:52:35,317][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase2]: sending transaction log operations (from [941] to [940]
  1> [2023-10-06T09:52:35,317][TRACE][o.e.t.T.tracer           ] [node_t0] [85][internal:index/shard/recovery/translog_ops] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [30m])
  1> [2023-10-06T09:52:35,318][TRACE][o.e.t.T.tracer           ] [node_t1] [85][internal:index/shard/recovery/translog_ops] received request
  1> [2023-10-06T09:52:35,318][TRACE][o.e.t.T.tracer           ] [node_t1] [85][internal:index/shard/recovery/translog_ops] sent response
  1> [2023-10-06T09:52:35,318][TRACE][o.e.t.T.tracer           ] [node_t0] [85][internal:index/shard/recovery/translog_ops] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:35,319][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] recovery [phase2]: took [1.6ms]
  1> [2023-10-06T09:52:35,319][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] finalizing recovery
  1> [2023-10-06T09:52:35,319][TRACE][o.e.t.T.tracer           ] [node_t0] [86][internal:index/shard/recovery/finalize] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [30m])
  1> [2023-10-06T09:52:35,319][TRACE][o.e.t.T.tracer           ] [node_t1] [86][internal:index/shard/recovery/finalize] received request
  1> [2023-10-06T09:52:35,321][TRACE][o.e.t.T.tracer           ] [node_t1] [86][internal:index/shard/recovery/finalize] sent response
  1> [2023-10-06T09:52:35,321][TRACE][o.e.t.T.tracer           ] [node_t0] [86][internal:index/shard/recovery/finalize] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:35,322][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] performing relocation hand-off
  1> [2023-10-06T09:52:35,322][TRACE][o.e.t.T.tracer           ] [node_t0] [87][internal:index/shard/recovery/handoff_primary_context] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [15m])
  1> [2023-10-06T09:52:35,322][TRACE][o.e.t.T.tracer           ] [node_t1] [87][internal:index/shard/recovery/handoff_primary_context] received request
  1> [2023-10-06T09:52:35,323][TRACE][o.e.t.T.tracer           ] [node_t1] [87][internal:index/shard/recovery/handoff_primary_context] sent response
  1> [2023-10-06T09:52:35,323][TRACE][o.e.t.T.tracer           ] [node_t0] [87][internal:index/shard/recovery/handoff_primary_context] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:35,323][TRACE][o.e.i.r.RecoverySourceHandler] [node_t0] [test-idx-1][0][recover to node_t1] finalizing recovery took [4.1ms]
  1> [2023-10-06T09:52:35,323][TRACE][o.e.t.T.tracer           ] [node_t0] [12][internal:index/shard/recovery/start_recovery] sent response
  1> [2023-10-06T09:52:35,323][TRACE][o.e.t.T.tracer           ] [node_t1] [12][internal:index/shard/recovery/start_recovery] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:35,323][TRACE][o.e.i.r.PeerRecoveryTargetService] [node_t1] [test-idx-1][0] marking recovery from {node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003} as done, id [25]
  1> [2023-10-06T09:52:35,324][TRACE][o.e.i.r.PeerRecoveryTargetService] [node_t1] [test-idx-1][0] recovery completed from {node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}, took[10s]
  1>    phase1: recovered_files [4] with total_size of [190.5kb], took [0s], throttling_wait [0s]
  1>          : reusing_files   [0] with total_size of [0b]
  1>    phase2: start took [10ms]
  1>          : recovered [0] transaction log operations, took [1ms]

  1> [2023-10-06T09:52:35,324][TRACE][o.e.t.T.tracer           ] [node_t1] [37][internal:cluster/shard/started] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:35,324][TRACE][o.e.t.T.tracer           ] [node_t0] [37][internal:cluster/shard/started] received request
  1> [2023-10-06T09:52:35,324][DEBUG][o.e.c.s.MasterService    ] [node_t0] executing cluster state update for [shard-started StartedShardEntry{shardId [[test-idx-1][0]], allocationId [zLCNR-ioTO6PJniNp6JIig], primary term [1], message [after peer recovery]}[StartedShardUpdateTask{entry=StartedShardEntry{shardId [[test-idx-1][0]], allocationId [zLCNR-ioTO6PJniNp6JIig], primary term [1], message [after peer recovery]}, listener=org.elasticsearch.action.ActionListenerImplementations$MappedActionListener/ChannelActionListener{TaskTransportChannel{task=103}{TcpTransportChannel{req=37}{internal:cluster/shard/started}{Netty4TcpChannel{localAddress=/127.0.0.1:13391, remoteAddress=/127.0.0.1:33496, profile=default}}}}/org.elasticsearch.cluster.action.shard.ShardStateAction$ShardStartedTransportHandler$$Lambda/0x00007f3408972220@6062d782}]]
  1> [2023-10-06T09:52:35,325][DEBUG][o.e.c.s.MasterService    ] [node_t0] took [1ms] to compute cluster state update for [shard-started StartedShardEntry{shardId [[test-idx-1][0]], allocationId [zLCNR-ioTO6PJniNp6JIig], primary term [1], message [after peer recovery]}[StartedShardUpdateTask{entry=StartedShardEntry{shardId [[test-idx-1][0]], allocationId [zLCNR-ioTO6PJniNp6JIig], primary term [1], message [after peer recovery]}, listener=org.elasticsearch.action.ActionListenerImplementations$MappedActionListener/ChannelActionListener{TaskTransportChannel{task=103}{TcpTransportChannel{req=37}{internal:cluster/shard/started}{Netty4TcpChannel{localAddress=/127.0.0.1:13391, remoteAddress=/127.0.0.1:33496, profile=default}}}}/org.elasticsearch.cluster.action.shard.ShardStateAction$ShardStartedTransportHandler$$Lambda/0x00007f3408972220@6062d782}]]
  1> [2023-10-06T09:52:35,325][TRACE][o.e.c.s.MasterService    ] [node_t0] cluster state updated, source [shard-started StartedShardEntry{shardId [[test-idx-1][0]], allocationId [zLCNR-ioTO6PJniNp6JIig], primary term [1], message [after peer recovery]}[StartedShardUpdateTask{entry=StartedShardEntry{shardId [[test-idx-1][0]], allocationId [zLCNR-ioTO6PJniNp6JIig], primary term [1], message [after peer recovery]}, listener=org.elasticsearch.action.ActionListenerImplementations$MappedActionListener/ChannelActionListener{TaskTransportChannel{task=103}{TcpTransportChannel{req=37}{internal:cluster/shard/started}{Netty4TcpChannel{localAddress=/127.0.0.1:13391, remoteAddress=/127.0.0.1:33496, profile=default}}}}/org.elasticsearch.cluster.action.shard.ShardStateAction$ShardStartedTransportHandler$$Lambda/0x00007f3408972220@6062d782}]]
  1> cluster uuid: jOPIkf-BTAK1JIrgROdi4Q [committed: true]
  1> version: 12
  1> state uuid: qf7Br-owS_Gg_WMDqtP_mw
  1> from_diff: false
  1> meta data version: 8
  1>    coordination_metadata:
  1>       term: 1
  1>       last_committed_config: VotingConfiguration{MsxO3EAyQruH5T7pFJ7mTg}
  1>       last_accepted_config: VotingConfiguration{MsxO3EAyQruH5T7pFJ7mTg}
  1>       voting tombstones: []
  1>    [test-idx-1/w493pQ07TM-vFE0wOS5z3w]: v[6], mv[2], sv[1], av[1]
  1>       0: p_term [1], isa_ids [zLCNR-ioTO6PJniNp6JIig]
  1> metadata customs:
  1>    persistent_tasks: {"last_allocation_id":1,"tasks":[{"id":"health-node","task":{"health-node":{"params":{}}},"allocation_id":1,"assignment":{"executor_node":"MsxO3EAyQruH5T7pFJ7mTg","explanation":""}}]}   index-graveyard: IndexGraveyard[[]]
  1> nodes (node-left generation: 0):
  1>    {node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}
  1>    {node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}, local, master
  1> node  versions:
  1>    Pp7H-a8JS022UvMuN2zg6g: CompatibilityVersions[transportVersion=8512000, systemIndexMappingsVersion={.tasks=MappingsVersion[version=0, hash=-945584329], .synonyms-2=MappingsVersion[version=1, hash=-888080772]}]
  1>    MsxO3EAyQruH5T7pFJ7mTg: CompatibilityVersions[transportVersion=8512000, systemIndexMappingsVersion={.tasks=MappingsVersion[version=0, hash=-945584329], .synonyms-2=MappingsVersion[version=1, hash=-888080772]}]
  1> routing_table (version 6):
  1> -- index [[test-idx-1/w493pQ07TM-vFE0wOS5z3w]]
  1> ----shard_id [test-idx-1][0]
  1> --------[test-idx-1][0], node[Pp7H-a8JS022UvMuN2zg6g], [P], s[STARTED], a[id=zLCNR-ioTO6PJniNp6JIig], failed_attempts[0]

  1> routing_nodes:
  1> -----node_id[MsxO3EAyQruH5T7pFJ7mTg][V]
  1> -----node_id[Pp7H-a8JS022UvMuN2zg6g][V]
  1> --------[test-idx-1][0], node[Pp7H-a8JS022UvMuN2zg6g], [P], s[STARTED], a[id=zLCNR-ioTO6PJniNp6JIig], failed_attempts[0]
  1> ---- unassigned
  1> customs:
  1>    health: HealthMetadata{diskMetadata={"high_watermark":"1b","high_max_headroom":"-1b","flood_stage_watermark":"1b","flood_stage_max_headroom":"-1b","frozen_flood_stage_watermark":"95%","frozen_flood_stage_max_headroom":"20gb"}, shardLimitsMetadata=ShardLimits[maxShardsPerNode=1000, maxShardsPerNodeFrozen=3000]}
  1> [2023-10-06T09:52:35,326][DEBUG][o.e.c.s.MasterService    ] [node_t0] publishing cluster state version [12]
  1> [2023-10-06T09:52:35,326][TRACE][o.e.t.T.tracer           ] [node_t0] [88][internal:cluster/coordination/publish_state] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:35,327][TRACE][o.e.t.T.tracer           ] [node_t1] [88][internal:cluster/coordination/publish_state] received request
  1> [2023-10-06T09:52:35,332][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [90][cluster:monitor/nodes/stats[n]] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:35,332][TRACE][o.e.t.T.tracer           ] [testRerouteRecovery] [90][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:35,332][TRACE][o.e.t.T.tracer           ] [node_t0] [89][cluster:monitor/nodes/stats[n]] sent to [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:35,332][TRACE][o.e.t.T.tracer           ] [node_t1] [89][cluster:monitor/nodes/stats[n]] received request
  1> [2023-10-06T09:52:35,332][TRACE][o.e.t.T.tracer           ] [node_t0] [90][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:35,332][TRACE][o.e.t.T.tracer           ] [node_t0] [90][cluster:monitor/nodes/stats[n]] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:35,332][TRACE][o.e.t.T.tracer           ] [node_t1] [89][cluster:monitor/nodes/stats[n]] sent response
  1> [2023-10-06T09:52:35,332][TRACE][o.e.t.T.tracer           ] [node_t0] [89][cluster:monitor/nodes/stats[n]] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:35,333][TRACE][o.e.t.T.tracer           ] [node_t0] [91][internal:cluster/coordination/commit_state] sent to [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}] (timeout: [null])
  1> [2023-10-06T09:52:35,333][TRACE][o.e.t.T.tracer           ] [node_t0] [91][internal:cluster/coordination/commit_state] received request
  1> [2023-10-06T09:52:35,333][TRACE][o.e.t.T.tracer           ] [node_t0] [91][internal:cluster/coordination/commit_state] sent response
  1> [2023-10-06T09:52:35,333][TRACE][o.e.t.T.tracer           ] [node_t0] [91][internal:cluster/coordination/commit_state] received response from [{node_t0}{MsxO3EAyQruH5T7pFJ7mTg}{0wJc4neCTM2mHDHaUsSebQ}{node_t0}{127.0.0.1}{127.0.0.1:13391}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:35,333][TRACE][o.e.t.T.tracer           ] [node_t1] [88][internal:cluster/coordination/publish_state] sent response
  1> [2023-10-06T09:52:35,333][TRACE][o.e.t.T.tracer           ] [node_t0] [88][internal:cluster/coordination/publish_state] received response from [{node_t1}{Pp7H-a8JS022UvMuN2zg6g}{cVjXuNiPTnqHQem9uKnW0Q}{node_t1}{127.0.0.1}{127.0.0.1:13392}{cdfhilmrstw}{8.12.0}{7000099-8500003}]
  1> [2023-10-06T09:52:35,333][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node A recoveryStats.throttleTime().millis(): 9981
  1> [2023-10-06T09:52:35,333][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] ~~~~testRerouteRecovery Node B recoveryStats.throttleTime().millis(): 0
  1> [2023-10-06T09:52:35,333][INFO ][o.e.i.r.IndexRecoveryIT  ] [testRerouteRecovery] [IndexRecoveryIT#testRerouteRecovery {seed=[1A584CEA05944470:F158331BA36FE0B5]}]: cleaning up after test

@DiannaHohensee
Copy link
Contributor

DiannaHohensee commented Oct 9, 2023

As an update here, Dave used git bisect and identified when the failures started occurring. Apparently it was a JDK 21 update that initiated the failures. The conclusion is that the test likely isn't stable, and JDK changes shook things up enough to destabilize the test. So, next steps are to split the test into two separate tests, testing throttling on the source node, and then throttling on the target node, separately: the notion is that throttling on the source reasonably results in no throttling being necessary on the target. But it's still curious that we do see throttling on the target in the test happy path, so that will be investigated further to find out why: one lead is that the file size affects throttling, since there are consistently few data files in the failure case, and that could turn out to be a bug.

@henningandersen henningandersen added the low-risk An open issue or test failure that is a low risk to future releases label Oct 11, 2023
@DiannaHohensee
Copy link
Contributor

Confirmed that it makes sense that Node B makes no progress on throttling. RateLimiter.pause() returns the time waited, and from adding logging to this code, the test calls that code once per second, because the source recovery is throttling progress. The SimpleRateLimter.pause() function (part of the Lucene library) will return 0 time waiting if the desired wait time has already elapsed with the last pause.

My notions about why the test is failing are a) just random whether timing lines up such that the target node throttles a little (enough for the test to pass) or not at all; or b) perhaps the persisted settings aren't picked up. I've put up a PR fix, in which the tests reliably pass, and I don't think this is worth further time investigating.

mfussenegger added a commit to crate/crate that referenced this issue Oct 16, 2023
The test is currently flaky and it was upstream as well:

- elastic/elasticsearch#99941

In ES they split out the throttle checks into dedicated tests:

- elastic/elasticsearch#100788

We can't copy them due to the License, but we can at least remove the
broken checks to make the test non-flaky.
mfussenegger added a commit to crate/crate that referenced this issue Oct 16, 2023
The test is currently flaky and it was upstream as well:

- elastic/elasticsearch#99941

In ES they split out the throttle checks into dedicated tests:

- elastic/elasticsearch#100788

We can't copy them due to the License, but we can at least remove the
broken checks to make the test non-flaky.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
:Distributed/Recovery Anything around constructing a new shard, either from a local or a remote source. low-risk An open issue or test failure that is a low risk to future releases Team:Distributed Meta label for distributed team >test-failure Triaged test failures from CI
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants