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/01/10 20:32:27 UTC
[JENKINS] Lucene » Lucene-Solr-Tests-8.x - Build # 1356 - Unstable!
Build: https://ci-builds.apache.org/job/Lucene/job/Lucene-Solr-Tests-8.x/1356/
1 tests failed.
FAILED: org.apache.solr.cloud.autoscaling.sim.TestSimComputePlanAction.testNodeWithMultipleReplicasLost
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([7A2AFCD38B553563:4AEA1D510327D43F]: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.TestSimComputePlanAction.init(TestSimComputePlanAction.java:105)
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$9.evaluate(RandomizedRunner.java:972)
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 13290 lines...]
[junit4] Suite: org.apache.solr.cloud.autoscaling.sim.TestSimComputePlanAction
[junit4] 2> 27266 INFO (SUITE-TestSimComputePlanAction-seed#[7A2AFCD38B553563]-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> 27267 INFO (SUITE-TestSimComputePlanAction-seed#[7A2AFCD38B553563]-worker) [ ] o.a.s.SolrTestCaseJ4 Created dataDir: /home/jenkins/jenkins-slave/workspace/Lucene/Lucene-Solr-Tests-8.x/solr/build/solr-core/test/J1/temp/solr.cloud.autoscaling.sim.TestSimComputePlanAction_7A2AFCD38B553563-001/data-dir-7-001
[junit4] 2> 27267 WARN (SUITE-TestSimComputePlanAction-seed#[7A2AFCD38B553563]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=1 numCloses=1
[junit4] 2> 27267 INFO (SUITE-TestSimComputePlanAction-seed#[7A2AFCD38B553563]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=false
[junit4] 2> 27270 INFO (SUITE-TestSimComputePlanAction-seed#[7A2AFCD38B553563]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (true) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN)
[junit4] 2> 27270 INFO (SUITE-TestSimComputePlanAction-seed#[7A2AFCD38B553563]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] IGNOR/A 0.01s J1 | TestSimComputePlanAction.testNodeLost
[junit4] > Assumption #1: 'awaitsfix' test group is disabled (@AwaitsFix(bugUrl=https://issues.apache.org/jira/browse/SOLR-12028))
[junit4] 2> 27279 INFO (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNodeWithMultipleReplicasLost
[junit4] 2> 27300 INFO (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.SolrPaths solr home defaulted to 'solr/' (could not find system property or JNDI)
[junit4] 2> 27349 DEBUG (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10000_solr
[junit4] 2> 27356 DEBUG (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=0
[junit4] 2> 27357 DEBUG (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 0
[junit4] 2> 27357 INFO (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 27387 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 27390 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 27408 DEBUG (simCloudManagerPool-122-thread-1) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 27411 DEBUG (simCloudManagerPool-122-thread-1) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 27534 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 27534 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 27534 DEBUG (simCloudManagerPool-122-thread-1) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 27541 DEBUG (simCloudManagerPool-122-thread-2) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 27541 DEBUG (simCloudManagerPool-122-thread-2) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 3
[junit4] 2> 28389 INFO (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.TestSimComputePlanAction -------------_ FINAL STATE --------------
[junit4] 2> 28389 INFO (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.TestSimComputePlanAction * Node values: {"127.0.0.1:10000_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":0,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":10240,
[junit4] 2> "sysprop.java.version":"1.8.0_252",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10000_solr",
[junit4] 2> "metrics:solr.jvm:buffers.direct.Count":0,
[junit4] 2> "port":10000,
[junit4] 2> "heapUsage":123450000,
[junit4] 2> "sysLoadAvg":1.0,
[junit4] 2> "metrics:solr.node:ADMIN./admin/authorization.clientErrors:count":0,
[junit4] 2> "totaldisk":10240}}
[junit4] 2> 28389 INFO (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.TestSimComputePlanAction * Live nodes: [127.0.0.1:10000_solr]
[junit4] 2> 28413 DEBUG (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 28413 DEBUG (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 28413 DEBUG (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 28413 DEBUG (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 28414 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 28414 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Interrupted
[junit4] 2> => java.lang.InterruptedException
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
[junit4] 2> java.lang.InterruptedException: null
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220) ~[?:1.8.0_252]
[junit4] 2> at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335) ~[?:1.8.0_252]
[junit4] 2> at org.apache.solr.cloud.autoscaling.OverseerTriggerThread.run(OverseerTriggerThread.java:197) [java/:?]
[junit4] 2> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
[junit4] 2> 28417 DEBUG (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 28417 DEBUG (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 28419 INFO (TEST-TestSimComputePlanAction.testNodeWithMultipleReplicasLost-seed#[7A2AFCD38B553563]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testNodeWithMultipleReplicasLost
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestSimComputePlanAction -Dtests.method=testNodeWithMultipleReplicasLost -Dtests.seed=7A2AFCD38B553563 -Dtests.multiplier=2 -Dtests.slow=true -Dtests.locale=de-AT -Dtests.timezone=SystemV/PST8PDT -Dtests.asserts=true -Dtests.file.encoding=US-ASCII
[junit4] ERROR 1.14s J1 | TestSimComputePlanAction.testNodeWithMultipleReplicasLost <<<
[junit4] > Throwable #1: java.util.concurrent.TimeoutException: OverseerTriggerThread never caught up to the latest znodeVersion
[junit4] > at __randomizedtesting.SeedInfo.seed([7A2AFCD38B553563:4AEA1D510327D43F]: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.TestSimComputePlanAction.init(TestSimComputePlanAction.java:105)
[junit4] > at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 28423 INFO (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNodeAdded
[junit4] 2> 28429 DEBUG (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10001_solr
[junit4] 2> 28440 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 28441 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 28441 DEBUG (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=0
[junit4] 2> 28441 DEBUG (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 0
[junit4] 2> 28441 INFO (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 28441 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 28441 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 28449 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10001_solr]
[junit4] 2> 28451 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 28451 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 28453 DEBUG (simCloudManagerPool-128-thread-1) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 28453 DEBUG (ScheduledTrigger-129-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28453 DEBUG (simCloudManagerPool-128-thread-1) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 28457 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 2
[junit4] 2> 28457 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 28458 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 2
[junit4] 2> 28476 DEBUG (ScheduledTrigger-129-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28477 DEBUG (simCloudManagerPool-128-thread-2) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 28477 DEBUG (simCloudManagerPool-128-thread-2) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 3
[junit4] 2> 28478 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 3
[junit4] 2> 28478 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 28478 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 3, lastZnodeVersion 3
[junit4] 2> 28496 DEBUG (ScheduledTrigger-129-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28517 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28537 DEBUG (ScheduledTrigger-129-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28557 DEBUG (ScheduledTrigger-129-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28577 DEBUG (ScheduledTrigger-129-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28597 DEBUG (ScheduledTrigger-129-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28612 DEBUG (simCloudManagerPool-128-thread-3) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 28612 DEBUG (simCloudManagerPool-128-thread-3) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 4
[junit4] 2> 28613 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 4
[junit4] 2> 28613 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger - Initial livenodes: [127.0.0.1:10001_solr]
[junit4] 2> 28613 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger instantiated with properties: {event=nodeAdded, waitFor=1, actions=[{name=compute_plan, class=solr.ComputePlanAction}, {name=test, class=org.apache.solr.cloud.autoscaling.sim.TestSimComputePlanAction$AssertingTriggerAction}], enabled=true}
[junit4] 2> 28613 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 28613 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 28614 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 1
[junit4] 2> 28614 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 4, lastZnodeVersion 4
[junit4] 2> 28615 DEBUG (simCloudManagerPool-128-thread-4) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 28615 DEBUG (simCloudManagerPool-128-thread-4) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 5
[junit4] 2> 28616 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 5
[junit4] 2> 28616 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 28616 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 5, lastZnodeVersion 5
[junit4] 2> 28618 DEBUG (ScheduledTrigger-129-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28621 DEBUG (simCloudManagerPool-128-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider -- simCreateCollection testNodeAdded, currentVersion=1
[junit4] 2> 28626 DEBUG (simCloudManagerPool-128-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=1
[junit4] 2> 28626 DEBUG (simCloudManagerPool-128-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 1
[junit4] 2> 28626 DEBUG (simCloudManagerPool-128-thread-5) [ ] o.a.s.c.o.ClusterStateMutator building a new cName: testNodeAdded
[junit4] 2> 28634 DEBUG (ScheduledTrigger-129-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 28634 DEBUG (ScheduledTrigger-129-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 1
[junit4] 2> 28638 DEBUG (ScheduledTrigger-129-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28643 DEBUG (simCloudManagerPool-128-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=2
[junit4] 2> 28645 DEBUG (simCloudManagerPool-128-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 2
[junit4] 2> 28647 WARN (simCloudManagerPool-128-thread-5) [ ] o.a.s.c.a.c.CreateCollectionCmd Specified number of replicas of 4 on collection testNodeAdded is higher than the number of Solr instances currently live or live and part of your createNodeSet(1). It's unusual to run two replica of the same slice on the same Solr-instance.
[junit4] 2> 28654 DEBUG (ScheduledTrigger-129-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 28654 DEBUG (ScheduledTrigger-129-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 1
[junit4] 2> 28659 DEBUG (ScheduledTrigger-129-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28675 DEBUG (ScheduledTrigger-129-thread-1) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 28675 DEBUG (ScheduledTrigger-129-thread-1) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 1
[junit4] 2> 28678 DEBUG (simCloudManagerPool-128-thread-5) [ ] o.a.s.c.s.c.a.PolicyHelper Creating a new session
[junit4] 2> 28679 DEBUG (ScheduledTrigger-129-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28681 DEBUG (simCloudManagerPool-128-thread-5) [ ] o.a.s.c.s.c.a.PolicyHelper New session created, 11353408243048452
[junit4] 2> 28695 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 28695 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 1
[junit4] 2> 28699 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28703 DEBUG (simCloudManagerPool-128-thread-5) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession 11353408243048452
[junit4] 2> 28703 DEBUG (simCloudManagerPool-128-thread-5) [ ] o.a.s.c.s.c.a.PolicyHelper final release, session 11353408243048452 lived a total of 1156ms,
[junit4] 2> 28715 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 28715 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 1
[junit4] 2> 28719 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28735 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 28735 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 1
[junit4] 2> 28945 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28946 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 28946 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 1
[junit4] 2> 28952 DEBUG (simCloudManagerPool-128-thread-6) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=3
[junit4] 2> 28953 DEBUG (simCloudManagerPool-128-thread-6) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 3
[junit4] 2> 28954 DEBUG (simCloudManagerPool-128-thread-6) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testNodeAdded / shard1)
[junit4] 2> 28954 DEBUG (simCloudManagerPool-128-thread-6) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testNodeAdded / shard1 (currentVersion=4): {"core_node1":{}}
[junit4] 2> 28966 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28966 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 28966 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 1
[junit4] 2> 28969 DEBUG (simCloudManagerPool-128-thread-7) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=4
[junit4] 2> 28970 DEBUG (simCloudManagerPool-128-thread-7) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 4
[junit4] 2> 28980 DEBUG (simCloudManagerPool-128-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=5
[junit4] 2> 28980 DEBUG (simCloudManagerPool-128-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 5
[junit4] 2> 28980 DEBUG (simCloudManagerPool-128-thread-5) [ ] o.a.s.c.a.s.SimClusterStateProvider -- finished createCollection testNodeAdded, currentVersion=6
[junit4] 2> 28986 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 28986 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 28986 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 1
[junit4] 2> 28994 DEBUG (simCloudManagerPool-128-thread-9) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=6
[junit4] 2> 28995 DEBUG (simCloudManagerPool-128-thread-9) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 6
[junit4] 2> 28995 DEBUG (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** creating new collection states, currentVersion=7
[junit4] 2> 28996 DEBUG (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.SimClusterStateProvider ** saved cluster state version 7
[junit4] 2> 29006 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 29006 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 29006 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 1
[junit4] 2> 29008 DEBUG (simCloudManagerPool-128-thread-10) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 29008 DEBUG (simCloudManagerPool-128-thread-10) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 6
[junit4] 2> 29009 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 6
[junit4] 2> 29010 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 29010 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 6, lastZnodeVersion 6
[junit4] 2> 29020 DEBUG (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.SimClusterStateProvider -- creating marker: /autoscaling/nodeAdded/127.0.0.1:10002_solr
[junit4] 2> 29026 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 1
[junit4] 2> 29026 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 29026 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 2
[junit4] 2> 29026 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:10002_solr at time 11353425556282952
[junit4] 2> 29046 DEBUG (ScheduledTrigger-129-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> 29046 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 29046 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 2
[junit4] 2> 29047 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger firing registered processor for nodes: [127.0.0.1:10002_solr] added at times [11353425556282952], now=11353426564555252
[junit4] 2> 29047 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"2855e161441e48Tcdamub871dif6bfuaw8rod9ah",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":11353425556282952,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[11353425556282952],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "nodeNames":["127.0.0.1:10002_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 29048 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [.auto_add_replicas, .scheduled_maintenance, node_added_trigger]
[junit4] 2> 29049 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"2855e161441e48Tcdamub871dif6bfuaw8rod9ah",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":11353425556282952,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[11353425556282952],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":11353426660132152,
[junit4] 2> "nodeNames":["127.0.0.1:10002_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 29060 DEBUG (ScheduledTrigger-129-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Removing new node from tracking: 127.0.0.1:10002_solr
[junit4] 2> 29060 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"2855e161441e48Tcdamub871dif6bfuaw8rod9ah",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":11353425556282952,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[11353425556282952],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":11353426660132152,
[junit4] 2> "nodeNames":["127.0.0.1:10002_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 29066 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- processing event: {
[junit4] 2> "id":"2855e161441e48Tcdamub871dif6bfuaw8rod9ah",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":11353425556282952,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[11353425556282952],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":11353426660132152,
[junit4] 2> "nodeNames":["127.0.0.1:10002_solr"],
[junit4] 2> "replicaType":"NRT"}} with context properties: {BEFORE_ACTION=[compute_plan]}
[junit4] 2> 29067 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper Creating a new session
[junit4] 2> 29068 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper New session created, 11353427652698752
[junit4] 2> 29069 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- NODE_ADDED event specified MOVEREPLICA - no hints added.
[junit4] 2> 29070 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- estimated total max ops=6, effective maxOps=6
[junit4] 2> 29082 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- NODE_ADDED event specified MOVEREPLICA - no hints added.
[junit4] 2> 29082 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.a.ComputePlanAction Computed Plan: action=MOVEREPLICA&collection=testNodeAdded&targetNode=127.0.0.1:10002_solr&inPlaceMove=true&replica=core_node1
[junit4] 2> 29083 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- NODE_ADDED event specified MOVEREPLICA - no hints added.
[junit4] 2> 29083 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.a.ComputePlanAction Computed Plan: action=MOVEREPLICA&collection=testNodeAdded&targetNode=127.0.0.1:10002_solr&inPlaceMove=true&replica=core_node2
[junit4] 2> 29083 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- NODE_ADDED event specified MOVEREPLICA - no hints added.
[junit4] 2> 29083 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- no more operations suggested, stopping after 2 ops...
[junit4] 2> 29084 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession 11353427652698752
[junit4] 2> 29084 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper final release, session 11353427652698752 lived a total of 763ms,
[junit4] 2> 29084 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"2855e161441e48Tcdamub871dif6bfuaw8rod9ah",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":11353425556282952,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[11353425556282952],
[junit4] 2> "__compute_diag__":{
[junit4] 2> "noSuggestionsStopAfter":2,
[junit4] 2> "estimatedMaxOps":6,
[junit4] 2> "requestedOperations":-1,
[junit4] 2> "opLimit":6,
[junit4] 2> "maxOperations":6},
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":11353426660132152,
[junit4] 2> "nodeNames":["127.0.0.1:10002_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 29084 INFO (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.TestSimComputePlanAction Node values: {
[junit4] 2> "127.0.0.1:10001_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":4,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":10239.999961853027,
[junit4] 2> "sysprop.java.version":"1.8.0_252",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10001_solr",
[junit4] 2> "metrics:solr.jvm:buffers.direct.Count":0,
[junit4] 2> "port":10001,
[junit4] 2> "heapUsage":123450000,
[junit4] 2> "sysLoadAvg":1.0,
[junit4] 2> "metrics:solr.node:ADMIN./admin/authorization.clientErrors:count":0,
[junit4] 2> "totaldisk":10240},
[junit4] 2> "127.0.0.1:10002_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":0,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":10240,
[junit4] 2> "sysprop.java.version":"1.8.0_252",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10002_solr",
[junit4] 2> "metrics:solr.jvm:buffers.direct.Count":0,
[junit4] 2> "port":10002,
[junit4] 2> "heapUsage":123450000,
[junit4] 2> "sysLoadAvg":1.0,
[junit4] 2> "metrics:solr.node:ADMIN./admin/authorization.clientErrors:count":0,
[junit4] 2> "totaldisk":10240}}
[junit4] 2> 29084 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"2855e161441e48Tcdamub871dif6bfuaw8rod9ah",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":11353425556282952,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[11353425556282952],
[junit4] 2> "__compute_diag__":{
[junit4] 2> "noSuggestionsStopAfter":2,
[junit4] 2> "estimatedMaxOps":6,
[junit4] 2> "requestedOperations":-1,
[junit4] 2> "opLimit":6,
[junit4] 2> "maxOperations":6},
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":11353426660132152,
[junit4] 2> "nodeNames":["127.0.0.1:10002_solr"],
[junit4] 2> "replicaType":"NRT"}}
[junit4] 2> 29084 INFO (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.TestSimComputePlanAction Live nodes: [127.0.0.1:10001_solr, 127.0.0.1:10002_solr], collection state: DocCollection(testNodeAdded//clusterstate.json/7 )={
[junit4] 2> "replicationFactor":"1",
[junit4] 2> "pullReplicas":"0",
[junit4] 2> "router":{"name":"compositeId"},
[junit4] 2> "maxShardsPerNode":"-1",
[junit4] 2> "autoAddReplicas":"false",
[junit4] 2> "nrtReplicas":"4",
[junit4] 2> "tlogReplicas":"0",
[junit4] 2> "autoCreated":"true",
[junit4] 2> "shards":{"shard1":{
[junit4] 2> "replicas":{
[junit4] 2> "core_node1":{
[junit4] 2> "core":"testNodeAdded_shard1_replica_n1",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0},
[junit4] 2> "core_node2":{
[junit4] 2> "core":"testNodeAdded_shard1_replica_n2",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0},
[junit4] 2> "core_node3":{
[junit4] 2> "core":"testNodeAdded_shard1_replica_n3",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0},
[junit4] 2> "core_node4":{
[junit4] 2> "core":"testNodeAdded_shard1_replica_n4",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}},
[junit4] 2> "range":"80000000-7fffffff",
[junit4] 2> "state":"active"}}}
[junit4] 2> 29085 INFO (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.TestSimComputePlanAction -------------_ FINAL STATE --------------
[junit4] 2> 29085 INFO (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.TestSimComputePlanAction * Node values: {
[junit4] 2> "127.0.0.1:10001_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":4,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":10239.999961853027,
[junit4] 2> "sysprop.java.version":"1.8.0_252",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10001_solr",
[junit4] 2> "metrics:solr.jvm:buffers.direct.Count":0,
[junit4] 2> "port":10001,
[junit4] 2> "heapUsage":123450000,
[junit4] 2> "sysLoadAvg":1.0,
[junit4] 2> "metrics:solr.node:ADMIN./admin/authorization.clientErrors:count":0,
[junit4] 2> "totaldisk":10240},
[junit4] 2> "127.0.0.1:10002_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":0,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":10240,
[junit4] 2> "sysprop.java.version":"1.8.0_252",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10002_solr",
[junit4] 2> "metrics:solr.jvm:buffers.direct.Count":0,
[junit4] 2> "port":10002,
[junit4] 2> "heapUsage":123450000,
[junit4] 2> "sysLoadAvg":1.0,
[junit4] 2> "metrics:solr.node:ADMIN./admin/authorization.clientErrors:count":0,
[junit4] 2> "totaldisk":10240}}
[junit4] 2> 29085 INFO (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.TestSimComputePlanAction * Live nodes: [127.0.0.1:10001_solr, 127.0.0.1:10002_solr]
[junit4] 2> 29085 INFO (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.s.TestSimComputePlanAction * Collection testNodeAdded state: DocCollection(testNodeAdded//clusterstate.json/7 )={
[junit4] 2> "replicationFactor":"1",
[junit4] 2> "pullReplicas":"0",
[junit4] 2> "router":{"name":"compositeId"},
[junit4] 2> "maxShardsPerNode":"-1",
[junit4] 2> "autoAddReplicas":"false",
[junit4] 2> "nrtReplicas":"4",
[junit4] 2> "tlogReplicas":"0",
[junit4] 2> "autoCreated":"true",
[junit4] 2> "shards":{"shard1":{
[junit4] 2> "replicas":{
[junit4] 2> "core_node1":{
[junit4] 2> "core":"testNodeAdded_shard1_replica_n1",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0},
[junit4] 2> "core_node2":{
[junit4] 2> "core":"testNodeAdded_shard1_replica_n2",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0},
[junit4] 2> "core_node3":{
[junit4] 2> "core":"testNodeAdded_shard1_replica_n3",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0},
[junit4] 2> "core_node4":{
[junit4] 2> "core":"testNodeAdded_shard1_replica_n4",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}},
[junit4] 2> "range":"80000000-7fffffff",
[junit4] 2> "state":"active"}}}
[junit4] 2> 29086 DEBUG (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 29086 DEBUG (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 29086 DEBUG (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 29086 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 29087 WARN (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.a.SystemLogListener Exception sending event. Collection: .system, event: {
[junit4] 2> "id":"2855e161441e48Tcdamub871dif6bfuaw8rod9ah",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":11353425556282952,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[11353425556282952],
[junit4] 2> "__compute_diag__":{
[junit4] 2> "noSuggestionsStopAfter":2,
[junit4] 2> "estimatedMaxOps":6,
[junit4] 2> "requestedOperations":-1,
[junit4] 2> "opLimit":6,
[junit4] 2> "maxOperations":6},
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":11353426660132152,
[junit4] 2> "nodeNames":["127.0.0.1:10002_solr"],
[junit4] 2> "replicaType":"NRT"}}, exception: java.io.IOException: already closed
[junit4] 2> 29088 DEBUG (AutoscalingActionExecutor-130-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 1388 ms for event id=2855e161441e48Tcdamub871dif6bfuaw8rod9ah
[junit4] 2> 29088 DEBUG (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 29088 DEBUG (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 29088 DEBUG (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 29088 INFO (TEST-TestSimComputePlanAction.testNodeAdded-seed#[7A2AFCD38B553563]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testNodeAdded
[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/J1/temp/solr.cloud.autoscaling.sim.TestSimComputePlanAction_7A2AFCD38B553563-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene87), sim=Asserting(RandomSimilarity(queryNorm=false): {}), locale=de-AT, timezone=SystemV/PST8PDT
[junit4] 2> NOTE: Linux 4.15.0-112-generic amd64/Oracle Corporation 1.8.0_252 (64-bit)/cpus=4,threads=1,free=323930240,total=371195904
[junit4] 2> NOTE: All tests run in this JVM: [CloudReplicaSourceTest, TestLegacyNumericUtils, TestInfoStreamLogging, TestSolrXml, ProtectedTermFilterFactoryTest, TestDynamicFieldCollectionResource, TestSchemaSimilarityResource, TestSimComputePlanAction]
[junit4] Completed [21/923 (1!)] on J1 in 2.31s, 3 tests, 1 error, 1 skipped <<< FAILURES!
[...truncated 53817 lines...]