You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2017/12/27 20:08:46 UTC
[JENKINS] Lucene-Solr-7.x-Solaris (64bit/jdk1.8.0) - Build # 356 -
Still Unstable!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-7.x-Solaris/356/
Java: 64bit/jdk1.8.0 -XX:-UseCompressedOops -XX:+UseG1GC
1 tests failed.
FAILED: org.apache.solr.cloud.autoscaling.TriggerIntegrationTest.testSetProperties
Error Message:
Stack Trace:
java.lang.AssertionError
at __randomizedtesting.SeedInfo.seed([98C4F0A068D35A9F:F3A027E9DBFECF1B]:0)
at org.junit.Assert.fail(Assert.java:92)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.junit.Assert.assertTrue(Assert.java:54)
at org.apache.solr.cloud.autoscaling.TriggerIntegrationTest.testSetProperties(TriggerIntegrationTest.java:1361)
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:1737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:934)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:970)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:984)
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:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890)
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 13580 lines...]
[junit4] Suite: org.apache.solr.cloud.autoscaling.TriggerIntegrationTest
[junit4] 2> 3946154 INFO (SUITE-TriggerIntegrationTest-seed#[98C4F0A068D35A9F]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> Creating dataDir: /export/home/jenkins/workspace/Lucene-Solr-7.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.autoscaling.TriggerIntegrationTest_98C4F0A068D35A9F-001/init-core-data-001
[junit4] 2> 3946154 WARN (SUITE-TriggerIntegrationTest-seed#[98C4F0A068D35A9F]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=24 numCloses=24
[junit4] 2> 3946154 INFO (SUITE-TriggerIntegrationTest-seed#[98C4F0A068D35A9F]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=false
[junit4] 2> 3946156 INFO (SUITE-TriggerIntegrationTest-seed#[98C4F0A068D35A9F]-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> 3946156 INFO (SUITE-TriggerIntegrationTest-seed#[98C4F0A068D35A9F]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 2 servers in /export/home/jenkins/workspace/Lucene-Solr-7.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.autoscaling.TriggerIntegrationTest_98C4F0A068D35A9F-001/tempDir-001
[junit4] 2> 3946156 INFO (SUITE-TriggerIntegrationTest-seed#[98C4F0A068D35A9F]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 3946156 INFO (Thread-8437) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 3946156 INFO (Thread-8437) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 3946159 ERROR (Thread-8437) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
[junit4] 2> 3946256 INFO (SUITE-TriggerIntegrationTest-seed#[98C4F0A068D35A9F]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:34588
[junit4] 2> 3946266 INFO (zkConnectionManagerCallback-4767-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3946288 INFO (jetty-launcher-4764-thread-2) [ ] o.e.j.s.Server jetty-9.3.20.v20170531
[junit4] 2> 3946288 INFO (jetty-launcher-4764-thread-1) [ ] o.e.j.s.Server jetty-9.3.20.v20170531
[junit4] 2> 3946295 INFO (jetty-launcher-4764-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@5f0500d3{/solr,null,AVAILABLE}
[junit4] 2> 3946295 INFO (jetty-launcher-4764-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@4036f898{/solr,null,AVAILABLE}
[junit4] 2> 3946296 INFO (jetty-launcher-4764-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@4785b8ba{HTTP/1.1,[http/1.1]}{127.0.0.1:54064}
[junit4] 2> 3946296 INFO (jetty-launcher-4764-thread-2) [ ] o.e.j.s.Server Started @3950789ms
[junit4] 2> 3946296 INFO (jetty-launcher-4764-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=54064}
[junit4] 2> 3946296 INFO (jetty-launcher-4764-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@37d291f6{HTTP/1.1,[http/1.1]}{127.0.0.1:58429}
[junit4] 2> 3946296 ERROR (jetty-launcher-4764-thread-2) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3946296 INFO (jetty-launcher-4764-thread-1) [ ] o.e.j.s.Server Started @3950790ms
[junit4] 2> 3946296 INFO (jetty-launcher-4764-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 3946297 INFO (jetty-launcher-4764-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=58429}
[junit4] 2> 3946297 INFO (jetty-launcher-4764-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3946297 INFO (jetty-launcher-4764-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 3946297 INFO (jetty-launcher-4764-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-12-27T19:39:33.431Z
[junit4] 2> 3946297 ERROR (jetty-launcher-4764-thread-1) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3946297 INFO (jetty-launcher-4764-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 3946298 INFO (jetty-launcher-4764-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3946298 INFO (jetty-launcher-4764-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 3946298 INFO (jetty-launcher-4764-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-12-27T19:39:33.432Z
[junit4] 2> 3946301 INFO (zkConnectionManagerCallback-4769-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3946301 INFO (zkConnectionManagerCallback-4771-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3946302 INFO (jetty-launcher-4764-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 3946303 INFO (jetty-launcher-4764-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 3946316 INFO (jetty-launcher-4764-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:34588/solr
[junit4] 2> 3946316 INFO (jetty-launcher-4764-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:34588/solr
[junit4] 2> 3946318 INFO (zkConnectionManagerCallback-4777-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3946319 INFO (zkConnectionManagerCallback-4779-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3946321 INFO (zkConnectionManagerCallback-4781-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3946322 INFO (zkConnectionManagerCallback-4783-thread-1-processing-n:127.0.0.1:54064_solr) [n:127.0.0.1:54064_solr ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3946462 INFO (jetty-launcher-4764-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 3946463 INFO (jetty-launcher-4764-thread-2) [n:127.0.0.1:54064_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 3946463 INFO (jetty-launcher-4764-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:58429_solr
[junit4] 2> 3946464 INFO (jetty-launcher-4764-thread-2) [n:127.0.0.1:54064_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54064_solr
[junit4] 2> 3946465 INFO (jetty-launcher-4764-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.Overseer Overseer (id=99247952579198981-127.0.0.1:58429_solr-n_0000000000) starting
[junit4] 2> 3946468 INFO (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 3946470 INFO (zkCallback-4782-thread-1-processing-n:127.0.0.1:54064_solr) [n:127.0.0.1:54064_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 3946479 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Adding .autoAddReplicas trigger
[junit4] 2> 3946481 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 3946481 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:54064_solr]
[junit4] 2> 3946482 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion -1
[junit4] 2> 3946482 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 3946482 INFO (jetty-launcher-4764-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58429_solr
[junit4] 2> 3946483 INFO (zkCallback-4782-thread-1-processing-n:127.0.0.1:54064_solr) [n:127.0.0.1:54064_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 3946484 INFO (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 3946485 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 3946485 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 3946486 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 3946613 INFO (jetty-launcher-4764-thread-2) [n:127.0.0.1:54064_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_54064.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@48c04b48
[junit4] 2> 3946614 INFO (jetty-launcher-4764-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58429.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@48c04b48
[junit4] 2> 3946619 INFO (jetty-launcher-4764-thread-2) [n:127.0.0.1:54064_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_54064.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@48c04b48
[junit4] 2> 3946619 INFO (jetty-launcher-4764-thread-2) [n:127.0.0.1:54064_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_54064.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@48c04b48
[junit4] 2> 3946621 INFO (jetty-launcher-4764-thread-2) [n:127.0.0.1:54064_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-7.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.autoscaling.TriggerIntegrationTest_98C4F0A068D35A9F-001/tempDir-001/node2/.
[junit4] 2> 3946622 INFO (jetty-launcher-4764-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58429.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@48c04b48
[junit4] 2> 3946622 INFO (jetty-launcher-4764-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58429.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@48c04b48
[junit4] 2> 3946623 INFO (jetty-launcher-4764-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-7.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.autoscaling.TriggerIntegrationTest_98C4F0A068D35A9F-001/tempDir-001/node1/.
[junit4] 2> 3946653 INFO (zkConnectionManagerCallback-4789-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3946656 INFO (zkConnectionManagerCallback-4793-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3946658 INFO (SUITE-TriggerIntegrationTest-seed#[98C4F0A068D35A9F]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 3946659 INFO (SUITE-TriggerIntegrationTest-seed#[98C4F0A068D35A9F]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:34588/solr ready
[junit4] 2> 3946784 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNodeAddedTriggerRestoreState
[junit4] 2> 3946785 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.a.s.c.a.TriggerIntegrationTest /autoscaling.json reset, new znode version 2
[junit4] 2> 3946786 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 3946786 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 2
[junit4] 2> 3946791 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3946792 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 3946792 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 2
[junit4] 2> 3946797 INFO (qtp1937897085-31620) [n:127.0.0.1:54064_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3946799 INFO (qtp1298289486-31612) [n:127.0.0.1:58429_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3946800 DEBUG (qtp1937897085-31617) [n:127.0.0.1:54064_solr ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 3946800 INFO (qtp1937897085-31617) [n:127.0.0.1:54064_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/autoscaling params={wt=javabin&version=2} status=0 QTime=4
[junit4] 2> 3946801 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 3
[junit4] 2> 3946801 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.e.j.s.Server jetty-9.3.20.v20170531
[junit4] 2> 3946804 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:54064_solr, 127.0.0.1:58429_solr]
[junit4] 2> 3946804 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_restore_trigger instantiated with properties: {event=nodeAdded, waitFor=5, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.TriggerIntegrationTest$TestTriggerAction}], enabled=true}
[junit4] 2> 3946804 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 3
[junit4] 2> 3946805 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@659a3066{/solr,null,AVAILABLE}
[junit4] 2> 3946806 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@6d25db28{HTTP/1.1,[http/1.1]}{127.0.0.1:60345}
[junit4] 2> 3946806 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.e.j.s.Server Started @3951299ms
[junit4] 2> 3946806 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=60345}
[junit4] 2> 3946806 ERROR (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3946806 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 3946806 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3946806 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 3946806 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-12-27T19:39:33.940Z
[junit4] 2> 3946807 INFO (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.TriggerIntegrationTest TestTriggerAction init
[junit4] 2> 3946810 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3946810 INFO (zkConnectionManagerCallback-4795-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3946811 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 3, lastZnodeVersion 3
[junit4] 2> 3946811 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_restore_trigger
[junit4] 2> 3946811 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 2
[junit4] 2> 3946811 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 3946819 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:34588/solr
[junit4] 2> 3946821 INFO (zkConnectionManagerCallback-4799-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3946824 INFO (zkConnectionManagerCallback-4801-thread-1-processing-n:127.0.0.1:60345_solr) [n:127.0.0.1:60345_solr ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3946836 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [n:127.0.0.1:60345_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 3946840 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [n:127.0.0.1:60345_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 3946843 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [n:127.0.0.1:60345_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60345_solr
[junit4] 2> 3946845 INFO (zkCallback-4782-thread-1-processing-n:127.0.0.1:54064_solr) [n:127.0.0.1:54064_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 3946845 INFO (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 3946847 INFO (zkCallback-4800-thread-1-processing-n:127.0.0.1:60345_solr) [n:127.0.0.1:60345_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 3946847 INFO (zkCallback-4792-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 3946949 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [n:127.0.0.1:60345_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_60345.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@48c04b48
[junit4] 2> 3946956 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [n:127.0.0.1:60345_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_60345.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@48c04b48
[junit4] 2> 3946956 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [n:127.0.0.1:60345_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_60345.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@48c04b48
[junit4] 2> 3946957 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [n:127.0.0.1:60345_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-7.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.autoscaling.TriggerIntegrationTest_98C4F0A068D35A9F-001/tempDir-001/node3/.
[junit4] 2> 3947821 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_restore_trigger
[junit4] 2> 3947822 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3947822 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:60345_solr at time 2147034263632547
[junit4] 2> 3948488 INFO (qtp1937897085-31622) [n:127.0.0.1:54064_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3948489 INFO (qtp1298289486-31613) [n:127.0.0.1:58429_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3948492 INFO (qtp1955971146-31672) [n:127.0.0.1:60345_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3948492 DEBUG (qtp1937897085-31621) [n:127.0.0.1:54064_solr ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 3948494 INFO (qtp1937897085-31621) [n:127.0.0.1:54064_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/autoscaling params={wt=javabin&version=2} status=0 QTime=7
[junit4] 2> 3948495 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 4
[junit4] 2> 3948496 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:54064_solr, 127.0.0.1:58429_solr, 127.0.0.1:60345_solr]
[junit4] 2> 3948496 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_restore_trigger instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.TriggerIntegrationTest$TestTriggerAction}], enabled=true}
[junit4] 2> 3948496 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 4
[junit4] 2> 3948498 INFO (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.TriggerIntegrationTest TestTriggerAction init
[junit4] 2> 3948499 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Adding node from marker path: 127.0.0.1:60345_solr
[junit4] 2> 3948501 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3948501 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_restore_trigger
[junit4] 2> 3948501 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3948501 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_restore_trigger firing registered processor for nodes: [127.0.0.1:60345_solr] added at times [2147034940848485], now=2147034943121521
[junit4] 2> 3948501 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"7a0b786f83965Tbs5gkwc63xlxd6sdmd1kwv4d9",
[junit4] 2> "source":"node_added_restore_trigger",
[junit4] 2> "eventTime":2147034940848485,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147034940848485],
[junit4] 2> "nodeNames":["127.0.0.1:60345_solr"]}}
[junit4] 2> 3948502 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 4, lastZnodeVersion 4
[junit4] 2> 3948503 INFO (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.SystemLogListener Collection .system does not exist, disabling logging.
[junit4] 2> 3948504 DEBUG (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"7a0b786f83965Tbs5gkwc63xlxd6sdmd1kwv4d9",
[junit4] 2> "source":"node_added_restore_trigger",
[junit4] 2> "eventTime":2147034940848485,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147034940848485],
[junit4] 2> "_enqueue_time_":2147034943399442,
[junit4] 2> "nodeNames":["127.0.0.1:60345_solr"]}}
[junit4] 2> 3948505 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testNodeAddedTriggerRestoreState
[junit4] 2> 3948516 DEBUG (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -- processing took 12 ms for event id=7a0b786f83965Tbs5gkwc63xlxd6sdmd1kwv4d9
[junit4] 2> 3948683 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testTriggerThrottling
[junit4] 2> 3948683 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.c.a.TriggerIntegrationTest /autoscaling.json reset, new znode version 5
[junit4] 2> 3948684 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 5
[junit4] 2> 3948684 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 5
[junit4] 2> 3948688 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3948688 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 3948689 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 5, lastZnodeVersion 5
[junit4] 2> 3948693 INFO (qtp1937897085-31623) [n:127.0.0.1:54064_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3948694 INFO (qtp1298289486-31614) [n:127.0.0.1:58429_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3948695 INFO (qtp1955971146-31676) [n:127.0.0.1:60345_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3948695 DEBUG (qtp1955971146-31674) [n:127.0.0.1:60345_solr ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 3948696 INFO (qtp1955971146-31674) [n:127.0.0.1:60345_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/cluster/autoscaling params={wt=javabin&version=2} status=0 QTime=4
[junit4] 2> 3948696 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 6
[junit4] 2> 3948697 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:54064_solr, 127.0.0.1:58429_solr, 127.0.0.1:60345_solr]
[junit4] 2> 3948697 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger1 instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.TriggerIntegrationTest$ThrottlingTesterAction}], enabled=true}
[junit4] 2> 3948697 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 6
[junit4] 2> 3948697 INFO (qtp1937897085-31608) [n:127.0.0.1:54064_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3948698 INFO (qtp1298289486-31616) [n:127.0.0.1:58429_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3948698 INFO (qtp1955971146-31670) [n:127.0.0.1:60345_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3948698 DEBUG (qtp1955971146-31677) [n:127.0.0.1:60345_solr ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 3948699 INFO (qtp1955971146-31677) [n:127.0.0.1:60345_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/cluster/autoscaling params={wt=javabin&version=2} status=0 QTime=3
[junit4] 2> 3948700 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 7
[junit4] 2> 3948700 INFO (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.TriggerIntegrationTest TestTriggerAction init
[junit4] 2> 3948700 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:54064_solr, 127.0.0.1:58429_solr, 127.0.0.1:60345_solr]
[junit4] 2> 3948700 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger2 instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.TriggerIntegrationTest$ThrottlingTesterAction}], enabled=true}
[junit4] 2> 3948700 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3948701 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:54064_solr, 127.0.0.1:58429_solr, 127.0.0.1:60345_solr]
[junit4] 2> 3948701 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger1 instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.TriggerIntegrationTest$ThrottlingTesterAction}], enabled=true}
[junit4] 2> 3948701 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 7, lastZnodeVersion 6
[junit4] 2> 3948701 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 7
[junit4] 2> 3948701 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 3948701 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3948704 INFO (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.TriggerIntegrationTest TestTriggerAction init
[junit4] 2> 3948704 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.e.j.s.Server jetty-9.3.20.v20170531
[junit4] 2> 3948705 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3948705 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 7, lastZnodeVersion 7
[junit4] 2> 3948705 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 3948705 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3948706 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@55dacf4e{/solr,null,AVAILABLE}
[junit4] 2> 3948707 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@5d54764b{HTTP/1.1,[http/1.1]}{127.0.0.1:33919}
[junit4] 2> 3948707 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.e.j.s.Server Started @3953201ms
[junit4] 2> 3948707 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=33919}
[junit4] 2> 3948707 ERROR (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3948707 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 3948707 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3948707 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 3948707 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-12-27T19:39:35.841Z
[junit4] 2> 3948709 INFO (zkConnectionManagerCallback-4805-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3948710 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 3948718 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:34588/solr
[junit4] 2> 3948720 INFO (zkConnectionManagerCallback-4809-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3948723 INFO (zkConnectionManagerCallback-4811-thread-1-processing-n:127.0.0.1:33919_solr) [n:127.0.0.1:33919_solr ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3948733 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [n:127.0.0.1:33919_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3)
[junit4] 2> 3948736 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [n:127.0.0.1:33919_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 3948738 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [n:127.0.0.1:33919_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33919_solr
[junit4] 2> 3948740 INFO (zkCallback-4782-thread-1-processing-n:127.0.0.1:54064_solr) [n:127.0.0.1:54064_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3948742 INFO (zkCallback-4810-thread-1-processing-n:127.0.0.1:33919_solr) [n:127.0.0.1:33919_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3948742 INFO (zkCallback-4800-thread-1-processing-n:127.0.0.1:60345_solr) [n:127.0.0.1:60345_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3948742 INFO (zkCallback-4792-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3948743 INFO (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3948879 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [n:127.0.0.1:33919_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_33919.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@48c04b48
[junit4] 2> 3948885 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [n:127.0.0.1:33919_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_33919.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@48c04b48
[junit4] 2> 3948885 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [n:127.0.0.1:33919_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_33919.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@48c04b48
[junit4] 2> 3948886 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [n:127.0.0.1:33919_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-7.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.autoscaling.TriggerIntegrationTest_98C4F0A068D35A9F-001/tempDir-001/node4/.
[junit4] 2> 3949703 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 3949704 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3949704 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:33919_solr at time 2147036146069577
[junit4] 2> 3949704 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger1 firing registered processor for nodes: [127.0.0.1:33919_solr] added at times [2147036146069577], now=2147036146172633
[junit4] 2> 3949704 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"7a0b7cece7049Tbs5gkwc63xlxd6sdmd1kwv4db",
[junit4] 2> "source":"node_added_trigger1",
[junit4] 2> "eventTime":2147036146069577,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147036146069577],
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3949706 INFO (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.SystemLogListener Collection .system does not exist, disabling logging.
[junit4] 2> 3949706 DEBUG (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"7a0b7cece7049Tbs5gkwc63xlxd6sdmd1kwv4db",
[junit4] 2> "source":"node_added_trigger1",
[junit4] 2> "eventTime":2147036146069577,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147036146069577],
[junit4] 2> "_enqueue_time_":2147036146512691,
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3949706 INFO (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.TriggerIntegrationTest action executed from node_added_trigger1
[junit4] 2> 3949709 DEBUG (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -- processing took 2 ms for event id=7a0b7cece7049Tbs5gkwc63xlxd6sdmd1kwv4db
[junit4] 2> 3950721 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 3950721 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 3950721 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3950721 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:33919_solr at time 2147037163822023
[junit4] 2> 3950721 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger2 firing registered processor for nodes: [127.0.0.1:33919_solr] added at times [2147037163822023], now=2147037163986288
[junit4] 2> 3950721 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3950722 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"7a0b80b781bc7Tbs5gkwc63xlxd6sdmd1kwv4dd",
[junit4] 2> "source":"node_added_trigger2",
[junit4] 2> "eventTime":2147037163822023,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147037163822023],
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3950722 INFO (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.SystemLogListener Collection .system does not exist, disabling logging.
[junit4] 2> 3951737 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 3951737 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3951737 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 3951737 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3951737 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger2 firing registered processor for nodes: [127.0.0.1:33919_solr] added at times [2147037163822023], now=2147038179893926
[junit4] 2> 3951737 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"7a0b80b781bc7Tbs5gkwc63xlxd6sdmd1kwv4df",
[junit4] 2> "source":"node_added_trigger2",
[junit4] 2> "eventTime":2147037163822023,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147037163822023],
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3952741 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 3952741 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 3952741 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3952741 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3952741 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger2 firing registered processor for nodes: [127.0.0.1:33919_solr] added at times [2147037163822023], now=2147039184524364
[junit4] 2> 3952742 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"7a0b80b781bc7Tbs5gkwc63xlxd6sdmd1kwv4dg",
[junit4] 2> "source":"node_added_trigger2",
[junit4] 2> "eventTime":2147037163822023,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147037163822023],
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3953743 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 3953743 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3953743 DEBUG (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 3953743 DEBUG (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3953743 DEBUG (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger2 firing registered processor for nodes: [127.0.0.1:33919_solr] added at times [2147037163822023], now=2147040186742926
[junit4] 2> 3953743 DEBUG (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"7a0b80b781bc7Tbs5gkwc63xlxd6sdmd1kwv4dh",
[junit4] 2> "source":"node_added_trigger2",
[junit4] 2> "eventTime":2147037163822023,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147037163822023],
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3954744 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 3954744 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 3954744 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3954744 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3954744 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger2 firing registered processor for nodes: [127.0.0.1:33919_solr] added at times [2147037163822023], now=2147041188043373
[junit4] 2> 3954745 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"7a0b80b781bc7Tbs5gkwc63xlxd6sdmd1kwv4di",
[junit4] 2> "source":"node_added_trigger2",
[junit4] 2> "eventTime":2147037163822023,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147037163822023],
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3954746 DEBUG (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"7a0b80b781bc7Tbs5gkwc63xlxd6sdmd1kwv4di",
[junit4] 2> "source":"node_added_trigger2",
[junit4] 2> "eventTime":2147037163822023,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147037163822023],
[junit4] 2> "_enqueue_time_":2147041188367959,
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3954747 INFO (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.TriggerIntegrationTest last action at 1514403576840000000 current time = 1514403581880000000
[junit4] 2> real diff: 5040000000
[junit4] 2> min diff: 4998000000
[junit4] 2> 3954747 INFO (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.TriggerIntegrationTest action executed from node_added_trigger2
[junit4] 2> 3954750 DEBUG (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -- processing took 3 ms for event id=7a0b80b781bc7Tbs5gkwc63xlxd6sdmd1kwv4di
[junit4] 2> 3954752 INFO (qtp1573688417-31701) [n:127.0.0.1:33919_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3954754 INFO (qtp1937897085-31618) [n:127.0.0.1:54064_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3954757 INFO (qtp1298289486-31619) [n:127.0.0.1:58429_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3954759 INFO (qtp1955971146-31673) [n:127.0.0.1:60345_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3954760 DEBUG (qtp1955971146-31672) [n:127.0.0.1:60345_solr ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 3954761 INFO (qtp1955971146-31672) [n:127.0.0.1:60345_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/cluster/autoscaling params={wt=javabin&version=2} status=0 QTime=12
[junit4] 2> 3954762 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 8
[junit4] 2> 3954764 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:54064_solr, 127.0.0.1:33919_solr, 127.0.0.1:58429_solr, 127.0.0.1:60345_solr]
[junit4] 2> 3954764 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger2 instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.TriggerIntegrationTest$ThrottlingTesterAction}], enabled=true}
[junit4] 2> 3954765 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:54064_solr, 127.0.0.1:33919_solr, 127.0.0.1:58429_solr, 127.0.0.1:60345_solr]
[junit4] 2> 3954766 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:54064_solr, 127.0.0.1:33919_solr, 127.0.0.1:58429_solr, 127.0.0.1:60345_solr]
[junit4] 2> 3954766 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger1 instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.TriggerIntegrationTest$ThrottlingTesterAction}], enabled=true}
[junit4] 2> 3954766 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 8
[junit4] 2> 3954766 INFO (qtp1573688417-31703) [n:127.0.0.1:33919_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3954768 INFO (qtp1937897085-31617) [n:127.0.0.1:54064_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3954771 INFO (qtp1298289486-31609) [n:127.0.0.1:58429_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3954772 INFO (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.TriggerIntegrationTest TestTriggerAction init
[junit4] 2> 3954773 INFO (qtp1955971146-31675) [n:127.0.0.1:60345_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CORE.coreName&wt=javabin&version=2&group=solr.core} status=0 QTime=0
[junit4] 2> 3954773 DEBUG (qtp1937897085-31620) [n:127.0.0.1:54064_solr ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 3954774 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 8, lastZnodeVersion 8
[junit4] 2> 3954775 INFO (qtp1937897085-31620) [n:127.0.0.1:54064_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/cluster/autoscaling params={wt=javabin&version=2} status=0 QTime=11
[junit4] 2> 3954775 DEBUG (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger1 with currently live nodes: 4
[junit4] 2> 3954776 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 9
[junit4] 2> 3954777 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:54064_solr, 127.0.0.1:33919_solr, 127.0.0.1:58429_solr, 127.0.0.1:60345_solr]
[junit4] 2> 3954777 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger2 instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.TriggerIntegrationTest$ThrottlingTesterAction}], enabled=true}
[junit4] 2> 3954778 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:54064_solr, 127.0.0.1:33919_solr, 127.0.0.1:58429_solr, 127.0.0.1:60345_solr]
[junit4] 2> 3954779 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:54064_solr, 127.0.0.1:33919_solr, 127.0.0.1:58429_solr, 127.0.0.1:60345_solr]
[junit4] 2> 3954779 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger1 instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.TriggerIntegrationTest$ThrottlingTesterAction}], enabled=true}
[junit4] 2> 3954780 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:54064_solr, 127.0.0.1:33919_solr, 127.0.0.1:58429_solr, 127.0.0.1:60345_solr]
[junit4] 2> 3954780 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 9
[junit4] 2> 3954788 INFO (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.TriggerIntegrationTest TestTriggerAction init
[junit4] 2> 3954789 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 9, lastZnodeVersion 9
[junit4] 2> 3954791 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger2 with currently live nodes: 4
[junit4] 2> 3954792 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@5d54764b{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 3954792 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=411375952
[junit4] 2> 3954792 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 3954792 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@36f36df4: rootName = solr_33919, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@111873a
[junit4] 2> 3954802 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 3954802 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@7375684: rootName = solr_33919, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@1e8d67f
[junit4] 2> 3954808 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 3954808 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@75f2c8d3: rootName = solr_33919, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@5cdb696a
[junit4] 2> 3954811 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:33919_solr
[junit4] 2> 3954812 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
[junit4] 2> 3954812 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 3954812 INFO (zkCallback-4810-thread-1-processing-n:127.0.0.1:33919_solr) [n:127.0.0.1:33919_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (3)
[junit4] 2> 3954813 INFO (zkCallback-4792-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (3)
[junit4] 2> 3954813 INFO (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (3)
[junit4] 2> 3954814 INFO (zkCallback-4782-thread-1-processing-n:127.0.0.1:54064_solr) [n:127.0.0.1:54064_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (3)
[junit4] 2> 3954814 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x160997cae2b000e, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 3954814 INFO (zkCallback-4800-thread-1-processing-n:127.0.0.1:60345_solr) [n:127.0.0.1:60345_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (3)
[junit4] 2> 3955745 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 3955746 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3955748 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 3955748 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3955777 DEBUG (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger1 with currently live nodes: 3
[junit4] 2> 3955777 DEBUG (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Tracking lost node: 127.0.0.1:33919_solr
[junit4] 2> 3955777 DEBUG (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger firing registered processor for lost nodes: [127.0.0.1:33919_solr]
[junit4] 2> 3955777 DEBUG (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"7a0b938e1abc1Tbs5gkwc63xlxd6sdmd1kwv4dj",
[junit4] 2> "source":"node_lost_trigger1",
[junit4] 2> "eventTime":2147042220682177,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147042220682177],
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3955778 INFO (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.SystemLogListener Collection .system does not exist, disabling logging.
[junit4] 2> 3955778 DEBUG (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"7a0b938e1abc1Tbs5gkwc63xlxd6sdmd1kwv4dj",
[junit4] 2> "source":"node_lost_trigger1",
[junit4] 2> "eventTime":2147042220682177,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147042220682177],
[junit4] 2> "_enqueue_time_":2147042220859416,
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3955778 INFO (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.TriggerIntegrationTest action executed from node_lost_trigger1
[junit4] 2> 3955779 DEBUG (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -- processing took 1 ms for event id=7a0b938e1abc1Tbs5gkwc63xlxd6sdmd1kwv4dj
[junit4] 2> 3955792 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger2 with currently live nodes: 3
[junit4] 2> 3955792 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Tracking lost node: 127.0.0.1:33919_solr
[junit4] 2> 3955792 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger firing registered processor for lost nodes: [127.0.0.1:33919_solr]
[junit4] 2> 3955792 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"7a0b939ce9c54Tbs5gkwc63xlxd6sdmd1kwv4dl",
[junit4] 2> "source":"node_lost_trigger2",
[junit4] 2> "eventTime":2147042236210260,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147042236210260],
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3955792 INFO (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.SystemLogListener Collection .system does not exist, disabling logging.
[junit4] 2> 3955792 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger processor for lost nodes: [127.0.0.1:33919_solr] is not ready, will try later
[junit4] 2> 3956314 WARN (zkCallback-4810-thread-1-processing-n:127.0.0.1:33919_solr) [n:127.0.0.1:33919_solr ] o.a.s.c.ZkController Unable to register nodeLost path for 127.0.0.1:33919_solr
[junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /autoscaling/nodeLost/127.0.0.1:33919_solr
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:783)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.lambda$create$7(SolrZkClient.java:364)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:60)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.create(SolrZkClient.java:364)
[junit4] 2> at org.apache.solr.cloud.ZkController.lambda$registerLiveNodesListener$2(ZkController.java:879)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.lambda$refreshLiveNodes$1(ZkStateReader.java:704)
[junit4] 2> at java.util.concurrent.ConcurrentHashMap$KeySetView.forEach(ConcurrentHashMap.java:4649)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.refreshLiveNodes(ZkStateReader.java:703)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.access$900(ZkStateReader.java:72)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader$LiveNodeWatcher.refreshAndWatch(ZkStateReader.java:1090)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader$LiveNodeWatcher.process(ZkStateReader.java:1085)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$1.lambda$process$1(SolrZkClient.java:268)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 3956315 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@55dacf4e{/solr,null,UNAVAILABLE}
[junit4] 2> 3956752 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 3956752 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 3956752 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3956752 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3956779 DEBUG (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger1 with currently live nodes: 3
[junit4] 2> 3956793 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger2 with currently live nodes: 3
[junit4] 2> 3956793 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger firing registered processor for lost nodes: [127.0.0.1:33919_solr]
[junit4] 2> 3956794 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"7a0b939ce9c54Tbs5gkwc63xlxd6sdmd1kwv4dn",
[junit4] 2> "source":"node_lost_trigger2",
[junit4] 2> "eventTime":2147042236210260,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147042236210260],
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3956794 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger processor for lost nodes: [127.0.0.1:33919_solr] is not ready, will try later
[junit4] 2> 3957753 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 3957753 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3957753 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 3957753 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3957780 DEBUG (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger1 with currently live nodes: 3
[junit4] 2> 3957794 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger2 with currently live nodes: 3
[junit4] 2> 3957794 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger firing registered processor for lost nodes: [127.0.0.1:33919_solr]
[junit4] 2> 3957794 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"7a0b939ce9c54Tbs5gkwc63xlxd6sdmd1kwv4do",
[junit4] 2> "source":"node_lost_trigger2",
[junit4] 2> "eventTime":2147042236210260,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147042236210260],
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3957794 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger processor for lost nodes: [127.0.0.1:33919_solr] is not ready, will try later
[junit4] 2> 3958754 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 3958754 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 3958754 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3958754 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3958780 DEBUG (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger1 with currently live nodes: 3
[junit4] 2> 3958794 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger2 with currently live nodes: 3
[junit4] 2> 3958795 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger firing registered processor for lost nodes: [127.0.0.1:33919_solr]
[junit4] 2> 3958795 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"7a0b939ce9c54Tbs5gkwc63xlxd6sdmd1kwv4dp",
[junit4] 2> "source":"node_lost_trigger2",
[junit4] 2> "eventTime":2147042236210260,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147042236210260],
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3958795 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger processor for lost nodes: [127.0.0.1:33919_solr] is not ready, will try later
[junit4] 2> 3959755 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 3959756 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 3959756 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3959756 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3959780 DEBUG (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger1 with currently live nodes: 3
[junit4] 2> 3959795 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger2 with currently live nodes: 3
[junit4] 2> 3959795 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger firing registered processor for lost nodes: [127.0.0.1:33919_solr]
[junit4] 2> 3959795 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"7a0b939ce9c54Tbs5gkwc63xlxd6sdmd1kwv4dq",
[junit4] 2> "source":"node_lost_trigger2",
[junit4] 2> "eventTime":2147042236210260,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147042236210260],
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3959795 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger processor for lost nodes: [127.0.0.1:33919_solr] is not ready, will try later
[junit4] 2> 3960757 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 3960757 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 3960757 DEBUG (ScheduledTrigger-11018-thread-1) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3960757 DEBUG (ScheduledTrigger-11018-thread-4) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3960780 DEBUG (ScheduledTrigger-11018-thread-3) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger1 with currently live nodes: 3
[junit4] 2> 3960796 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger2 with currently live nodes: 3
[junit4] 2> 3960796 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger firing registered processor for lost nodes: [127.0.0.1:33919_solr]
[junit4] 2> 3960796 DEBUG (ScheduledTrigger-11018-thread-2) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"7a0b939ce9c54Tbs5gkwc63xlxd6sdmd1kwv4dr",
[junit4] 2> "source":"node_lost_trigger2",
[junit4] 2> "eventTime":2147042236210260,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147042236210260],
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3960797 DEBUG (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"7a0b939ce9c54Tbs5gkwc63xlxd6sdmd1kwv4dr",
[junit4] 2> "source":"node_lost_trigger2",
[junit4] 2> "eventTime":2147042236210260,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2147042236210260],
[junit4] 2> "_enqueue_time_":2147047241146965,
[junit4] 2> "nodeNames":["127.0.0.1:33919_solr"]}}
[junit4] 2> 3960798 INFO (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.TriggerIntegrationTest last action at 1514403582912000000 current time = 1514403587932000000
[junit4] 2> real diff: 5020000000
[junit4] 2> min diff: 4998000000
[junit4] 2> 3960798 INFO (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.TriggerIntegrationTest action executed from node_lost_trigger2
[junit4] 2> 3960798 INFO (TEST-TriggerIntegrationTest.testTriggerThrottling-seed#[98C4F0A068D35A9F]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testTriggerThrottling
[junit4] 2> 3960830 DEBUG (AutoscalingActionExecutor-11019-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.ScheduledTriggers -- processing took 33 ms for event id=7a0b939ce9c54Tbs5gkwc63xlxd6sdmd1kwv4dr
[junit4] 2> 3960961 INFO (TEST-TriggerIntegrationTest.testNodeLostTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNodeLostTriggerRestoreState
[junit4] 2> 3960961 INFO (TEST-TriggerIntegrationTest.testNodeLostTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.a.s.c.a.TriggerIntegrationTest /autoscaling.json reset, new znode version 10
[junit4] 2> 3960962 DEBUG (zkCallback-4780-thread-1-processing-n:127.0.0.1:58429_solr) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 10
[junit4] 2> 3960962 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 10
[junit4] 2> 3960971 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3960971 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 3960972 DEBUG (OverseerAutoScalingTriggerThread-99247952579198981-127.0.0.1:58429_solr-n_0000000000) [n:127.0.0.1:58429_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 10, lastZnodeVersion 10
[junit4] 2> 3960972 INFO (TEST-TriggerIntegrationTest.testNodeLostTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.e.j.s.Server jetty-9.3.20.v20170531
[junit4] 2> 3960973 INFO (TEST-TriggerIntegrationTest.testNodeLostTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@ced492d{/solr,null,AVAILABLE}
[junit4] 2> 3960973 INFO (TEST-TriggerIntegrationTest.testNodeLostTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@b3ebf76{HTTP/1.1,[http/1.1]}{127.0.0.1:38524}
[junit4] 2> 3960973 INFO (TEST-TriggerIntegrationTest.testNodeLostTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.e.j.s.Server Started @3965471ms
[junit4] 2> 3960973 INFO (TEST-TriggerIntegrationTest.testNodeLostTriggerRestoreState-seed#[98C4F0A068D35A9F]) [ ] o.a.s.c.s.e.JettySolrRunne
[...truncated too long message...]
l.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 4122389 INFO (jetty-closer-4765-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@2f5449f1{/solr,null,UNAVAILABLE}
[junit4] 2> 4122393 ERROR (SUITE-TriggerIntegrationTest-seed#[98C4F0A068D35A9F]-worker) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
[junit4] 2> 4122395 INFO (SUITE-TriggerIntegrationTest-seed#[98C4F0A068D35A9F]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:34588 34588
[junit4] 2> 4127624 INFO (Thread-8437) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:34588 34588
[junit4] 2> 4127641 WARN (Thread-8437) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 20 /solr/aliases.json
[junit4] 2> 20 /solr/clusterprops.json
[junit4] 2> 19 /solr/security.json
[junit4] 2> 3 /solr/configs/conf
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 26 /solr/collections/testMetricTrigger/state.json
[junit4] 2> 20 /solr/clusterstate.json
[junit4] 2> 6 /solr/autoscaling.json
[junit4] 2> 3 /solr/overseer_elect/election/99247952579198987-127.0.0.1:60345_solr-n_0000000002
[junit4] 2> 2 /solr/overseer_elect/election/99247952579199005-127.0.0.1:48212_solr-n_0000000008
[junit4] 2> 2 /solr/overseer_elect/election/99247952579199021-127.0.0.1:63784_solr-n_0000000013
[junit4] 2> 2 /solr/overseer_elect/election/99247952579199015-127.0.0.1:65274_solr-n_0000000011
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 20 /solr/live_nodes
[junit4] 2> 20 /solr/collections
[junit4] 2> 6 /solr/overseer/queue-work
[junit4] 2> 6 /solr/autoscaling/events/.auto_add_replicas
[junit4] 2> 6 /solr/overseer/queue
[junit4] 2> 6 /solr/overseer/collection-queue-work
[junit4] 2> 3 /solr/autoscaling/events/node_added_trigger
[junit4] 2> 2 /solr/autoscaling/events/node_lost_trigger
[junit4] 2>
[junit4] 2> NOTE: leaving temporary files on disk at: /export/home/jenkins/workspace/Lucene-Solr-7.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.autoscaling.TriggerIntegrationTest_98C4F0A068D35A9F-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene70): {id=Lucene50(blocksize=128), x_s=PostingsFormat(name=MockRandom)}, docValues:{}, maxPointsInLeafNode=1216, maxMBSortInHeap=5.4596507488744495, sim=RandomSimilarity(queryNorm=true): {}, locale=es, timezone=Africa/Timbuktu
[junit4] 2> NOTE: SunOS 5.11 amd64/Oracle Corporation 1.8.0_152 (64-bit)/cpus=3,threads=1,free=292399688,total=536870912
[junit4] 2> NOTE: All tests run in this JVM: [RuleEngineTest, MultiThreadedOCPTest, ExitableDirectoryReaderTest, QueryResultKeyTest, BadComponentTest, HdfsRecoveryZkTest, TermVectorComponentTest, AnalysisAfterCoreReloadTest, BadCopyFieldTest, TestLMJelinekMercerSimilarityFactory, TestSolrQueryParser, MBeansHandlerTest, DistanceUnitsTest, TestHdfsUpdateLog, TestAuthenticationFramework, InfixSuggestersTest, BufferStoreTest, TestUniqueKeyFieldResource, TestRandomFlRTGCloud, ParsingFieldUpdateProcessorsTest, OutOfBoxZkACLAndCredentialsProvidersTest, TestPKIAuthenticationPlugin, SystemInfoHandlerTest, TestNumericRangeQuery64, TestUtilizeNode, TestMultiWordSynonyms, TestReplicationHandlerBackup, SimpleFacetsTest, BasicZkTest, TestFieldTypeResource, TestCrossCoreJoin, TestCryptoKeys, TestPayloadScoreQParserPlugin, TestRawResponseWriter, TestCharFilters, TestPostingsSolrHighlighter, CollectionsAPIDistributedZkTest, TestPullReplica, TestConfigSetsAPIExclusivity, TestLuceneMatchVersion, ClassificationUpdateProcessorFactoryTest, TestTrie, EchoParamsTest, DocumentAnalysisRequestHandlerTest, TestSolrConfigHandlerConcurrent, DeleteLastCustomShardedReplicaTest, DistributedQueryComponentCustomSortTest, TestCollationField, TestSolrCloudWithKerberosAlt, TestSkipOverseerOperations, TestConfigsApi, LukeRequestHandlerTest, TestInPlaceUpdatesStandalone, DocValuesNotIndexedTest, TestCloudPivotFacet, PolyFieldTest, ZkStateWriterTest, ExternalFileFieldSortTest, TestAnalyzedSuggestions, LeaderInitiatedRecoveryOnCommitTest, TestSimpleTrackingShardHandler, CacheHeaderTest, SuggestComponentContextFilterQueryTest, TestSuggestSpellingConverter, TestMergePolicyConfig, PreAnalyzedFieldTest, TestSimDistributedQueue, TestDistribIDF, ComputePlanActionTest, TestDocSet, TestNodeLostTrigger, TestLegacyFieldCache, CachingDirectoryFactoryTest, DebugComponentTest, WrapperMergePolicyFactoryTest, TestConfig, TestSQLHandlerNonCloud, TestCollapseQParserPlugin, TestNumericTerms64, TestLeaderInitiatedRecoveryThread, TestInitQParser, TestSolrConfigHandler, TestUseDocValuesAsStored, TestRandomFaceting, TestXmlQParser, TestGraphTermsQParserPlugin, JsonLoaderTest, TestQueryTypes, CoreSorterTest, SolrGraphiteReporterTest, ChaosMonkeyNothingIsSafeWithPullReplicasTest, HdfsLockFactoryTest, TermsComponentTest, PeerSyncTest, TestGeoJSONResponseWriter, BigEndianAscendingWordSerializerTest, HdfsBasicDistributedZkTest, SolrPluginUtilsTest, ReplaceNodeTest, ChangedSchemaMergeTest, TestCloudInspectUtil, TestStressLucene, SearchHandlerTest, TestGroupingSearch, FieldMutatingUpdateProcessorTest, SSLMigrationTest, SystemLogListenerTest, TestOrdValues, DocValuesMultiTest, OpenCloseCoreStressTest, TestPartialUpdateDeduplication, SparseHLLTest, PKIAuthenticationIntegrationTest, BaseCdcrDistributedZkTest, TestExclusionRuleCollectionAccess, TestOnReconnectListenerSupport, CustomCollectionTest, TestRTGBase, TestSolrJ, TestDistributedStatsComponentCardinality, ZkFailoverTest, VersionInfoTest, SOLR749Test, SpellPossibilityIteratorTest, CollectionsAPIAsyncDistributedZkTest, TestZkAclsWithHadoopAuth, HLLSerializationTest, TestBadConfig, TestSearchPerf, MergeStrategyTest, RecoveryAfterSoftCommitTest, TestRequestForwarding, LoggingHandlerTest, DOMUtilTest, QueryElevationComponentTest, DistributedMLTComponentTest, HdfsChaosMonkeySafeLeaderTest, DirectSolrSpellCheckerTest, TestComplexPhraseQParserPlugin, SpatialRPTFieldTypeTest, TestExtendedDismaxParser, TestLegacyField, ShardSplitTest, OverseerTaskQueueTest, TestElisionMultitermQuery, AutoscalingHistoryHandlerTest, SoftAutoCommitTest, TestFieldSortValues, TestConfigOverlay, ZkSolrClientTest, TestManagedSchemaThreadSafety, CollectionStateFormat2Test, SimplePostToolTest, TestTolerantUpdateProcessorCloud, TestLeaderElectionWithEmptyReplica, MetricTriggerTest, TestHashPartitioner, TestZkChroot, TestSystemIdResolver, TestLuceneIndexBackCompat, AtomicUpdateProcessorFactoryTest, TestJsonFacets, TestMaxScoreQueryParser, QueryEqualityTest, TestFieldCacheVsDocValues, HttpPartitionTest, TestStressReorder, SpellCheckCollatorWithCollapseTest, TestDocBasedVersionConstraints, TestIndexSearcher, TestFieldCache, TestFieldCacheSort, DateRangeFieldTest, TestClusterStateMutator, TestFastLRUCache, UpdateParamsTest, MissingSegmentRecoveryTest, TestCoreBackup, SolrJmxReporterTest, HdfsTlogReplayBufferedWhileIndexingTest, TestPerFieldSimilarity, GraphQueryTest, TestConfigSetProperties, TestSolr4Spatial2, TestDistributedMissingSort, DocumentBuilderTest, InfoHandlerTest, BasicDistributedZkTest, TestReplicationHandler, TestDistributedGrouping, TestFaceting, TermVectorComponentDistributedTest, ZkControllerTest, TestStressVersions, SolrCoreTest, SolrCmdDistributorTest, TestFunctionQuery, TestLazyCores, SignatureUpdateProcessorFactoryTest, CoreAdminHandlerTest, DocValuesTest, TestRemoteStreaming, DistanceFunctionTest, TestSurroundQueryParser, TestQueryUtils, TestReversedWildcardFilterFactory, FileBasedSpellCheckerTest, RequestHandlersTest, TestValueSourceCache, RequiredFieldsTest, FieldAnalysisRequestHandlerTest, IndexSchemaRuntimeFieldTest, UpdateRequestProcessorFactoryTest, QueryParsingTest, CSVRequestHandlerTest, TestComponentsName, HighlighterConfigTest, TestQuerySenderListener, TestSolrIndexConfig, CopyFieldTest, SolrIndexConfigTest, TestSolrDeletionPolicy2, MultiTermTest, SampleTest, TestBinaryField, NumericFieldsTest, OutputWriterTest, DirectSolrConnectionTest, TestPhraseSuggestions, SynonymTokenizerTest, TestSweetSpotSimilarityFactory, TestDFRSimilarityFactory, TestLMDirichletSimilarityFactory, TestBM25SimilarityFactory, TestFastWriter, ResourceLoaderTest, TestFastOutputStream, ScriptEngineTest, OpenExchangeRatesOrgProviderTest, URLClassifyProcessorTest, PluginInfoTest, PrimUtilsTest, DateFieldTest, SpellingQueryConverterTest, TestLRUCache, TestUtils, TestDocumentBuilder, ZkNodePropsTest, SliceStateTest, UUIDFieldTest, FileUtilsTest, CircularListTest, CursorPagingTest, SolrTestCaseJ4Test, TestJettySolrRunner, ConnectionReuseTest, AliasIntegrationTest, AssignTest, CloudExitableDirectoryReaderTest, ConcurrentDeleteAndCreateCollectionTest, ConfigSetsAPITest, CreateCollectionCleanupTest, DeleteShardTest, DistribCursorPagingTest, DistribJoinFromCollectionTest, DistributedQueueTest, LeaderFailoverAfterPartitionTest, MoveReplicaHDFSTest, SolrCloudExampleTest, TestCloudRecovery, TestDistribDocBasedVersion, TestLeaderElectionZkExpiry, TestLockTree, TestPullReplicaErrorHandling, TestRequestStatusCollectionAPI, TestSolrCloudWithDelegationTokens, TestSolrCloudWithSecureImpersonation, VMParamsZkACLAndCredentialsProvidersTest, AutoScalingHandlerTest, HdfsAutoAddReplicasIntegrationTest, TriggerIntegrationTest]
[junit4] Completed [579/764 (1!)] on J1 in 181.55s, 14 tests, 1 failure, 1 skipped <<< FAILURES!
[...truncated 48758 lines...]