You are viewing a plain text version of this content. The canonical link for it is here.
Posted to builds@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2021/11/10 09:53:38 UTC
[JENKINS] Lucene » Lucene-Solr-Tests-8.11 - Build # 49 - Unstable!
Build: https://ci-builds.apache.org/job/Lucene/job/Lucene-Solr-Tests-8.11/49/
1 tests failed.
FAILED: org.apache.solr.cloud.autoscaling.sim.TestSimScenario.testAutoAddReplicas
Error Message:
Timed out waiting for trigger .auto_add_replicas to fire after simulated 60s (real 1200ms).
Stack Trace:
java.io.IOException: Timed out waiting for trigger .auto_add_replicas to fire after simulated 60s (real 1200ms).
at __randomizedtesting.SeedInfo.seed([A33F0FB252633F13:2A9FFCCE2668F33A]:0)
at org.apache.solr.cloud.autoscaling.sim.SimScenario$SimWaitListener.wait(SimScenario.java:705)
at org.apache.solr.cloud.autoscaling.sim.SimScenario$WaitEvent.execute(SimScenario.java:771)
at org.apache.solr.cloud.autoscaling.sim.SimScenario.run(SimScenario.java:1119)
at org.apache.solr.cloud.autoscaling.sim.TestSimScenario.testAutoAddReplicas(TestSimScenario.java:57)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1750)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:938)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:974)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:988)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.junit.rules.RunRules.evaluate(RunRules.java:20)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.junit.rules.RunRules.evaluate(RunRules.java:20)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:947)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:832)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:883)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:894)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.junit.rules.RunRules.evaluate(RunRules.java:20)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at org.junit.rules.RunRules.evaluate(RunRules.java:20)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.lang.Thread.run(Thread.java:748)
Build Log:
[...truncated 13512 lines...]
[junit4] Suite: org.apache.solr.cloud.autoscaling.sim.TestSimScenario
[junit4] 2> 176249 INFO (SUITE-TestSimScenario-seed#[A33F0FB252633F13]-worker) [ ] o.a.s.SolrTestCase Setting 'solr.default.confdir' system property to test-framework derived value of '/home/jenkins/jenkins-slave/workspace/Lucene/Lucene-Solr-Tests-8.11/solr/server/solr/configsets/_default/conf'
[junit4] 2> 176249 INFO (SUITE-TestSimScenario-seed#[A33F0FB252633F13]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> 176250 INFO (SUITE-TestSimScenario-seed#[A33F0FB252633F13]-worker) [ ] o.a.s.u.ErrorLogMuter Closing ErrorLogMuter-regex-24 after mutting 0 log messages
[junit4] 2> 176250 INFO (SUITE-TestSimScenario-seed#[A33F0FB252633F13]-worker) [ ] o.a.s.u.ErrorLogMuter Creating ErrorLogMuter-regex-25 for ERROR logs matching regex: ignore_exception
[junit4] 2> 176251 INFO (SUITE-TestSimScenario-seed#[A33F0FB252633F13]-worker) [ ] o.a.s.SolrTestCaseJ4 Created dataDir: /home/jenkins/jenkins-slave/workspace/Lucene/Lucene-Solr-Tests-8.11/solr/build/solr-core/test/J0/temp/solr.cloud.autoscaling.sim.TestSimScenario_A33F0FB252633F13-001/data-dir-11-001
[junit4] 2> 176251 WARN (SUITE-TestSimScenario-seed#[A33F0FB252633F13]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=9 numCloses=9
[junit4] 2> 176263 INFO (SUITE-TestSimScenario-seed#[A33F0FB252633F13]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=false
[junit4] 2> 176265 INFO (SUITE-TestSimScenario-seed#[A33F0FB252633F13]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN)
[junit4] 2> 176277 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testSplitShard
[junit4] 2> 176321 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 1. CreateCluster numNodes=2
[junit4] 2> 176321 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario CreateCluster numNodes=2
[junit4] 2> 176360 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.SolrPaths solr home defaulted to 'solr/' (could not find system property or JNDI)
[junit4] 2> 176406 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10000_solr
[junit4] 2> 176406 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 176407 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 176407 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 176407 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 176435 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=0
[junit4] 2> 176436 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 0
[junit4] 2> 176436 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 176436 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 2. RunSolrRequest path=/admin/collections&action=CREATE&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=5
[junit4] 2> 176436 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collections&action=CREATE&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=5
[junit4] 2> 176445 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr]
[junit4] 2> 176454 DEBUG (simCloudManagerPool-1333-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- simCreateCollection testCollection, currentVersion=1
[junit4] 2> 176454 DEBUG (simCloudManagerPool-1333-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=1
[junit4] 2> 176456 DEBUG (simCloudManagerPool-1333-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 1
[junit4] 2> 176459 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 176459 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 176459 DEBUG (ScheduledTrigger-1334-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 176669 DEBUG (simCloudManagerPool-1333-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=2
[junit4] 2> 176671 DEBUG (simCloudManagerPool-1333-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 2
[junit4] 2> 176719 DEBUG (ScheduledTrigger-1334-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 176732 DEBUG (simCloudManagerPool-1333-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=3
[junit4] 2> 176733 DEBUG (simCloudManagerPool-1333-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 3
[junit4] 2> 176733 DEBUG (simCloudManagerPool-1333-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1)
[junit4] 2> 176740 DEBUG (ScheduledTrigger-1334-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 176734 DEBUG (simCloudManagerPool-1333-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1 (currentVersion=4): {"core_node1":{}}
[junit4] 2> 176754 DEBUG (simCloudManagerPool-1333-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=4
[junit4] 2> 176755 DEBUG (simCloudManagerPool-1333-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 4
[junit4] 2> 176760 DEBUG (ScheduledTrigger-1334-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 176766 DEBUG (simCloudManagerPool-1333-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=5
[junit4] 2> 176766 DEBUG (simCloudManagerPool-1333-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 5
[junit4] 2> 176766 DEBUG (simCloudManagerPool-1333-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard2)
[junit4] 2> 176766 DEBUG (simCloudManagerPool-1333-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard2 (currentVersion=6): {"core_node3":{}}
[junit4] 2> 176766 DEBUG (simCloudManagerPool-1333-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- finished createCollection testCollection, currentVersion=6
[junit4] 2> 176767 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 3. WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 176767 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 176777 DEBUG (simCloudManagerPool-1333-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=6
[junit4] 2> 176777 DEBUG (simCloudManagerPool-1333-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 6
[junit4] 2> 176777 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=7
[junit4] 2> 176777 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 7
[junit4] 2> 176778 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 4. SetShardMetrics collection=testCollection&shard=shard1&INDEX.sizeInBytes=1000000000
[junit4] 2> 176778 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario SetShardMetrics collection=testCollection&shard=shard1&INDEX.sizeInBytes=1000000000
[junit4] 2> 176779 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 5. SetNodeMetrics nodeset=#ANY&freedisk=1.5
[junit4] 2> 176779 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario SetNodeMetrics nodeset=#ANY&freedisk=1.5
[junit4] 2> 176780 DEBUG (ScheduledTrigger-1334-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 176779 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 6. RunSolrRequest path=/admin/collection&action=SPLITSHARD&collection=testCollection&shard=shard1&splitMethod=${method}
[junit4] 2> 176781 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collection&action=SPLITSHARD&collection=testCollection&shard=shard1&splitMethod=REWRITE
[junit4] 2> 176789 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 176789 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 176789 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 176789 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 176789 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 176789 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 176789 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 176789 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 1. CreateCluster numNodes=2
[junit4] 2> 176789 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario CreateCluster numNodes=2
[junit4] 2> 176794 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10002_solr
[junit4] 2> 176794 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 176794 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 176795 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 176795 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 176795 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=0
[junit4] 2> 176795 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 0
[junit4] 2> 176795 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 176795 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 2. RunSolrRequest path=/admin/collections&action=CREATE&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=5
[junit4] 2> 176795 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collections&action=CREATE&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=5
[junit4] 2> 176799 DEBUG (simCloudManagerPool-1339-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- simCreateCollection testCollection, currentVersion=1
[junit4] 2> 176799 DEBUG (simCloudManagerPool-1339-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=1
[junit4] 2> 176811 DEBUG (simCloudManagerPool-1339-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 1
[junit4] 2> 176811 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10002_solr, 127.0.0.1:10003_solr]
[junit4] 2> 176811 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 176811 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 176812 DEBUG (ScheduledTrigger-1340-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 176821 DEBUG (simCloudManagerPool-1339-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=2
[junit4] 2> 176821 DEBUG (simCloudManagerPool-1339-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 2
[junit4] 2> 176837 DEBUG (ScheduledTrigger-1340-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 176847 DEBUG (simCloudManagerPool-1339-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=3
[junit4] 2> 176847 DEBUG (simCloudManagerPool-1339-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 3
[junit4] 2> 176847 DEBUG (simCloudManagerPool-1339-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1)
[junit4] 2> 176847 DEBUG (simCloudManagerPool-1339-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1 (currentVersion=4): {"core_node1":{}}
[junit4] 2> 176857 DEBUG (simCloudManagerPool-1339-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=4
[junit4] 2> 176858 DEBUG (simCloudManagerPool-1339-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 4
[junit4] 2> 176858 DEBUG (ScheduledTrigger-1340-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 176868 DEBUG (simCloudManagerPool-1339-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=5
[junit4] 2> 176869 DEBUG (simCloudManagerPool-1339-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 5
[junit4] 2> 176869 DEBUG (simCloudManagerPool-1339-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard2)
[junit4] 2> 176869 DEBUG (simCloudManagerPool-1339-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard2 (currentVersion=6): {"core_node3":{}}
[junit4] 2> 176869 DEBUG (simCloudManagerPool-1339-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- finished createCollection testCollection, currentVersion=6
[junit4] 2> 176869 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 3. WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 176869 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 176878 DEBUG (ScheduledTrigger-1340-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 177044 DEBUG (ScheduledTrigger-1340-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 177044 DEBUG (simCloudManagerPool-1339-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=6
[junit4] 2> 177044 DEBUG (simCloudManagerPool-1339-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 6
[junit4] 2> 177079 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=7
[junit4] 2> 177081 DEBUG (ScheduledTrigger-1340-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 177081 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 7
[junit4] 2> 177081 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 4. SetShardMetrics collection=testCollection&shard=shard1&INDEX.sizeInBytes=1000000000
[junit4] 2> 177081 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario SetShardMetrics collection=testCollection&shard=shard1&INDEX.sizeInBytes=1000000000
[junit4] 2> 177082 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 5. SetNodeMetrics nodeset=#ANY&freedisk=1.5
[junit4] 2> 177082 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario SetNodeMetrics nodeset=#ANY&freedisk=1.5
[junit4] 2> 177082 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 6. RunSolrRequest path=/admin/collection&action=SPLITSHARD&collection=testCollection&shard=shard1&splitMethod=${method}
[junit4] 2> 177082 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collection&action=SPLITSHARD&collection=testCollection&shard=shard1&splitMethod=LINK
[junit4] 2> 177103 DEBUG (ScheduledTrigger-1340-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 177123 DEBUG (ScheduledTrigger-1340-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 177143 DEBUG (ScheduledTrigger-1340-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 177163 DEBUG (ScheduledTrigger-1340-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 177184 DEBUG (ScheduledTrigger-1340-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 177187 INFO (simCloudManagerPool-1339-thread-6) [ ] o.a.s.c.a.c.SplitShardCmd numSubShards set at: 2
[junit4] 2> 177204 DEBUG (ScheduledTrigger-1340-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 177224 DEBUG (ScheduledTrigger-1340-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 177228 DEBUG (simCloudManagerPool-1339-thread-6) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=8
[junit4] 2> 177229 DEBUG (simCloudManagerPool-1339-thread-6) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 8
[junit4] 2> 177245 DEBUG (ScheduledTrigger-1340-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 177245 DEBUG (simCloudManagerPool-1339-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=9
[junit4] 2> 177249 DEBUG (simCloudManagerPool-1339-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 9
[junit4] 2> 177249 DEBUG (simCloudManagerPool-1339-thread-9) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=10
[junit4] 2> 177252 DEBUG (simCloudManagerPool-1339-thread-9) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 10
[junit4] 2> 177252 DEBUG (simCloudManagerPool-1339-thread-9) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1_1)
[junit4] 2> 177252 DEBUG (simCloudManagerPool-1339-thread-9) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1_1 (currentVersion=11): {"core_node12":{}}
[junit4] 2> 177255 DEBUG (simCloudManagerPool-1339-thread-6) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=11
[junit4] 2> 177256 DEBUG (simCloudManagerPool-1339-thread-6) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 11
[junit4] 2> 177256 DEBUG (simCloudManagerPool-1339-thread-6) [ ] o.a.s.c.a.s.SimClusterStateProvider ** no leader in testCollection / shard1_0:{
[junit4] 2> "parent":"shard1",
[junit4] 2> "stateTimestamp":"1636534112774988450",
[junit4] 2> "range":"80000000-bfffffff",
[junit4] 2> "state":"construction",
[junit4] 2> "replicas":{
[junit4] 2> "core_node10":{
[junit4] 2> "core":"testCollection_shard1_0_replica_n9",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":20480,
[junit4] 2> "node_name":"127.0.0.1:10002_solr",
[junit4] 2> "base_url":"https://127.0.0.1:10002/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":1.9073486328125E-5,
[junit4] 2> "SEARCHER.searcher.numDocs":0},
[junit4] 2> "core_node8":{
[junit4] 2> "core":"testCollection_shard1_0_replica_n7",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":20480,
[junit4] 2> "node_name":"127.0.0.1:10003_solr",
[junit4] 2> "base_url":"https://127.0.0.1:10003/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":1.9073486328125E-5,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}}
[junit4] 2> 177256 DEBUG (simCloudManagerPool-1339-thread-10) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1_0)
[junit4] 2> 177256 DEBUG (simCloudManagerPool-1339-thread-10) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1_0 (currentVersion=12): {"core_node10":{}}
[junit4] 2> 177258 DEBUG (simCloudManagerPool-1339-thread-6) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=12
[junit4] 2> 177258 DEBUG (simCloudManagerPool-1339-thread-6) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 12
[junit4] 2> 177259 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 7. WaitCollection collection=testCollection&shards=4&withInactive=true&replicas=2&requireLeaders=true
[junit4] 2> 177259 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario WaitCollection collection=testCollection&shards=4&withInactive=true&replicas=2&requireLeaders=true
[junit4] 2> 177259 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=13
[junit4] 2> 177259 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 13
[junit4] 2> 177260 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 177260 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 177260 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 177260 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 177260 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 177260 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 177260 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 177262 INFO (TEST-TestSimScenario.testSplitShard-seed#[A33F0FB252633F13]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testSplitShard
[junit4] 2> 177266 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testIndexing
[junit4] 2> 177267 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 1. CreateCluster numNodes=100
[junit4] 2> 177267 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario CreateCluster numNodes=100
[junit4] 2> 177274 DEBUG (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10004_solr
[junit4] 2> 177275 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 177275 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 177279 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 177279 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 177279 DEBUG (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=0
[junit4] 2> 177279 DEBUG (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 0
[junit4] 2> 177279 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 177282 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10004_solr, 127.0.0.1:10018_solr, 127.0.0.1:10026_solr, 127.0.0.1:10012_solr, 127.0.0.1:10020_solr, 127.0.0.1:10023_solr, 127.0.0.1:10007_solr, 127.0.0.1:10015_solr, 127.0.0.1:10010_solr, 127.0.0.1:10016_solr, 127.0.0.1:10005_solr, 127.0.0.1:10013_solr, 127.0.0.1:10021_solr, 127.0.0.1:10035_solr, 127.0.0.1:10032_solr, 127.0.0.1:10008_solr, 127.0.0.1:10019_solr, 127.0.0.1:10024_solr, 127.0.0.1:10027_solr, 127.0.0.1:10022_solr, 127.0.0.1:10033_solr, 127.0.0.1:10025_solr, 127.0.0.1:10017_solr, 127.0.0.1:10028_solr, 127.0.0.1:10031_solr, 127.0.0.1:10034_solr, 127.0.0.1:10006_solr, 127.0.0.1:10009_solr, 127.0.0.1:10029_solr, 127.0.0.1:10030_solr, 127.0.0.1:10014_solr, 127.0.0.1:10011_solr]
[junit4] 2> 177282 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 177282 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 177282 DEBUG (ScheduledTrigger-1346-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 32 and last live nodes: 32
[junit4] 2> 177501 DEBUG (ScheduledTrigger-1346-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 53 and last live nodes: 32
[junit4] 2> 177508 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 2. RunSolrRequest path=/admin/collections&action=CREATE&autoAddReplicas=true&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=2
[junit4] 2> 177508 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collections&action=CREATE&autoAddReplicas=true&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=2
[junit4] 2> 177523 DEBUG (ScheduledTrigger-1346-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 53
[junit4] 2> 177523 DEBUG (simCloudManagerPool-1345-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- simCreateCollection testCollection, currentVersion=1
[junit4] 2> 177523 DEBUG (simCloudManagerPool-1345-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=1
[junit4] 2> 177524 DEBUG (simCloudManagerPool-1345-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 1
[junit4] 2> 177534 DEBUG (simCloudManagerPool-1345-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=2
[junit4] 2> 177534 DEBUG (simCloudManagerPool-1345-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 2
[junit4] 2> 177544 DEBUG (ScheduledTrigger-1346-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 177555 DEBUG (simCloudManagerPool-1345-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=3
[junit4] 2> 177556 DEBUG (simCloudManagerPool-1345-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 3
[junit4] 2> 177556 DEBUG (simCloudManagerPool-1345-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1)
[junit4] 2> 177556 DEBUG (simCloudManagerPool-1345-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1 (currentVersion=4): {"core_node1":{}}
[junit4] 2> 177559 DEBUG (simCloudManagerPool-1345-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- finished createCollection testCollection, currentVersion=4
[junit4] 2> 177560 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 3. WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 177560 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 177564 DEBUG (ScheduledTrigger-1346-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 177571 DEBUG (simCloudManagerPool-1345-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=4
[junit4] 2> 177572 DEBUG (simCloudManagerPool-1345-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 4
[junit4] 2> 177582 DEBUG (simCloudManagerPool-1345-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=5
[junit4] 2> 177582 DEBUG (simCloudManagerPool-1345-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 5
[junit4] 2> 177582 DEBUG (simCloudManagerPool-1345-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard2)
[junit4] 2> 177582 DEBUG (simCloudManagerPool-1345-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard2 (currentVersion=6): {"core_node3":{}}
[junit4] 2> 177583 DEBUG (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=6
[junit4] 2> 177583 DEBUG (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 6
[junit4] 2> 177584 DEBUG (ScheduledTrigger-1346-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 177593 DEBUG (simCloudManagerPool-1345-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=7
[junit4] 2> 177593 DEBUG (simCloudManagerPool-1345-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 7
[junit4] 2> 177593 DEBUG (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=8
[junit4] 2> 177593 DEBUG (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 8
[junit4] 2> 177594 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 4. RunSolrRequest path=/admin/autoscaling&httpMethod=POST&stream.body={'set-trigger':{'name':'indexSizeTrigger','event':'indexSize','waitFor':'10s','aboveDocs':1000,'enabled':true,'actions':[{'name':'compute_plan','class':'solr.ComputePlanAction'},{'name':'execute_plan','class':'solr.ExecutePlanAction'}]}}
[junit4] 2> 177594 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/autoscaling&httpMethod=POST&stream.body={'set-trigger':{'name':'indexSizeTrigger','event':'indexSize','waitFor':'10s','aboveDocs':1000,'enabled':true,'actions':[{'name':'compute_plan','class':'solr.ComputePlanAction'},{'name':'execute_plan','class':'solr.ExecutePlanAction'}]}}
[junit4] 2> 177604 DEBUG (ScheduledTrigger-1346-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 177624 DEBUG (ScheduledTrigger-1346-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 177645 DEBUG (ScheduledTrigger-1346-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 177661 DEBUG (simCloudManagerPool-1345-thread-6) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 177661 DEBUG (simCloudManagerPool-1345-thread-6) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 177665 DEBUG (ScheduledTrigger-1346-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 177666 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 2
[junit4] 2> 177666 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 5. SetEventListener trigger=indexSizeTrigger&stage=SUCCEEDED
[junit4] 2> 177666 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario SetEventListener trigger=indexSizeTrigger&stage=SUCCEEDED
[junit4] 2> 177666 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 177666 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 2
[junit4] 2> 177667 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 6. IndexDocs collection=testCollection&numDocs=3000
[junit4] 2> 177667 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario IndexDocs collection=testCollection&numDocs=3000
[junit4] 2> 177680 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 7. RunSimulator
[junit4] 2> 177680 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario RunSimulator
[junit4] 2> 177689 DEBUG (ScheduledTrigger-1346-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 177710 DEBUG (ScheduledTrigger-1346-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 177730 DEBUG (ScheduledTrigger-1346-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 177751 DEBUG (ScheduledTrigger-1346-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 177771 DEBUG (ScheduledTrigger-1346-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 177791 DEBUG (ScheduledTrigger-1346-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 177812 DEBUG (ScheduledTrigger-1346-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 177833 DEBUG (ScheduledTrigger-1346-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 178115 DEBUG (ScheduledTrigger-1346-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 178117 DEBUG (ScheduledTrigger-1346-thread-3) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"85831cd6f74d4dT70g2uijsefksev1ye9h49zvqk",
[junit4] 2> "source":"indexSizeTrigger",
[junit4] 2> "eventTime":37580331791371597,
[junit4] 2> "eventType":"INDEXSIZE",
[junit4] 2> "properties":{
[junit4] 2> "aboveSize":{
[junit4] 2> "testCollection_shard1_replica_n1":"docs=1500, bytes=3082240",
[junit4] 2> "testCollection_shard2_replica_n3":"docs=1500, bytes=3082240"},
[junit4] 2> "belowSize":{},
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard1"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}},
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard2"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}}]}}
[junit4] 2> 178117 DEBUG (ScheduledTrigger-1346-thread-3) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [.auto_add_replicas, .scheduled_maintenance, indexSizeTrigger]
[junit4] 2> 178118 DEBUG (ScheduledTrigger-1346-thread-3) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"85831cd6f74d4dT70g2uijsefksev1ye9h49zvqk",
[junit4] 2> "source":"indexSizeTrigger",
[junit4] 2> "eventTime":37580331791371597,
[junit4] 2> "eventType":"INDEXSIZE",
[junit4] 2> "properties":{
[junit4] 2> "aboveSize":{
[junit4] 2> "testCollection_shard1_replica_n1":"docs=1500, bytes=3082240",
[junit4] 2> "testCollection_shard2_replica_n3":"docs=1500, bytes=3082240"},
[junit4] 2> "belowSize":{},
[junit4] 2> "_enqueue_time_":37580352735144947,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard1"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}},
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard2"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}}]}}
[junit4] 2> 178147 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"85831cd6f74d4dT70g2uijsefksev1ye9h49zvqk",
[junit4] 2> "source":"indexSizeTrigger",
[junit4] 2> "eventTime":37580331791371597,
[junit4] 2> "eventType":"INDEXSIZE",
[junit4] 2> "properties":{
[junit4] 2> "aboveSize":{
[junit4] 2> "testCollection_shard1_replica_n1":"docs=1500, bytes=3082240",
[junit4] 2> "testCollection_shard2_replica_n3":"docs=1500, bytes=3082240"},
[junit4] 2> "belowSize":{},
[junit4] 2> "_enqueue_time_":37580352735144947,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard1"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}},
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard2"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}}]}}
[junit4] 2> 178148 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- processing event: {
[junit4] 2> "id":"85831cd6f74d4dT70g2uijsefksev1ye9h49zvqk",
[junit4] 2> "source":"indexSizeTrigger",
[junit4] 2> "eventTime":37580331791371597,
[junit4] 2> "eventType":"INDEXSIZE",
[junit4] 2> "properties":{
[junit4] 2> "aboveSize":{
[junit4] 2> "testCollection_shard1_replica_n1":"docs=1500, bytes=3082240",
[junit4] 2> "testCollection_shard2_replica_n3":"docs=1500, bytes=3082240"},
[junit4] 2> "belowSize":{},
[junit4] 2> "_enqueue_time_":37580352735144947,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard1"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}},
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard2"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}}]}} with context properties: {BEFORE_ACTION=[compute_plan]}
[junit4] 2> 178172 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- estimated total max ops=1200, effective maxOps=1200
[junit4] 2> 178172 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- adjusting limit due to explicitly requested number of ops=2
[junit4] 2> 178174 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.ComputePlanAction Computed Plan: action=SPLITSHARD&collection=testCollection&shard=shard1&splitMethod=link&splitByPrefix=false
[junit4] 2> 178180 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.ComputePlanAction Computed Plan: action=SPLITSHARD&collection=testCollection&shard=shard2&splitMethod=link&splitByPrefix=false
[junit4] 2> 178180 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- reached limit of maxOps=2, stopping.
[junit4] 2> 178180 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.ExecutePlanAction -- processing event: {
[junit4] 2> "id":"85831cd6f74d4dT70g2uijsefksev1ye9h49zvqk",
[junit4] 2> "source":"indexSizeTrigger",
[junit4] 2> "eventTime":37580331791371597,
[junit4] 2> "eventType":"INDEXSIZE",
[junit4] 2> "properties":{
[junit4] 2> "__start__":2,
[junit4] 2> "__compute_diag__":{
[junit4] 2> "estimatedMaxOps":1200,
[junit4] 2> "requestedOperations":2,
[junit4] 2> "opLimit":2,
[junit4] 2> "opLimitReached":true,
[junit4] 2> "maxOperations":1200},
[junit4] 2> "aboveSize":{
[junit4] 2> "testCollection_shard1_replica_n1":"docs=1500, bytes=3082240",
[junit4] 2> "testCollection_shard2_replica_n3":"docs=1500, bytes=3082240"},
[junit4] 2> "belowSize":{},
[junit4] 2> "_enqueue_time_":37580352735144947,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard1"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}},
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard2"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}}]}} with context properties: {operations=[{
[junit4] 2> "class":"org.apache.solr.client.solrj.request.CollectionAdminRequest$SplitShard",
[junit4] 2> "method":"GET",
[junit4] 2> "params.action":"SPLITSHARD",
[junit4] 2> "params.collection":"testCollection",
[junit4] 2> "params.shard":"shard1",
[junit4] 2> "params.splitMethod":"link",
[junit4] 2> "params.splitByPrefix":"false"}, {
[junit4] 2> "class":"org.apache.solr.client.solrj.request.CollectionAdminRequest$SplitShard",
[junit4] 2> "method":"GET",
[junit4] 2> "params.action":"SPLITSHARD",
[junit4] 2> "params.collection":"testCollection",
[junit4] 2> "params.shard":"shard2",
[junit4] 2> "params.splitMethod":"link",
[junit4] 2> "params.splitByPrefix":"false"}], AFTER_ACTION=[compute_plan], BEFORE_ACTION=[compute_plan, execute_plan]}
[junit4] 2> 178180 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.ExecutePlanAction Executing operation: action=SPLITSHARD&collection=testCollection&shard=shard1&splitMethod=link&splitByPrefix=false
[junit4] 2> 178287 INFO (simCloudManagerPool-1345-thread-8) [ ] o.a.s.c.a.c.SplitShardCmd numSubShards set at: 2
[junit4] 2> 178329 DEBUG (simCloudManagerPool-1345-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=9
[junit4] 2> 178330 DEBUG (simCloudManagerPool-1345-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 9
[junit4] 2> 178345 DEBUG (simCloudManagerPool-1345-thread-10) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=10
[junit4] 2> 178407 DEBUG (simCloudManagerPool-1345-thread-10) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 10
[junit4] 2> 178407 DEBUG (simCloudManagerPool-1345-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=11
[junit4] 2> 178408 DEBUG (simCloudManagerPool-1345-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 11
[junit4] 2> 178408 DEBUG (simCloudManagerPool-1345-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider ** no leader in testCollection / shard1_0:{
[junit4] 2> "parent":"shard1",
[junit4] 2> "stateTimestamp":"1636534167784446850",
[junit4] 2> "range":"80000000-bfffffff",
[junit4] 2> "state":"construction",
[junit4] 2> "replicas":{
[junit4] 2> "core_node10":{
[junit4] 2> "core":"testCollection_shard1_0_replica_n9",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1556480,
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "base_url":"https://127.0.0.1:10004/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":0.0014495849609375,
[junit4] 2> "SEARCHER.searcher.numDocs":750},
[junit4] 2> "core_node8":{
[junit4] 2> "core":"testCollection_shard1_0_replica_n7",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1556480,
[junit4] 2> "node_name":"127.0.0.1:10082_solr",
[junit4] 2> "base_url":"https://127.0.0.1:10082/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":0.0014495849609375,
[junit4] 2> "SEARCHER.searcher.numDocs":750}}}
[junit4] 2> 178411 DEBUG (simCloudManagerPool-1345-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider ** no leader in testCollection / shard1_0:{
[junit4] 2> "parent":"shard1",
[junit4] 2> "stateTimestamp":"1636534167784446850",
[junit4] 2> "range":"80000000-bfffffff",
[junit4] 2> "state":"construction",
[junit4] 2> "replicas":{
[junit4] 2> "core_node10":{
[junit4] 2> "core":"testCollection_shard1_0_replica_n9",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1556480,
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "base_url":"https://127.0.0.1:10004/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":0.0014495849609375,
[junit4] 2> "SEARCHER.searcher.numDocs":750},
[junit4] 2> "core_node8":{
[junit4] 2> "core":"testCollection_shard1_0_replica_n7",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1556480,
[junit4] 2> "node_name":"127.0.0.1:10082_solr",
[junit4] 2> "base_url":"https://127.0.0.1:10082/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":0.0014495849609375,
[junit4] 2> "SEARCHER.searcher.numDocs":750}}}
[junit4] 2> 178411 DEBUG (simCloudManagerPool-1345-thread-12) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1_0)
[junit4] 2> 178411 DEBUG (simCloudManagerPool-1345-thread-12) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1_0 (currentVersion=12): {"core_node10":{}}
[junit4] 2> 178412 DEBUG (simCloudManagerPool-1345-thread-11) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=12
[junit4] 2> 178413 DEBUG (simCloudManagerPool-1345-thread-11) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 12
[junit4] 2> 178413 DEBUG (simCloudManagerPool-1345-thread-11) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1_1)
[junit4] 2> 178413 DEBUG (simCloudManagerPool-1345-thread-11) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1_1 (currentVersion=13): {"core_node12":{}}
[junit4] 2> 178413 DEBUG (simCloudManagerPool-1345-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=13
[junit4] 2> 178413 DEBUG (simCloudManagerPool-1345-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 13
[junit4] 2> 178436 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.ExecutePlanAction Executing operation: action=SPLITSHARD&collection=testCollection&shard=shard2&splitMethod=link&splitByPrefix=false
[junit4] 2> 178442 DEBUG (simCloudManagerPool-1345-thread-15) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=14
[junit4] 2> 178443 DEBUG (simCloudManagerPool-1345-thread-15) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 14
[junit4] 2> 178839 INFO (simCloudManagerPool-1345-thread-15) [ ] o.a.s.c.a.c.SplitShardCmd numSubShards set at: 2
[junit4] 2> 178880 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 8. WaitEvent trigger=indexSizeTrigger&wait=60
[junit4] 2> 178880 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario WaitEvent trigger=indexSizeTrigger&wait=60
[junit4] 2> 178881 DEBUG (simCloudManagerPool-1345-thread-15) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=15
[junit4] 2> 178882 DEBUG (simCloudManagerPool-1345-thread-15) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 15
[junit4] 2> 178885 DEBUG (simCloudManagerPool-1345-thread-17) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=16
[junit4] 2> 178900 DEBUG (simCloudManagerPool-1345-thread-17) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 16
[junit4] 2> 178906 DEBUG (simCloudManagerPool-1345-thread-18) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=17
[junit4] 2> 178906 DEBUG (simCloudManagerPool-1345-thread-18) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 17
[junit4] 2> 178906 DEBUG (simCloudManagerPool-1345-thread-18) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard2_1)
[junit4] 2> 178906 DEBUG (simCloudManagerPool-1345-thread-18) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard2_1 (currentVersion=18): {"core_node22":{}}
[junit4] 2> 178906 DEBUG (MetricsHistoryHandler-1349-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=18
[junit4] 2> 178906 DEBUG (MetricsHistoryHandler-1349-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 18
[junit4] 2> 178914 DEBUG (simCloudManagerPool-1345-thread-20) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=19
[junit4] 2> 178914 DEBUG (simCloudManagerPool-1345-thread-20) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 19
[junit4] 2> 178914 DEBUG (simCloudManagerPool-1345-thread-15) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=20
[junit4] 2> 178914 DEBUG (simCloudManagerPool-1345-thread-15) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 20
[junit4] 2> 178914 DEBUG (simCloudManagerPool-1345-thread-15) [ ] o.a.s.c.a.s.SimClusterStateProvider ** no leader in testCollection / shard2_0:{
[junit4] 2> "parent":"shard2",
[junit4] 2> "stateTimestamp":"1636534195401350750",
[junit4] 2> "range":"0-3fffffff",
[junit4] 2> "state":"construction",
[junit4] 2> "replicas":{
[junit4] 2> "core_node18":{
[junit4] 2> "core":"testCollection_shard2_0_replica_n17",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1556480,
[junit4] 2> "node_name":"127.0.0.1:10082_solr",
[junit4] 2> "base_url":"https://127.0.0.1:10082/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":0.0014495849609375,
[junit4] 2> "SEARCHER.searcher.numDocs":750},
[junit4] 2> "core_node20":{
[junit4] 2> "core":"testCollection_shard2_0_replica_n19",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1556480,
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "base_url":"https://127.0.0.1:10004/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":0.0014495849609375,
[junit4] 2> "SEARCHER.searcher.numDocs":750}}}
[junit4] 2> 178917 DEBUG (simCloudManagerPool-1345-thread-15) [ ] o.a.s.c.a.s.SimClusterStateProvider ** no leader in testCollection / shard2_0:{
[junit4] 2> "parent":"shard2",
[junit4] 2> "stateTimestamp":"1636534195401350750",
[junit4] 2> "range":"0-3fffffff",
[junit4] 2> "state":"construction",
[junit4] 2> "replicas":{
[junit4] 2> "core_node18":{
[junit4] 2> "core":"testCollection_shard2_0_replica_n17",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1556480,
[junit4] 2> "node_name":"127.0.0.1:10082_solr",
[junit4] 2> "base_url":"https://127.0.0.1:10082/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":0.0014495849609375,
[junit4] 2> "SEARCHER.searcher.numDocs":750},
[junit4] 2> "core_node20":{
[junit4] 2> "core":"testCollection_shard2_0_replica_n19",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1556480,
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "base_url":"https://127.0.0.1:10004/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":0.0014495849609375,
[junit4] 2> "SEARCHER.searcher.numDocs":750}}}
[junit4] 2> 178919 DEBUG (simCloudManagerPool-1345-thread-15) [ ] o.a.s.c.a.s.SimClusterStateProvider ** no leader in testCollection / shard2_0:{
[junit4] 2> "parent":"shard2",
[junit4] 2> "stateTimestamp":"1636534195401350750",
[junit4] 2> "range":"0-3fffffff",
[junit4] 2> "state":"construction",
[junit4] 2> "replicas":{
[junit4] 2> "core_node18":{
[junit4] 2> "core":"testCollection_shard2_0_replica_n17",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1556480,
[junit4] 2> "node_name":"127.0.0.1:10082_solr",
[junit4] 2> "base_url":"https://127.0.0.1:10082/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":0.0014495849609375,
[junit4] 2> "SEARCHER.searcher.numDocs":750},
[junit4] 2> "core_node20":{
[junit4] 2> "core":"testCollection_shard2_0_replica_n19",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1556480,
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "base_url":"https://127.0.0.1:10004/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":0.0014495849609375,
[junit4] 2> "SEARCHER.searcher.numDocs":750}}}
[junit4] 2> 178920 DEBUG (simCloudManagerPool-1345-thread-21) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard2_0)
[junit4] 2> 178920 DEBUG (simCloudManagerPool-1345-thread-21) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard2_0 (currentVersion=21): {"core_node18":{}}
[junit4] 2> 178921 DEBUG (simCloudManagerPool-1345-thread-15) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=21
[junit4] 2> 178921 DEBUG (simCloudManagerPool-1345-thread-15) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 21
[junit4] 2> 178926 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=22
[junit4] 2> 178926 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 22
[junit4] 2> 178926 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"85831cd6f74d4dT70g2uijsefksev1ye9h49zvqk",
[junit4] 2> "source":"indexSizeTrigger",
[junit4] 2> "eventTime":37580331791371597,
[junit4] 2> "eventType":"INDEXSIZE",
[junit4] 2> "properties":{
[junit4] 2> "__start__":2,
[junit4] 2> "__compute_diag__":{
[junit4] 2> "estimatedMaxOps":1200,
[junit4] 2> "requestedOperations":2,
[junit4] 2> "opLimit":2,
[junit4] 2> "opLimitReached":true,
[junit4] 2> "maxOperations":1200},
[junit4] 2> "aboveSize":{
[junit4] 2> "testCollection_shard1_replica_n1":"docs=1500, bytes=3082240",
[junit4] 2> "testCollection_shard2_replica_n3":"docs=1500, bytes=3082240"},
[junit4] 2> "belowSize":{},
[junit4] 2> "_enqueue_time_":37580352735144947,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard1"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}},
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard2"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}}]}}
[junit4] 2> 178927 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 9. Assert condition=not_null&key=_trigger_event_indexSizeTrigger
[junit4] 2> 178927 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario Assert condition=not_null&key=_trigger_event_indexSizeTrigger
[junit4] 2> 178928 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 10. Assert condition=equals&key=_trigger_event_indexSizeTrigger/eventType&expected=INDEXSIZE
[junit4] 2> 178928 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: .scheduled_maintenance after 100ms
[junit4] 2> 178928 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: .auto_add_replicas after 100ms
[junit4] 2> 178928 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: indexSizeTrigger after 100ms
[junit4] 2> 178928 DEBUG (AutoscalingActionExecutor-1347-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 39085 ms for event id=85831cd6f74d4dT70g2uijsefksev1ye9h49zvqk
[junit4] 2> 178928 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario Assert condition=equals&key=_trigger_event_indexSizeTrigger/eventType&expected=INDEXSIZE
[junit4] 2> 178928 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 11. Assert condition=equals&key=_trigger_event_indexSizeTrigger/properties/requestedOps[0]/action&expected=SPLITSHARD
[junit4] 2> 178928 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario Assert condition=equals&key=_trigger_event_indexSizeTrigger/properties/requestedOps[0]/action&expected=SPLITSHARD
[junit4] 2> 178929 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 12. WaitCollection collection=testCollection&shards=6&withInactive=true&requireLeaders=false&replicas=2
[junit4] 2> 178929 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario WaitCollection collection=testCollection&shards=6&withInactive=true&requireLeaders=false&replicas=2
[junit4] 2> 178984 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 178984 DEBUG (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 178984 DEBUG (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 178984 DEBUG (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 178984 DEBUG (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 178984 DEBUG (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 178984 DEBUG (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 178985 INFO (TEST-TestSimScenario.testIndexing-seed#[A33F0FB252633F13]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testIndexing
[junit4] 2> 179003 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testSuggestions
[junit4] 2> 179004 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 1. CreateCluster numNodes=2
[junit4] 2> 179004 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario CreateCluster numNodes=2
[junit4] 2> 179052 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10104_solr
[junit4] 2> 179055 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 179056 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 179061 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 179061 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 179077 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10104_solr]
[junit4] 2> 179080 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=0
[junit4] 2> 179080 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 0
[junit4] 2> 179080 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 179080 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 2. RunSolrRequest path=/admin/collections&action=CREATE&autoAddReplicas=true&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=2
[junit4] 2> 179080 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collections&action=CREATE&autoAddReplicas=true&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=2
[junit4] 2> 179080 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 179081 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 179081 DEBUG (ScheduledTrigger-1352-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 1
[junit4] 2> 179081 DEBUG (simCloudManagerPool-1351-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- simCreateCollection testCollection, currentVersion=1
[junit4] 2> 179081 DEBUG (simCloudManagerPool-1351-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=1
[junit4] 2> 179081 DEBUG (simCloudManagerPool-1351-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 1
[junit4] 2> 179091 DEBUG (simCloudManagerPool-1351-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=2
[junit4] 2> 179091 DEBUG (simCloudManagerPool-1351-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 2
[junit4] 2> 179118 DEBUG (simCloudManagerPool-1351-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=3
[junit4] 2> 179118 DEBUG (simCloudManagerPool-1351-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 3
[junit4] 2> 179118 DEBUG (simCloudManagerPool-1351-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1)
[junit4] 2> 179118 DEBUG (simCloudManagerPool-1351-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1 (currentVersion=4): {"core_node1":{}}
[junit4] 2> 179127 DEBUG (ScheduledTrigger-1352-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 179142 DEBUG (simCloudManagerPool-1351-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=4
[junit4] 2> 179142 DEBUG (simCloudManagerPool-1351-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 4
[junit4] 2> 179142 DEBUG (simCloudManagerPool-1351-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard2)
[junit4] 2> 179142 DEBUG (simCloudManagerPool-1351-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard2 (currentVersion=5): {"core_node3":{}}
[junit4] 2> 179143 DEBUG (simCloudManagerPool-1351-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- finished createCollection testCollection, currentVersion=5
[junit4] 2> 179143 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 3. WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 179143 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 179148 DEBUG (ScheduledTrigger-1352-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 179153 DEBUG (simCloudManagerPool-1351-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=5
[junit4] 2> 179153 DEBUG (simCloudManagerPool-1351-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 5
[junit4] 2> 179164 DEBUG (simCloudManagerPool-1351-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=6
[junit4] 2> 179164 DEBUG (simCloudManagerPool-1351-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 6
[junit4] 2> 179164 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=7
[junit4] 2> 179164 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 7
[junit4] 2> 179164 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 4. CtxSet key=myNode&value=${_random_node_}
[junit4] 2> 179164 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario CtxSet key=myNode&value=127.0.0.1:10105_solr
[junit4] 2> 179164 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 5. RunSolrRequest path=/admin/collections&action=ADDREPLICA&collection=testCollection&shard=shard1&node=${myNode}
[junit4] 2> 179165 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collections&action=ADDREPLICA&collection=testCollection&shard=shard1&node=127.0.0.1:10105_solr
[junit4] 2> 179168 DEBUG (ScheduledTrigger-1352-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 179187 INFO (simCloudManagerPool-1351-thread-6) [ ] o.a.s.c.a.c.AddReplicaCmd Node Identified 127.0.0.1:10105_solr for creating new replica of shard shard1 for collection testCollection
[junit4] 2> 179187 INFO (simCloudManagerPool-1351-thread-6) [ ] o.a.s.c.a.c.AddReplicaCmd Returning CreateReplica command.
[junit4] 2> 179188 DEBUG (ScheduledTrigger-1352-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 179198 DEBUG (simCloudManagerPool-1351-thread-6) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=8
[junit4] 2> 179198 DEBUG (simCloudManagerPool-1351-thread-6) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 8
[junit4] 2> 179198 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 6. RunSolrRequest path=/admin/collections&action=ADDREPLICA&collection=testCollection&shard=shard1&node=${myNode}
[junit4] 2> 179198 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collections&action=ADDREPLICA&collection=testCollection&shard=shard1&node=127.0.0.1:10105_solr
[junit4] 2> 179199 DEBUG (simCloudManagerPool-1351-thread-7) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=9
[junit4] 2> 179200 DEBUG (simCloudManagerPool-1351-thread-7) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 9
[junit4] 2> 179201 INFO (simCloudManagerPool-1351-thread-7) [ ] o.a.s.c.a.c.AddReplicaCmd Node Identified 127.0.0.1:10105_solr for creating new replica of shard shard1 for collection testCollection
[junit4] 2> 179201 INFO (simCloudManagerPool-1351-thread-7) [ ] o.a.s.c.a.c.AddReplicaCmd Returning CreateReplica command.
[junit4] 2> 179208 DEBUG (ScheduledTrigger-1352-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 179211 DEBUG (simCloudManagerPool-1351-thread-7) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=10
[junit4] 2> 179211 DEBUG (simCloudManagerPool-1351-thread-7) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 10
[junit4] 2> 179211 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 7. LoopOp iterations=${iterative}
[junit4] 2> 179211 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario LoopOp iterations=0
[junit4] 2> 179211 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario 8. LoopOp iterations=${justCalc}
[junit4] 2> 179211 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario LoopOp iterations=1
[junit4] 2> 179211 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario * iter 1 :
[junit4] 2> 179211 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario - CalculateSuggestions )
[junit4] 2> 179213 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=11
[junit4] 2> 179213 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 11
[junit4] 2> 179228 DEBUG (ScheduledTrigger-1352-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 179231 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario - 1 suggestions
[junit4] 2> 179231 INFO (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SimScenario - SaveSnapshot path=/home/jenkins/jenkins-slave/workspace/Lucene/Lucene-Solr-Tests-8.11/solr/build/solr-core/test/J0/temp/solr.cloud.autoscaling.sim.TestSimScenario_A33F0FB252633F13-001/tempDir-001/snapshot/0)
[junit4] 2> 179240 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.s.SnapshotDistribStateManager - copying 22 resources from SimDistribStateManager
[j
[...truncated too long message...]
Exception
[junit4] 2> at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:404) ~[?:1.8.0_291]
[junit4] 2> at java.util.concurrent.FutureTask.get(FutureTask.java:204) ~[?:1.8.0_291]
[junit4] 2> at org.apache.solr.cloud.autoscaling.sim.SimCloudManager.request(SimCloudManager.java:735) ~[java/:?]
[junit4] 2> ... 9 more
[junit4] 2> 185526 WARN (AutoscalingActionExecutor-1365-thread-1) [ ] o.a.s.c.a.SystemLogListener Exception sending event. Collection: .system, event: {
[junit4] 2> "id":"858369fbc1fe4bT70g2uijsefksev1ye9h49zvqo",
[junit4] 2> "source":".auto_add_replicas",
[junit4] 2> "eventTime":37580663121116747,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[37580663121116747],
[junit4] 2> "__compute_diag__":{
[junit4] 2> "noSuggestionsStopAfter":2,
[junit4] 2> "estimatedMaxOps":12,
[junit4] 2> "requestedOperations":-1,
[junit4] 2> "opLimit":12,
[junit4] 2> "maxOperations":12},
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":37580673409880547,
[junit4] 2> "nodeNames":["127.0.0.1:10109_solr"]}}, exception: java.io.IOException: already closed
[junit4] 2> 185526 WARN (AutoscalingActionExecutor-1365-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Exception executing actions
[junit4] 2> => org.apache.solr.cloud.autoscaling.TriggerActionException: Error processing action for trigger event: {
[junit4] 2> "id":"858369fbc1fe4bT70g2uijsefksev1ye9h49zvqo",
[junit4] 2> org.apache.solr.cloud.autoscaling.TriggerActionException: Error processing action for trigger event: {
[junit4] 2> "id":"858369fbc1fe4bT70g2uijsefksev1ye9h49zvqo",
[junit4] 2> "source":".auto_add_replicas",
[junit4] 2> "eventTime":37580663121116747,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[37580663121116747],
[junit4] 2> "__compute_diag__":{
[junit4] 2> "noSuggestionsStopAfter":2,
[junit4] 2> "estimatedMaxOps":12,
[junit4] 2> "requestedOperations":-1,
[junit4] 2> "opLimit":12,
[junit4] 2> "maxOperations":12},
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":37580673409880547,
[junit4] 2> "nodeNames":["127.0.0.1:10109_solr"]}}
[junit4] 2> at org.apache.solr.cloud.autoscaling.ScheduledTriggers.lambda$null$3(ScheduledTriggers.java:334) ~[java/:?]
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_291]
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_291]
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:218) ~[java/:?]
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_291]
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_291]
[junit4] 2> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_291]
[junit4] 2> Caused by: org.apache.solr.common.SolrException: Unexpected exception while processing event: {
[junit4] 2> "id":"858369fbc1fe4bT70g2uijsefksev1ye9h49zvqo",
[junit4] 2> "source":".auto_add_replicas",
[junit4] 2> "eventTime":37580663121116747,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[37580663121116747],
[junit4] 2> "__compute_diag__":{
[junit4] 2> "noSuggestionsStopAfter":2,
[junit4] 2> "estimatedMaxOps":12,
[junit4] 2> "requestedOperations":-1,
[junit4] 2> "opLimit":12,
[junit4] 2> "maxOperations":12},
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":37580673409880547,
[junit4] 2> "nodeNames":["127.0.0.1:10109_solr"]}}
[junit4] 2> at org.apache.solr.cloud.autoscaling.ExecutePlanAction.process(ExecutePlanAction.java:188) ~[java/:?]
[junit4] 2> at org.apache.solr.cloud.autoscaling.ScheduledTriggers.lambda$null$3(ScheduledTriggers.java:331) ~[java/:?]
[junit4] 2> ... 6 more
[junit4] 2> Caused by: org.apache.solr.common.SolrException: Unexpected exception executing operation: action=MOVEREPLICA&async=.auto_add_replicas/858369fbc1fe4bT70g2uijsefksev1ye9h49zvqo/1&waitForFinalState=true&collection=testCollection&targetNode=127.0.0.1:10108_solr&inPlaceMove=true&replica=core_node3
[junit4] 2> at org.apache.solr.cloud.autoscaling.ExecutePlanAction.process(ExecutePlanAction.java:178) ~[java/:?]
[junit4] 2> at org.apache.solr.cloud.autoscaling.ScheduledTriggers.lambda$null$3(ScheduledTriggers.java:331) ~[java/:?]
[junit4] 2> ... 6 more
[junit4] 2> Caused by: java.io.IOException: java.lang.InterruptedException
[junit4] 2> at org.apache.solr.cloud.autoscaling.sim.SimCloudManager.request(SimCloudManager.java:737) ~[java/:?]
[junit4] 2> at org.apache.solr.cloud.autoscaling.ExecutePlanAction.waitForTaskToFinish(ExecutePlanAction.java:200) ~[java/:?]
[junit4] 2> at org.apache.solr.cloud.autoscaling.ExecutePlanAction.process(ExecutePlanAction.java:120) ~[java/:?]
[junit4] 2> at org.apache.solr.cloud.autoscaling.ScheduledTriggers.lambda$null$3(ScheduledTriggers.java:331) ~[java/:?]
[junit4] 2> ... 6 more
[junit4] 2> Caused by: java.lang.InterruptedException
[junit4] 2> at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:404) ~[?:1.8.0_291]
[junit4] 2> at java.util.concurrent.FutureTask.get(FutureTask.java:204) ~[?:1.8.0_291]
[junit4] 2> at org.apache.solr.cloud.autoscaling.sim.SimCloudManager.request(SimCloudManager.java:735) ~[java/:?]
[junit4] 2> at org.apache.solr.cloud.autoscaling.ExecutePlanAction.waitForTaskToFinish(ExecutePlanAction.java:200) ~[java/:?]
[junit4] 2> at org.apache.solr.cloud.autoscaling.ExecutePlanAction.process(ExecutePlanAction.java:120) ~[java/:?]
[junit4] 2> at org.apache.solr.cloud.autoscaling.ScheduledTriggers.lambda$null$3(ScheduledTriggers.java:331) ~[java/:?]
[junit4] 2> ... 6 more
[junit4] 2> 185531 DEBUG (AutoscalingActionExecutor-1365-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 49499 ms for event id=858369fbc1fe4bT70g2uijsefksev1ye9h49zvqo
[junit4] 2> 185531 DEBUG (TEST-TestSimScenario.testAutoAddReplicas-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 185531 DEBUG (TEST-TestSimScenario.testAutoAddReplicas-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 185531 DEBUG (TEST-TestSimScenario.testAutoAddReplicas-seed#[A33F0FB252633F13]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 185532 INFO (TEST-TestSimScenario.testAutoAddReplicas-seed#[A33F0FB252633F13]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testAutoAddReplicas
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestSimScenario -Dtests.method=testAutoAddReplicas -Dtests.seed=A33F0FB252633F13 -Dtests.multiplier=2 -Dtests.slow=true -Dtests.locale=en-IN -Dtests.timezone=America/Grand_Turk -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] ERROR 1.63s J0 | TestSimScenario.testAutoAddReplicas <<<
[junit4] > Throwable #1: java.io.IOException: Timed out waiting for trigger .auto_add_replicas to fire after simulated 60s (real 1200ms).
[junit4] > at __randomizedtesting.SeedInfo.seed([A33F0FB252633F13:2A9FFCCE2668F33A]:0)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.SimScenario$SimWaitListener.wait(SimScenario.java:705)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.SimScenario$WaitEvent.execute(SimScenario.java:771)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.SimScenario.run(SimScenario.java:1119)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.TestSimScenario.testAutoAddReplicas(TestSimScenario.java:57)
[junit4] > at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 185534 INFO (SUITE-TestSimScenario-seed#[A33F0FB252633F13]-worker) [ ] o.a.s.u.ErrorLogMuter Closing ErrorLogMuter-regex-25 after mutting 0 log messages
[junit4] 2> 185534 INFO (SUITE-TestSimScenario-seed#[A33F0FB252633F13]-worker) [ ] o.a.s.u.ErrorLogMuter Creating ErrorLogMuter-regex-26 for ERROR logs matching regex: ignore_exception
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/jenkins-slave/workspace/Lucene/Lucene-Solr-Tests-8.11/solr/build/solr-core/test/J0/temp/solr.cloud.autoscaling.sim.TestSimScenario_A33F0FB252633F13-001
[junit4] 2> NOTE: test params are: codec=FastCompressingStoredFieldsData(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=FAST, chunkSize=92, maxDocsPerChunk=2, blockShift=5), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=FAST, chunkSize=92, maxDocsPerChunk=2, blockSize=5)), sim=Asserting(RandomSimilarity(queryNorm=false): {}), locale=en-IN, timezone=America/Grand_Turk
[junit4] 2> NOTE: Linux 5.4.0-45-generic amd64/Oracle Corporation 1.8.0_291 (64-bit)/cpus=4,threads=1,free=389181416,total=465043456
[junit4] 2> NOTE: All tests run in this JVM: [DateFieldTest, TestSchemaVersionResource, CreateCollectionCleanupTest, TestRemoteStreaming, OverseerTest, ClusterStateMockUtilTest, CdcrReplicationHandlerTest, TestLRUStatsCache, ShardRoutingCustomTest, FileBasedSpellCheckerTest, TestOrdValues, TestFieldCacheReopen, AnalyticsMergeStrategyTest, TestMacroExpander, TestSimScenario]
[junit4] Completed [44/952 (1!)] on J0 in 9.53s, 4 tests, 1 error <<< FAILURES!
[...truncated 57373 lines...]