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 2020/10/07 07:05:50 UTC
[JENKINS] Lucene » Lucene-Solr-Tests-8.x - Build # 554 - Unstable!
Build: https://ci-builds.apache.org/job/Lucene/job/Lucene-Solr-Tests-8.x/554/
1 tests failed.
FAILED: org.apache.solr.cloud.autoscaling.sim.TestSimTriggerIntegration.testEventQueue
Error Message:
OverseerTriggerThread never caught up to the latest znodeVersion
Stack Trace:
java.util.concurrent.TimeoutException: OverseerTriggerThread never caught up to the latest znodeVersion
at __randomizedtesting.SeedInfo.seed([47AC6AC11037A35:CDCF84021864BCC0]:0)
at org.apache.solr.util.TimeOut.waitFor(TimeOut.java:66)
at org.apache.solr.cloud.autoscaling.sim.SimSolrCloudTestCase.assertAutoscalingUpdateComplete(SimSolrCloudTestCase.java:98)
at org.apache.solr.cloud.autoscaling.sim.TestSimTriggerIntegration.testEventQueue(TestSimTriggerIntegration.java:750)
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.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:947)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:832)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:883)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:894)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
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 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 14033 lines...]
[junit4] Suite: org.apache.solr.cloud.autoscaling.sim.TestSimTriggerIntegration
[junit4] 2> 681772 INFO (SUITE-TestSimTriggerIntegration-seed#[47AC6AC11037A35]-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.x/solr/server/solr/configsets/_default/conf'
[junit4] 2> 681773 INFO (SUITE-TestSimTriggerIntegration-seed#[47AC6AC11037A35]-worker) [ ] o.a.s.SolrTestCaseJ4 Created dataDir: /home/jenkins/jenkins-slave/workspace/Lucene/Lucene-Solr-Tests-8.x/solr/build/solr-core/test/J0/temp/solr.cloud.autoscaling.sim.TestSimTriggerIntegration_47AC6AC11037A35-001/data-dir-58-001
[junit4] 2> 681773 WARN (SUITE-TestSimTriggerIntegration-seed#[47AC6AC11037A35]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=95 numCloses=95
[junit4] 2> 681773 INFO (SUITE-TestSimTriggerIntegration-seed#[47AC6AC11037A35]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=false
[junit4] 2> 681775 INFO (SUITE-TestSimTriggerIntegration-seed#[47AC6AC11037A35]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, value=NaN, ssl=NaN, clientAuth=NaN)
[junit4] 2> 681775 INFO (SUITE-TestSimTriggerIntegration-seed#[47AC6AC11037A35]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> 681786 INFO (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testSearchRate
[junit4] 2> 681803 DEBUG (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10004_solr
[junit4] 2> 681803 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 681803 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 681803 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 681803 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 681823 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10004_solr]
[junit4] 2> 681834 DEBUG (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=0
[junit4] 2> 681835 DEBUG (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 0
[junit4] 2> 681835 INFO (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 681845 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 1
[junit4] 2> 681865 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 681865 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 681884 DEBUG (ScheduledTrigger-7284-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> 681884 DEBUG (simCloudManagerPool-7283-thread-2) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 681884 DEBUG (simCloudManagerPool-7283-thread-2) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 681891 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 2
[junit4] 2> 681894 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 681894 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 2
[junit4] 2> 681894 DEBUG (simCloudManagerPool-7283-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider -- simCreateCollection collection1, currentVersion=1
[junit4] 2> 681894 DEBUG (simCloudManagerPool-7283-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=1
[junit4] 2> 681896 DEBUG (simCloudManagerPool-7283-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 1
[junit4] 2> 681904 DEBUG (ScheduledTrigger-7284-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> 681909 DEBUG (simCloudManagerPool-7283-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=2
[junit4] 2> 681909 DEBUG (simCloudManagerPool-7283-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 2
[junit4] 2> 681924 DEBUG (ScheduledTrigger-7284-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> 681934 DEBUG (simCloudManagerPool-7283-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=3
[junit4] 2> 681935 DEBUG (simCloudManagerPool-7283-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 3
[junit4] 2> 681935 DEBUG (simCloudManagerPool-7283-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (collection1 / shard1)
[junit4] 2> 681935 DEBUG (simCloudManagerPool-7283-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for collection1 / shard1 (currentVersion=4): {"core_node1":{
[junit4] 2> "core":"collection1_shard1_replica_n1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "node_name":"127.0.0.1:10005_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}
[junit4] 2> 681935 DEBUG (simCloudManagerPool-7283-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider -- finished createCollection collection1, currentVersion=4
[junit4] 2> 681935 DEBUG (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=4
[junit4] 2> 681935 DEBUG (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 4
[junit4] 2> 681945 DEBUG (ScheduledTrigger-7284-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> 681946 DEBUG (simCloudManagerPool-7283-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=5
[junit4] 2> 681946 DEBUG (simCloudManagerPool-7283-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 5
[junit4] 2> 681946 DEBUG (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=6
[junit4] 2> 682140 DEBUG (ScheduledTrigger-7284-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> 682141 DEBUG (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 6
[junit4] 2> 682159 DEBUG (simCloudManagerPool-7283-thread-6) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 682159 DEBUG (simCloudManagerPool-7283-thread-6) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 3
[junit4] 2> 682159 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 3
[junit4] 2> 682160 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 682160 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 3, lastZnodeVersion 3
[junit4] 2> 682160 DEBUG (ScheduledTrigger-7284-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> 682170 DEBUG (simCloudManagerPool-7283-thread-7) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 682170 DEBUG (ScheduledTrigger-7284-thread-2) [ ] o.a.s.c.a.SearchRateTrigger ### rates for node 127.0.0.1:10004_solr
[junit4] 2> 682170 DEBUG (simCloudManagerPool-7283-thread-7) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 4
[junit4] 2> 682171 DEBUG (ScheduledTrigger-7284-thread-2) [ ] o.a.s.c.a.SearchRateTrigger ### rates for node 127.0.0.1:10005_solr
[junit4] 2> 682175 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 4
[junit4] 2> 682175 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 682175 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 4, lastZnodeVersion 4
[junit4] 2> 682180 DEBUG (ScheduledTrigger-7284-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> 682201 DEBUG (ScheduledTrigger-7284-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> 682206 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ### rates for node 127.0.0.1:10004_solr
[junit4] 2> 682206 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ### metrics:solr.core.collection1.shard1.replica_n2:QUERY./select.requestTimes:1minRate 250
[junit4] 2> 682207 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ### rates for node 127.0.0.1:10005_solr
[junit4] 2> 682207 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ### metrics:solr.core.collection1.shard1.replica_n1:QUERY./select.requestTimes:1minRate 250
[junit4] 2> 682207 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ## Collection: collection1
[junit4] 2> 682207 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ## - shard1
[junit4] 2> 682207 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ## collection1_shard1_replica_n2 250.0
[junit4] 2> 682208 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ## collection1_shard1_replica_n1 250.0
[junit4] 2> 682210 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger -- collection1.shard1: totalShardRate=500.0, shardRate=250.0
[junit4] 2> 682221 DEBUG (ScheduledTrigger-7284-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> 682231 DEBUG (ScheduledTrigger-7284-thread-2) [ ] o.a.s.c.a.SearchRateTrigger ### rates for node 127.0.0.1:10004_solr
[junit4] 2> 682231 DEBUG (ScheduledTrigger-7284-thread-2) [ ] o.a.s.c.a.SearchRateTrigger ### metrics:solr.core.collection1.shard1.replica_n2:QUERY./select.requestTimes:1minRate 250
[junit4] 2> 682231 DEBUG (ScheduledTrigger-7284-thread-2) [ ] o.a.s.c.a.SearchRateTrigger ### rates for node 127.0.0.1:10005_solr
[junit4] 2> 682231 DEBUG (ScheduledTrigger-7284-thread-2) [ ] o.a.s.c.a.SearchRateTrigger ### metrics:solr.core.collection1.shard1.replica_n1:QUERY./select.requestTimes:1minRate 250
[junit4] 2> 682231 DEBUG (ScheduledTrigger-7284-thread-2) [ ] o.a.s.c.a.SearchRateTrigger ## Collection: collection1
[junit4] 2> 682231 DEBUG (ScheduledTrigger-7284-thread-2) [ ] o.a.s.c.a.SearchRateTrigger ## - shard1
[junit4] 2> 682231 DEBUG (ScheduledTrigger-7284-thread-2) [ ] o.a.s.c.a.SearchRateTrigger ## collection1_shard1_replica_n2 250.0
[junit4] 2> 682231 DEBUG (ScheduledTrigger-7284-thread-2) [ ] o.a.s.c.a.SearchRateTrigger ## collection1_shard1_replica_n1 250.0
[junit4] 2> 682231 DEBUG (ScheduledTrigger-7284-thread-2) [ ] o.a.s.c.a.SearchRateTrigger -- collection1.shard1: totalShardRate=500.0, shardRate=250.0
[junit4] 2> 682300 DEBUG (ScheduledTrigger-7284-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> 682300 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ### rates for node 127.0.0.1:10004_solr
[junit4] 2> 682300 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ### metrics:solr.core.collection1.shard1.replica_n2:QUERY./select.requestTimes:1minRate 250
[junit4] 2> 682300 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ### rates for node 127.0.0.1:10005_solr
[junit4] 2> 682300 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ### metrics:solr.core.collection1.shard1.replica_n1:QUERY./select.requestTimes:1minRate 250
[junit4] 2> 682300 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ## Collection: collection1
[junit4] 2> 682300 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ## - shard1
[junit4] 2> 682300 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ## collection1_shard1_replica_n2 250.0
[junit4] 2> 682300 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger ## collection1_shard1_replica_n1 250.0
[junit4] 2> 682300 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SearchRateTrigger -- collection1.shard1: totalShardRate=500.0, shardRate=250.0
[junit4] 2> 682305 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"b0a64abdb9044T2s87l1cbzkfch2q3tkyudt1r9",
[junit4] 2> "source":"search_rate_trigger",
[junit4] 2> "eventTime":3107652240117828,
[junit4] 2> "eventType":"SEARCHRATE",
[junit4] 2> "properties":{
[junit4] 2> "hotReplicas":[
[junit4] 2> {"core_node2":{
[junit4] 2> "core":"collection1_shard1_replica_n2",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "rate":250.0,
[junit4] 2> "state":"active",
[junit4] 2> "QUERY./select.requestTimes:1minRate":250,
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}},
[junit4] 2> {"core_node1":{
[junit4] 2> "core":"collection1_shard1_replica_n1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "node_name":"127.0.0.1:10005_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "rate":250.0,
[junit4] 2> "state":"active",
[junit4] 2> "QUERY./select.requestTimes:1minRate":250,
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}],
[junit4] 2> "coldNodes":{},
[junit4] 2> "coldShards":{},
[junit4] 2> "coldReplicas":[],
[junit4] 2> "violationType":["hotShards"],
[junit4] 2> "coldCollections":{},
[junit4] 2> "hotShards":{"collection1":{"shard1":250.0}},
[junit4] 2> "hotCollections":{"collection1":500.0},
[junit4] 2> "hotNodes":{
[junit4] 2> "127.0.0.1:10004_solr":250.0,
[junit4] 2> "127.0.0.1:10005_solr":250.0},
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}},
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}},
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}}]}}
[junit4] 2> 682306 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [.auto_add_replicas, search_rate_trigger]
[junit4] 2> 682306 DEBUG (ScheduledTrigger-7284-thread-1) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"b0a64abdb9044T2s87l1cbzkfch2q3tkyudt1r9",
[junit4] 2> "source":"search_rate_trigger",
[junit4] 2> "eventTime":3107652240117828,
[junit4] 2> "eventType":"SEARCHRATE",
[junit4] 2> "properties":{
[junit4] 2> "hotReplicas":[
[junit4] 2> {"core_node2":{
[junit4] 2> "core":"collection1_shard1_replica_n2",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "rate":250.0,
[junit4] 2> "state":"active",
[junit4] 2> "QUERY./select.requestTimes:1minRate":250,
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}},
[junit4] 2> {"core_node1":{
[junit4] 2> "core":"collection1_shard1_replica_n1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "node_name":"127.0.0.1:10005_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "rate":250.0,
[junit4] 2> "state":"active",
[junit4] 2> "QUERY./select.requestTimes:1minRate":250,
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}],
[junit4] 2> "coldNodes":{},
[junit4] 2> "coldShards":{},
[junit4] 2> "coldReplicas":[],
[junit4] 2> "violationType":["hotShards"],
[junit4] 2> "coldCollections":{},
[junit4] 2> "hotShards":{"collection1":{"shard1":250.0}},
[junit4] 2> "hotCollections":{"collection1":500.0},
[junit4] 2> "hotNodes":{
[junit4] 2> "127.0.0.1:10004_solr":250.0,
[junit4] 2> "127.0.0.1:10005_solr":250.0},
[junit4] 2> "_enqueue_time_":3107657165661678,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}},
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}},
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}}]}}
[junit4] 2> 682310 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"b0a64abdb9044T2s87l1cbzkfch2q3tkyudt1r9",
[junit4] 2> "source":"search_rate_trigger",
[junit4] 2> "eventTime":3107652240117828,
[junit4] 2> "eventType":"SEARCHRATE",
[junit4] 2> "properties":{
[junit4] 2> "hotReplicas":[
[junit4] 2> {"core_node2":{
[junit4] 2> "core":"collection1_shard1_replica_n2",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "rate":250.0,
[junit4] 2> "state":"active",
[junit4] 2> "QUERY./select.requestTimes:1minRate":250,
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}},
[junit4] 2> {"core_node1":{
[junit4] 2> "core":"collection1_shard1_replica_n1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "node_name":"127.0.0.1:10005_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "rate":250.0,
[junit4] 2> "state":"active",
[junit4] 2> "QUERY./select.requestTimes:1minRate":250,
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}],
[junit4] 2> "coldNodes":{},
[junit4] 2> "coldShards":{},
[junit4] 2> "coldReplicas":[],
[junit4] 2> "violationType":["hotShards"],
[junit4] 2> "coldCollections":{},
[junit4] 2> "hotShards":{"collection1":{"shard1":250.0}},
[junit4] 2> "hotCollections":{"collection1":500.0},
[junit4] 2> "hotNodes":{
[junit4] 2> "127.0.0.1:10004_solr":250.0,
[junit4] 2> "127.0.0.1:10005_solr":250.0},
[junit4] 2> "_enqueue_time_":3107657165661678,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}},
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}},
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}}]}}
[junit4] 2> 682311 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- processing event: {
[junit4] 2> "id":"b0a64abdb9044T2s87l1cbzkfch2q3tkyudt1r9",
[junit4] 2> "source":"search_rate_trigger",
[junit4] 2> "eventTime":3107652240117828,
[junit4] 2> "eventType":"SEARCHRATE",
[junit4] 2> "properties":{
[junit4] 2> "hotReplicas":[
[junit4] 2> {"core_node2":{
[junit4] 2> "core":"collection1_shard1_replica_n2",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "rate":250.0,
[junit4] 2> "state":"active",
[junit4] 2> "QUERY./select.requestTimes:1minRate":250,
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}},
[junit4] 2> {"core_node1":{
[junit4] 2> "core":"collection1_shard1_replica_n1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "node_name":"127.0.0.1:10005_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "rate":250.0,
[junit4] 2> "state":"active",
[junit4] 2> "QUERY./select.requestTimes:1minRate":250,
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}],
[junit4] 2> "coldNodes":{},
[junit4] 2> "coldShards":{},
[junit4] 2> "coldReplicas":[],
[junit4] 2> "violationType":["hotShards"],
[junit4] 2> "coldCollections":{},
[junit4] 2> "hotShards":{"collection1":{"shard1":250.0}},
[junit4] 2> "hotCollections":{"collection1":500.0},
[junit4] 2> "hotNodes":{
[junit4] 2> "127.0.0.1:10004_solr":250.0,
[junit4] 2> "127.0.0.1:10005_solr":250.0},
[junit4] 2> "_enqueue_time_":3107657165661678,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}},
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}},
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}}]}} with context properties: {AFTER_ACTION=[start], BEFORE_ACTION=[start, compute]}
[junit4] 2> 682315 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.ComputePlanAction Computed Plan: action=ADDREPLICA&collection=collection1&shard=shard1&node=127.0.0.1:10005_solr&type=NRT
[junit4] 2> 682315 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.ComputePlanAction Computed Plan: action=ADDREPLICA&collection=collection1&shard=shard1&node=127.0.0.1:10004_solr&type=NRT
[junit4] 2> 682315 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.ComputePlanAction Computed Plan: action=ADDREPLICA&collection=collection1&shard=shard1&node=127.0.0.1:10004_solr&type=NRT
[junit4] 2> 682317 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.ExecutePlanAction -- processing event: {
[junit4] 2> "id":"b0a64abdb9044T2s87l1cbzkfch2q3tkyudt1r9",
[junit4] 2> "source":"search_rate_trigger",
[junit4] 2> "eventTime":3107652240117828,
[junit4] 2> "eventType":"SEARCHRATE",
[junit4] 2> "properties":{
[junit4] 2> "hotReplicas":[
[junit4] 2> {"core_node2":{
[junit4] 2> "core":"collection1_shard1_replica_n2",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "rate":250.0,
[junit4] 2> "state":"active",
[junit4] 2> "QUERY./select.requestTimes:1minRate":250,
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}},
[junit4] 2> {"core_node1":{
[junit4] 2> "core":"collection1_shard1_replica_n1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "node_name":"127.0.0.1:10005_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "rate":250.0,
[junit4] 2> "state":"active",
[junit4] 2> "QUERY./select.requestTimes:1minRate":250,
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}],
[junit4] 2> "__start__":3,
[junit4] 2> "coldNodes":{},
[junit4] 2> "coldShards":{},
[junit4] 2> "coldReplicas":[],
[junit4] 2> "violationType":["hotShards"],
[junit4] 2> "coldCollections":{},
[junit4] 2> "hotShards":{"collection1":{"shard1":250.0}},
[junit4] 2> "hotCollections":{"collection1":500.0},
[junit4] 2> "hotNodes":{
[junit4] 2> "127.0.0.1:10004_solr":250.0,
[junit4] 2> "127.0.0.1:10005_solr":250.0},
[junit4] 2> "_enqueue_time_":3107657165661678,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}},
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}},
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}}]}} with context properties: {operations=[{
[junit4] 2> "class":"org.apache.solr.client.solrj.request.CollectionAdminRequest$AddReplica",
[junit4] 2> "method":"GET",
[junit4] 2> "params.action":"ADDREPLICA",
[junit4] 2> "params.collection":"collection1",
[junit4] 2> "params.shard":"shard1",
[junit4] 2> "params.node":"127.0.0.1:10005_solr",
[junit4] 2> "params.type":"NRT"}, {
[junit4] 2> "class":"org.apache.solr.client.solrj.request.CollectionAdminRequest$AddReplica",
[junit4] 2> "method":"GET",
[junit4] 2> "params.action":"ADDREPLICA",
[junit4] 2> "params.collection":"collection1",
[junit4] 2> "params.shard":"shard1",
[junit4] 2> "params.node":"127.0.0.1:10004_solr",
[junit4] 2> "params.type":"NRT"}, {
[junit4] 2> "class":"org.apache.solr.client.solrj.request.CollectionAdminRequest$AddReplica",
[junit4] 2> "method":"GET",
[junit4] 2> "params.action":"ADDREPLICA",
[junit4] 2> "params.collection":"collection1",
[junit4] 2> "params.shard":"shard1",
[junit4] 2> "params.node":"127.0.0.1:10004_solr",
[junit4] 2> "params.type":"NRT"}], AFTER_ACTION=[start, compute], BEFORE_ACTION=[start, compute, execute]}
[junit4] 2> 682317 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.ExecutePlanAction Executing operation: action=ADDREPLICA&collection=collection1&shard=shard1&node=127.0.0.1:10005_solr&type=NRT
[junit4] 2> 682319 INFO (simCloudManagerPool-7283-thread-8) [ ] o.a.s.c.a.c.AddReplicaCmd Node Identified 127.0.0.1:10005_solr for creating new replica of shard shard1 for collection collection1
[junit4] 2> 682319 INFO (simCloudManagerPool-7283-thread-8) [ ] o.a.s.c.a.c.AddReplicaCmd Returning CreateReplica command.
[junit4] 2> 682329 DEBUG (simCloudManagerPool-7283-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=7
[junit4] 2> 682329 DEBUG (simCloudManagerPool-7283-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 7
[junit4] 2> 682349 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.ExecutePlanAction Executing operation: action=ADDREPLICA&collection=collection1&shard=shard1&node=127.0.0.1:10004_solr&type=NRT
[junit4] 2> 682351 DEBUG (simCloudManagerPool-7283-thread-11) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=8
[junit4] 2> 682352 DEBUG (simCloudManagerPool-7283-thread-11) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 8
[junit4] 2> 682352 INFO (simCloudManagerPool-7283-thread-11) [ ] o.a.s.c.a.c.AddReplicaCmd Node Identified 127.0.0.1:10004_solr for creating new replica of shard shard1 for collection collection1
[junit4] 2> 682352 INFO (simCloudManagerPool-7283-thread-11) [ ] o.a.s.c.a.c.AddReplicaCmd Returning CreateReplica command.
[junit4] 2> 682362 DEBUG (simCloudManagerPool-7283-thread-11) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=9
[junit4] 2> 682363 DEBUG (simCloudManagerPool-7283-thread-11) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 9
[junit4] 2> 682363 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.ExecutePlanAction Executing operation: action=ADDREPLICA&collection=collection1&shard=shard1&node=127.0.0.1:10004_solr&type=NRT
[junit4] 2> 682364 DEBUG (simCloudManagerPool-7283-thread-14) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=10
[junit4] 2> 682364 DEBUG (simCloudManagerPool-7283-thread-14) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 10
[junit4] 2> 682364 INFO (simCloudManagerPool-7283-thread-14) [ ] o.a.s.c.a.c.AddReplicaCmd Node Identified 127.0.0.1:10004_solr for creating new replica of shard shard1 for collection collection1
[junit4] 2> 682364 INFO (simCloudManagerPool-7283-thread-14) [ ] o.a.s.c.a.c.AddReplicaCmd Returning CreateReplica command.
[junit4] 2> 682375 DEBUG (simCloudManagerPool-7283-thread-14) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=11
[junit4] 2> 682375 DEBUG (simCloudManagerPool-7283-thread-14) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 11
[junit4] 2> 682377 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=12
[junit4] 2> 682378 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 12
[junit4] 2> 682378 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"b0a64abdb9044T2s87l1cbzkfch2q3tkyudt1r9",
[junit4] 2> "source":"search_rate_trigger",
[junit4] 2> "eventTime":3107652240117828,
[junit4] 2> "eventType":"SEARCHRATE",
[junit4] 2> "properties":{
[junit4] 2> "hotReplicas":[
[junit4] 2> {"core_node2":{
[junit4] 2> "core":"collection1_shard1_replica_n2",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "rate":250.0,
[junit4] 2> "state":"active",
[junit4] 2> "QUERY./select.requestTimes:1minRate":250,
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}},
[junit4] 2> {"core_node1":{
[junit4] 2> "core":"collection1_shard1_replica_n1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "node_name":"127.0.0.1:10005_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "rate":250.0,
[junit4] 2> "state":"active",
[junit4] 2> "QUERY./select.requestTimes:1minRate":250,
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}],
[junit4] 2> "__start__":3,
[junit4] 2> "coldNodes":{},
[junit4] 2> "coldShards":{},
[junit4] 2> "coldReplicas":[],
[junit4] 2> "violationType":["hotShards"],
[junit4] 2> "coldCollections":{},
[junit4] 2> "hotShards":{"collection1":{"shard1":250.0}},
[junit4] 2> "hotCollections":{"collection1":500.0},
[junit4] 2> "hotNodes":{
[junit4] 2> "127.0.0.1:10004_solr":250.0,
[junit4] 2> "127.0.0.1:10005_solr":250.0},
[junit4] 2> "_enqueue_time_":3107657165661678,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}},
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}},
[junit4] 2> {
[junit4] 2> "action":"ADDREPLICA",
[junit4] 2> "hints":{"COLL_SHARD":[{
[junit4] 2> "first":"collection1",
[junit4] 2> "second":"shard1"}]}}]}}
[junit4] 2> 682378 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: search_rate_trigger after 100ms
[junit4] 2> 682378 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: .auto_add_replicas after 100ms
[junit4] 2> 682378 DEBUG (AutoscalingActionExecutor-7285-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 3425 ms for event id=b0a64abdb9044T2s87l1cbzkfch2q3tkyudt1r9
[junit4] 2> 682382 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 682391 DEBUG (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 682392 DEBUG (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 682392 DEBUG (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 682393 DEBUG (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 682393 DEBUG (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 682393 DEBUG (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 682393 INFO (TEST-TestSimTriggerIntegration.testSearchRate-seed#[47AC6AC11037A35]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testSearchRate
[junit4] 2> 682399 INFO (TEST-TestSimTriggerIntegration.testNodeLostTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNodeLostTriggerRestoreState
[junit4] 2> 682406 DEBUG (TEST-TestSimTriggerIntegration.testNodeLostTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10006_solr
[junit4] 2> 682406 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 682407 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 682408 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 682408 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 682414 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10006_solr]
[junit4] 2> 682414 DEBUG (TEST-TestSimTriggerIntegration.testNodeLostTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=0
[junit4] 2> 682414 DEBUG (TEST-TestSimTriggerIntegration.testNodeLostTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 0
[junit4] 2> 682414 INFO (TEST-TestSimTriggerIntegration.testNodeLostTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 682415 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 682415 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 682415 DEBUG (ScheduledTrigger-7290-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> 682420 DEBUG (simCloudManagerPool-7289-thread-2) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 682420 DEBUG (simCloudManagerPool-7289-thread-2) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 682423 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 2
[junit4] 2> 682440 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 682440 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 2
[junit4] 2> 682442 DEBUG (ScheduledTrigger-7290-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> 682442 DEBUG (simCloudManagerPool-7289-thread-3) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 682442 DEBUG (simCloudManagerPool-7289-thread-3) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 3
[junit4] 2> 682443 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 3
[junit4] 2> 682443 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestSimTriggerIntegration TestTriggerAction init
[junit4] 2> 682443 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger node_lost_restore_trigger - Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10007_solr]
[junit4] 2> 682443 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 682443 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 3, lastZnodeVersion 3
[junit4] 2> 682444 DEBUG (ScheduledTrigger-7290-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_restore_trigger with currently live nodes: 3 and last live nodes: 2
[junit4] 2> 682548 DEBUG (TEST-TestSimTriggerIntegration.testNodeLostTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider -- created marker: /autoscaling/nodeLost/127.0.0.1:10008_solr
[junit4] 2> 682548 DEBUG (ScheduledTrigger-7290-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> 682549 DEBUG (ScheduledTrigger-7290-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_restore_trigger with currently live nodes: 2 and last live nodes: 3
[junit4] 2> 682549 DEBUG (ScheduledTrigger-7290-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Tracking lost node: 127.0.0.1:10008_solr
[junit4] 2> 682569 DEBUG (ScheduledTrigger-7290-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_restore_trigger with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 682570 DEBUG (ScheduledTrigger-7290-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> 682573 DEBUG (simCloudManagerPool-7289-thread-4) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 682573 DEBUG (simCloudManagerPool-7289-thread-4) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 4
[junit4] 2> 682574 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 4
[junit4] 2> 682574 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestSimTriggerIntegration TestTriggerAction init
[junit4] 2> 682574 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger node_lost_restore_trigger - Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10007_solr]
[junit4] 2> 682574 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 682574 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 4, lastZnodeVersion 4
[junit4] 2> 682574 DEBUG (ScheduledTrigger-7290-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_restore_trigger with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 682574 DEBUG (ScheduledTrigger-7290-thread-1) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger firing registered processor for lost nodes: [127.0.0.1:10008_solr]
[junit4] 2> 682574 DEBUG (ScheduledTrigger-7290-thread-1) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"b0a68a500d91aT2s87l1cbzkfch2q3tkyudt1rb",
[junit4] 2> "source":"node_lost_restore_trigger",
[junit4] 2> "eventTime":3107669304989978,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3107669304989978],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "nodeNames":["127.0.0.1:10008_solr"]}}
[junit4] 2> 682574 DEBUG (ScheduledTrigger-7290-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [.auto_add_replicas, node_lost_restore_trigger]
[junit4] 2> 682574 DEBUG (ScheduledTrigger-7290-thread-1) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"b0a68a500d91aT2s87l1cbzkfch2q3tkyudt1rb",
[junit4] 2> "source":"node_lost_restore_trigger",
[junit4] 2> "eventTime":3107669304989978,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3107669304989978],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":3107670584514828,
[junit4] 2> "nodeNames":["127.0.0.1:10008_solr"]}}
[junit4] 2> 682578 DEBUG (AutoscalingActionExecutor-7291-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"b0a68a500d91aT2s87l1cbzkfch2q3tkyudt1rb",
[junit4] 2> "source":"node_lost_restore_trigger",
[junit4] 2> "eventTime":3107669304989978,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3107669304989978],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":3107670584514828,
[junit4] 2> "nodeNames":["127.0.0.1:10008_solr"]}}
[junit4] 2> 682578 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 682579 DEBUG (TEST-TestSimTriggerIntegration.testNodeLostTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 682579 DEBUG (TEST-TestSimTriggerIntegration.testNodeLostTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 682579 DEBUG (TEST-TestSimTriggerIntegration.testNodeLostTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 682579 WARN (AutoscalingActionExecutor-7291-thread-1) [ ] o.a.s.c.a.SystemLogListener Exception sending event. Collection: .system, event: {
[junit4] 2> "id":"b0a68a500d91aT2s87l1cbzkfch2q3tkyudt1rb",
[junit4] 2> "source":"node_lost_restore_trigger",
[junit4] 2> "eventTime":3107669304989978,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3107669304989978],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":3107670584514828,
[junit4] 2> "nodeNames":["127.0.0.1:10008_solr"]}}, exception: java.io.IOException: already closed
[junit4] 2> 682579 DEBUG (AutoscalingActionExecutor-7291-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 87 ms for event id=b0a68a500d91aT2s87l1cbzkfch2q3tkyudt1rb
[junit4] 2> 682579 DEBUG (TEST-TestSimTriggerIntegration.testNodeLostTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 682579 DEBUG (TEST-TestSimTriggerIntegration.testNodeLostTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 682579 DEBUG (TEST-TestSimTriggerIntegration.testNodeLostTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 682580 INFO (TEST-TestSimTriggerIntegration.testNodeLostTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testNodeLostTriggerRestoreState
[junit4] 2> 682583 INFO (TEST-TestSimTriggerIntegration.testListeners-seed#[47AC6AC11037A35]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testListeners
[junit4] 2> 682586 DEBUG (TEST-TestSimTriggerIntegration.testListeners-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10009_solr
[junit4] 2> 682586 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 682586 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 682587 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 682587 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 682587 DEBUG (TEST-TestSimTriggerIntegration.testListeners-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=0
[junit4] 2> 682587 DEBUG (TEST-TestSimTriggerIntegration.testListeners-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 0
[junit4] 2> 682587 INFO (TEST-TestSimTriggerIntegration.testListeners-seed#[47AC6AC11037A35]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 682588 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10010_solr, 127.0.0.1:10009_solr]
[junit4] 2> 682588 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 682588 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 682588 DEBUG (ScheduledTrigger-7296-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> 682593 DEBUG (simCloudManagerPool-7295-thread-2) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 682593 DEBUG (simCloudManagerPool-7295-thread-2) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 682593 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 2
[junit4] 2> 682600 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 682600 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 2
[junit4] 2> 682601 DEBUG (simCloudManagerPool-7295-thread-3) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 682602 DEBUG (simCloudManagerPool-7295-thread-3) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 3
[junit4] 2> 682602 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 3
[junit4] 2> 682602 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestSimTriggerIntegration TestTriggerAction init
[junit4] 2> 682602 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger - Initial livenodes: [127.0.0.1:10010_solr, 127.0.0.1:10009_solr]
[junit4] 2> 682602 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger instantiated with properties: {event=nodeAdded, waitFor=1, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestSimTriggerIntegration$TestTriggerAction}, {name=test1, class=org.apache.solr.cloud.autoscaling.sim.TestSimTriggerIntegration$TestDummyAction}], enabled=true}
[junit4] 2> 682602 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 682602 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 3, lastZnodeVersion 3
[junit4] 2> 682602 DEBUG (ScheduledTrigger-7296-thread-1) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 682602 DEBUG (ScheduledTrigger-7296-thread-1) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 2
[junit4] 2> 682603 DEBUG (simCloudManagerPool-7295-thread-4) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 682603 DEBUG (simCloudManagerPool-7295-thread-4) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 4
[junit4] 2> 682603 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 4
[junit4] 2> 682603 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 682603 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 4, lastZnodeVersion 4
[junit4] 2> 682607 DEBUG (simCloudManagerPool-7295-thread-5) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 682607 DEBUG (simCloudManagerPool-7295-thread-5) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 5
[junit4] 2> 682608 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 5
[junit4] 2> 682608 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 682608 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 5, lastZnodeVersion 5
[junit4] 2> 682608 DEBUG (TEST-TestSimTriggerIntegration.testListeners-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider -- creating marker: /autoscaling/nodeAdded/127.0.0.1:10011_solr
[junit4] 2> 682608 DEBUG (ScheduledTrigger-7296-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3 and last live nodes: 2
[junit4] 2> 682623 DEBUG (ScheduledTrigger-7296-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 682623 DEBUG (ScheduledTrigger-7296-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 682623 DEBUG (ScheduledTrigger-7296-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:10011_solr at time 3107673002813928
[junit4] 2> 682629 DEBUG (ScheduledTrigger-7296-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3 and last live nodes: 3
[junit4] 2> 682644 DEBUG (ScheduledTrigger-7296-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 682644 DEBUG (ScheduledTrigger-7296-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 682644 DEBUG (ScheduledTrigger-7296-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger firing registered processor for nodes: [127.0.0.1:10011_solr] added at times [3107673002813928], now=3107674046033378
[junit4] 2> 682644 DEBUG (ScheduledTrigger-7296-thread-3) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"b0a69816929e8T2s87l1cbzkfch2q3tkyudt1rd",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":3107673002813928,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3107673002813928],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "nodeNames":["127.0.0.1:10011_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 682644 DEBUG (ScheduledTrigger-7296-thread-3) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [.auto_add_replicas, node_added_trigger]
[junit4] 2> 682645 DEBUG (ScheduledTrigger-7296-thread-3) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"b0a69816929e8T2s87l1cbzkfch2q3tkyudt1rd",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":3107673002813928,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3107673002813928],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":3107674085647028,
[junit4] 2> "nodeNames":["127.0.0.1:10011_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 682645 DEBUG (ScheduledTrigger-7296-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Removing new node from tracking: 127.0.0.1:10011_solr
[junit4] 2> 682645 DEBUG (AutoscalingActionExecutor-7297-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"b0a69816929e8T2s87l1cbzkfch2q3tkyudt1rd",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":3107673002813928,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3107673002813928],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":3107674085647028,
[junit4] 2> "nodeNames":["127.0.0.1:10011_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 682646 DEBUG (AutoscalingActionExecutor-7297-thread-1) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"b0a69816929e8T2s87l1cbzkfch2q3tkyudt1rd",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":3107673002813928,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3107673002813928],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":3107674085647028,
[junit4] 2> "nodeNames":["127.0.0.1:10011_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 682646 DEBUG (AutoscalingActionExecutor-7297-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: node_added_trigger after 100ms
[junit4] 2> 682646 DEBUG (AutoscalingActionExecutor-7297-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: .auto_add_replicas after 100ms
[junit4] 2> 682646 DEBUG (AutoscalingActionExecutor-7297-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 48 ms for event id=b0a69816929e8T2s87l1cbzkfch2q3tkyudt1rd
[junit4] 2> 682647 DEBUG (TEST-TestSimTriggerIntegration.testListeners-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider -- creating marker: /autoscaling/nodeAdded/127.0.0.1:10012_solr
[junit4] 2> 682746 DEBUG (ScheduledTrigger-7296-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 682746 DEBUG (ScheduledTrigger-7296-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 682746 DEBUG (ScheduledTrigger-7296-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:10012_solr at time 3107679186478978
[junit4] 2> 682746 DEBUG (ScheduledTrigger-7296-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 4 and last live nodes: 3
[junit4] 2> 682767 DEBUG (ScheduledTrigger-7296-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 682767 DEBUG (ScheduledTrigger-7296-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 682767 DEBUG (ScheduledTrigger-7296-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger firing registered processor for nodes: [127.0.0.1:10012_solr] added at times [3107679186478978], now=3107680202189078
[junit4] 2> 682767 DEBUG (ScheduledTrigger-7296-thread-2) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"b0a6af1fc6782T2s87l1cbzkfch2q3tkyudt1re",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":3107679186478978,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3107679186478978],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "nodeNames":["127.0.0.1:10012_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 682767 DEBUG (ScheduledTrigger-7296-thread-2) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [.auto_add_replicas, node_added_trigger]
[junit4] 2> 682767 DEBUG (ScheduledTrigger-7296-thread-2) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"b0a6af1fc6782T2s87l1cbzkfch2q3tkyudt1re",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":3107679186478978,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3107679186478978],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":3107680210796178,
[junit4] 2> "nodeNames":["127.0.0.1:10012_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 682767 DEBUG (ScheduledTrigger-7296-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Removing new node from tracking: 127.0.0.1:10012_solr
[junit4] 2> 682767 DEBUG (AutoscalingActionExecutor-7297-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"b0a6af1fc6782T2s87l1cbzkfch2q3tkyudt1re",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":3107679186478978,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3107679186478978],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":3107680210796178,
[junit4] 2> "nodeNames":["127.0.0.1:10012_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 682768 DEBUG (AutoscalingActionExecutor-7297-thread-1) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"b0a6af1fc6782T2s87l1cbzkfch2q3tkyudt1re",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":3107679186478978,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3107679186478978],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":3107680210796178,
[junit4] 2> "nodeNames":["127.0.0.1:10012_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 682768 WARN (AutoscalingActionExecutor-7297-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":"b0a6af1fc6782T2s87l1cbzkfch2q3tkyudt1re",
[junit4] 2> org.apache.solr.cloud.autoscaling.TriggerActionException: Error processing action for trigger event: {
[junit4] 2> "id":"b0a6af1fc6782T2s87l1cbzkfch2q3tkyudt1re",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":3107679186478978,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3107679186478978],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":3107680210796178,
[junit4] 2> "nodeNames":["127.0.0.1:10012_solr"],
[junit4] 2> "replicaType":"NRT"}}
[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_252]
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_252]
[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_252]
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
[junit4] 2> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
[junit4] 2> Caused by: java.lang.RuntimeException: failure
[junit4] 2> at org.apache.solr.cloud.autoscaling.sim.TestSimTriggerIntegration$TestDummyAction.process(TestSimTriggerIntegration.java:1116) ~[test/:?]
[junit4] 2> at org.apache.solr.cloud.autoscaling.ScheduledTriggers.lambda$null$3(ScheduledTriggers.java:331) ~[java/:?]
[junit4] 2> ... 6 more
[junit4] 2> 682768 DEBUG (AutoscalingActionExecutor-7297-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: node_added_trigger after 100ms
[junit4] 2> 682768 DEBUG (AutoscalingActionExecutor-7297-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: .auto_add_replicas after 100ms
[junit4] 2> 682769 DEBUG (AutoscalingActionExecutor-7297-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 64 ms for event id=b0a6af1fc6782T2s87l1cbzkfch2q3tkyudt1re
[junit4] 2> 682769 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 682769 DEBUG (TEST-TestSimTriggerIntegration.testListeners-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 682769 DEBUG (TEST-TestSimTriggerIntegration.testListeners-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 682769 DEBUG (TEST-TestSimTriggerIntegration.testListeners-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 682769 DEBUG (TEST-TestSimTriggerIntegration.testListeners-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 682769 DEBUG (TEST-TestSimTriggerIntegration.testListeners-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 682769 DEBUG (TEST-TestSimTriggerIntegration.testListeners-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 682770 INFO (TEST-TestSimTriggerIntegration.testListeners-seed#[47AC6AC11037A35]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testListeners
[junit4] 2> 682772 INFO (TEST-TestSimTriggerIntegration.testEventQueue-seed#[47AC6AC11037A35]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testEventQueue
[junit4] 2> 682776 DEBUG (TEST-TestSimTriggerIntegration.testEventQueue-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10013_solr
[junit4] 2> 682776 DEBUG (TEST-TestSimTriggerIntegration.testEventQueue-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=0
[junit4] 2> 682776 DEBUG (TEST-TestSimTriggerIntegration.testEventQueue-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 0
[junit4] 2> 682777 INFO (TEST-TestSimTriggerIntegration.testEventQueue-seed#[47AC6AC11037A35]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 682778 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 682778 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 682779 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 682779 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 682779 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10013_solr, 127.0.0.1:10014_solr]
[junit4] 2> 682782 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 682783 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 682783 DEBUG (ScheduledTrigger-7302-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> 682786 DEBUG (simCloudManagerPool-7301-thread-3) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 682786 DEBUG (simCloudManagerPool-7301-thread-3) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 682786 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 2
[junit4] 2> 682793 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 682793 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 2
[junit4] 2> 682794 INFO (simCloudManagerPool-7301-thread-4) [ ] o.a.s.c.a.s.TestSimTriggerIntegration$TestEventQueueAction TestEventQueueAction instantiated
[junit4] 2> 682795 DEBUG (simCloudManagerPool-7301-thread-4) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 682796 DEBUG (simCloudManagerPool-7301-thread-4) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 3
[junit4] 2> 682796 INFO (simCloudManagerPool-7301-thread-4) [ ] o.a.s.c.a.s.TestSimTriggerIntegration$TestEventQueueAction TestEventQueueAction instantiated
[junit4] 2> 682796 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 3
[junit4] 2> 683628 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestSimTriggerIntegration$TestEventQueueAction TestEventQueueAction init
[junit4] 2> 683629 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger1 - Initial livenodes: [127.0.0.1:10013_solr, 127.0.0.1:10014_solr]
[junit4] 2> 683629 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger1 instantiated with properties: {event=nodeAdded, waitFor=1, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestSimTriggerIntegration$TestEventQueueAction}], enabled=true}
[junit4] 2> 683629 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 683629 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 3, lastZnodeVersion 3
[junit4] 2> 683629 DEBUG (ScheduledTrigger-7302-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 683629 DEBUG (ScheduledTrigger-7302-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 2
[junit4] 2> 683629 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 683629 DEBUG (ScheduledTrigger-7302-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> 683634 DEBUG (TEST-TestSimTriggerIntegration.testEventQueue-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 683635 DEBUG (TEST-TestSimTriggerIntegration.testEventQueue-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 683635 DEBUG (TEST-TestSimTriggerIntegration.testEventQueue-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 683635 DEBUG (TEST-TestSimTriggerIntegration.testEventQueue-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 683635 DEBUG (TEST-TestSimTriggerIntegration.testEventQueue-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 683635 DEBUG (TEST-TestSimTriggerIntegration.testEventQueue-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 683636 INFO (TEST-TestSimTriggerIntegration.testEventQueue-seed#[47AC6AC11037A35]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testEventQueue
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestSimTriggerIntegration -Dtests.method=testEventQueue -Dtests.seed=47AC6AC11037A35 -Dtests.multiplier=2 -Dtests.slow=true -Dtests.locale=de-LU -Dtests.timezone=Asia/Gaza -Dtests.asserts=true -Dtests.file.encoding=US-ASCII
[junit4] ERROR 0.87s J0 | TestSimTriggerIntegration.testEventQueue <<<
[junit4] > Throwable #1: java.util.concurrent.TimeoutException: OverseerTriggerThread never caught up to the latest znodeVersion
[junit4] > at __randomizedtesting.SeedInfo.seed([47AC6AC11037A35:CDCF84021864BCC0]:0)
[junit4] > at org.apache.solr.util.TimeOut.waitFor(TimeOut.java:66)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.SimSolrCloudTestCase.assertAutoscalingUpdateComplete(SimSolrCloudTestCase.java:98)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.TestSimTriggerIntegration.testEventQueue(TestSimTriggerIntegration.java:750)
[junit4] > at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 683644 INFO (TEST-TestSimTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNodeAddedTriggerRestoreState
[junit4] 2> 683648 DEBUG (TEST-TestSimTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10015_solr
[junit4] 2> 683649 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 683649 DEBUG (TEST-TestSimTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=0
[junit4] 2> 683649 DEBUG (TEST-TestSimTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 0
[junit4] 2> 683649 INFO (TEST-TestSimTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[47AC6AC11037A35]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 683649 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 683649 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 683649 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 683650 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10016_solr, 127.0.0.1:10015_solr]
[junit4] 2> 683650 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 683650 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 683650 DEBUG (ScheduledTrigger-7308-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> 683652 DEBUG (simCloudManagerPool-7307-thread-2) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 683652 DEBUG (simCloudManagerPool-7307-thread-2) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 683652 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 2
[junit4] 2> 683653 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 683653 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 2
[junit4] 2> 683654 DEBUG (simCloudManagerPool-7307-thread-3) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 683655 DEBU
[...truncated too long message...]
"nodeNames":["127.0.0.1:10037_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 691147 DEBUG (ScheduledTrigger-7350-thread-2) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [.auto_add_replicas, node_added_trigger2, node_added_trigger1]
[junit4] 2> 691147 DEBUG (ScheduledTrigger-7350-thread-2) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"b0accbcea60a0T2s87l1cbzkfch2q3tkyudt1rz",
[junit4] 2> "source":"node_added_trigger2",
[junit4] 2> "eventTime":3108099202900128,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3108099202900128],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":3108099213484678,
[junit4] 2> "nodeNames":["127.0.0.1:10037_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 691147 DEBUG (ScheduledTrigger-7350-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Removing new node from tracking: 127.0.0.1:10037_solr
[junit4] 2> 691147 DEBUG (AutoscalingActionExecutor-7351-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"b0accbcea60a0T2s87l1cbzkfch2q3tkyudt1rz",
[junit4] 2> "source":"node_added_trigger2",
[junit4] 2> "eventTime":3108099202900128,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3108099202900128],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":3108099213484678,
[junit4] 2> "nodeNames":["127.0.0.1:10037_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 691147 INFO (AutoscalingActionExecutor-7351-thread-1) [ ] o.a.s.c.a.s.TestSimTriggerIntegration last action at 3108094181413878 time = 3108099233211128
[junit4] 2> 691147 INFO (AutoscalingActionExecutor-7351-thread-1) [ ] o.a.s.c.a.s.TestSimTriggerIntegration action executed from node_added_trigger2
[junit4] 2> 691148 DEBUG (simCloudManagerPool-7349-thread-5) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 691149 DEBUG (simCloudManagerPool-7349-thread-5) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 5
[junit4] 2> 691149 DEBUG (AutoscalingActionExecutor-7351-thread-1) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"b0accbcea60a0T2s87l1cbzkfch2q3tkyudt1rz",
[junit4] 2> "source":"node_added_trigger2",
[junit4] 2> "eventTime":3108099202900128,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[3108099202900128],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":3108099213484678,
[junit4] 2> "nodeNames":["127.0.0.1:10037_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 691149 DEBUG (AutoscalingActionExecutor-7351-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: .auto_add_replicas after 100ms
[junit4] 2> 691149 DEBUG (AutoscalingActionExecutor-7351-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: node_added_trigger2 after 100ms
[junit4] 2> 691149 DEBUG (AutoscalingActionExecutor-7351-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: node_added_trigger1 after 100ms
[junit4] 2> 691149 DEBUG (AutoscalingActionExecutor-7351-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 84 ms for event id=b0accbcea60a0T2s87l1cbzkfch2q3tkyudt1rz
[junit4] 2> 691149 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 5
[junit4] 2> 691149 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestSimTriggerIntegration TestTriggerAction init
[junit4] 2> 691149 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger node_lost_trigger1 - Initial livenodes: [127.0.0.1:10037_solr, 127.0.0.1:10035_solr, 127.0.0.1:10036_solr]
[junit4] 2> 691149 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 691149 DEBUG (ScheduledTrigger-7350-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger1 with currently live nodes: 3 and last live nodes: 3
[junit4] 2> 691150 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 5, lastZnodeVersion 5
[junit4] 2> 691158 DEBUG (simCloudManagerPool-7349-thread-6) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 691158 DEBUG (simCloudManagerPool-7349-thread-6) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 6
[junit4] 2> 691159 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 6
[junit4] 2> 691159 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestSimTriggerIntegration TestTriggerAction init
[junit4] 2> 691159 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger node_lost_trigger2 - Initial livenodes: [127.0.0.1:10037_solr, 127.0.0.1:10035_solr, 127.0.0.1:10036_solr]
[junit4] 2> 691159 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 691159 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 6, lastZnodeVersion 6
[junit4] 2> 691159 DEBUG (ScheduledTrigger-7350-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger2 with currently live nodes: 3 and last live nodes: 3
[junit4] 2> 691159 DEBUG (TEST-TestSimTriggerIntegration.testTriggerThrottling-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.s.SimClusterStateProvider -- created marker: /autoscaling/nodeLost/127.0.0.1:10037_solr
[junit4] 2> 691165 DEBUG (TEST-TestSimTriggerIntegration.testTriggerThrottling-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 691165 DEBUG (TEST-TestSimTriggerIntegration.testTriggerThrottling-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 691165 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 691165 DEBUG (TEST-TestSimTriggerIntegration.testTriggerThrottling-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 691166 DEBUG (TEST-TestSimTriggerIntegration.testTriggerThrottling-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 691166 DEBUG (TEST-TestSimTriggerIntegration.testTriggerThrottling-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 691166 DEBUG (TEST-TestSimTriggerIntegration.testTriggerThrottling-seed#[47AC6AC11037A35]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 691167 INFO (TEST-TestSimTriggerIntegration.testTriggerThrottling-seed#[47AC6AC11037A35]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testTriggerThrottling
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/jenkins-slave/workspace/Lucene/Lucene-Solr-Tests-8.x/solr/build/solr-core/test/J0/temp/solr.cloud.autoscaling.sim.TestSimTriggerIntegration_47AC6AC11037A35-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene87): {}, docValues:{}, maxPointsInLeafNode=61, maxMBSortInHeap=5.915675717819276, sim=Asserting(RandomSimilarity(queryNorm=true): {}), locale=de-LU, timezone=Asia/Gaza
[junit4] 2> NOTE: Linux 4.15.0-112-generic amd64/Oracle Corporation 1.8.0_252 (64-bit)/cpus=4,threads=1,free=268613960,total=515899392
[junit4] 2> NOTE: All tests run in this JVM: [TestPKIAuthenticationPlugin, NodeAddedTriggerTest, SliceStateTest, SolrMetricsIntegrationTest, AnalysisAfterCoreReloadTest, TestLocalFSCloudBackupRestore, TestSolr4Spatial2, OverseerRolesTest, TestGraphTermsQParserPlugin, DistributedMLTComponentTest, TestSimClusterStateProvider, TestDynamicFieldResource, AddBlockUpdateTest, TestLegacyFieldCache, TestSolrCLIRunExample, TestLuceneIndexBackCompat, TestConfigSets, DeleteLastCustomShardedReplicaTest, SearchRateTriggerIntegrationTest, SpatialFilterTest, TestExpandComponent, LeaderFailoverAfterPartitionTest, DateFieldTest, ZkStateReaderTest, TestConfigSetsAPIZkFailure, SolrSlf4jReporterTest, TestLockTree, TestSchemaField, ChaosMonkeySafeLeaderWithPullReplicasTest, TestValueSourceCache, RootFieldTest, TestLuceneMatchVersion, BasicZkTest, TestChildDocTransformer, PathHierarchyTokenizerFactoryTest, MultiSolrCloudTestCaseTest, TestJettySolrRunner, SpellCheckComponentTest, TermVectorComponentDistributedTest, HdfsDirectoryFactoryTest, SplitShardTest, TestJsonRequest, TestSolrConfigHandlerCloud, RecoveryAfterSoftCommitTest, DateMathParserTest, FastVectorHighlighterTest, BooleanFieldTest, NumberUtilsTest, SparseHLLTest, TestSimExecutePlanAction, HdfsNNFailoverTest, URLClassifyProcessorTest, TestCloudSearcherWarming, BasicAuthIntegrationTest, TestPullReplica, SplitByPrefixTest, UnloadDistributedZkTest, PingRequestHandlerTest, TestStressVersions, CustomCollectionTest, TestSimTriggerIntegration]
[junit4] Completed [228/920 (1!)] on J0 in 9.67s, 11 tests, 1 error <<< FAILURES!
[...truncated 54617 lines...]