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/17 03:18:59 UTC
[JENKINS] Lucene-Solr-7.x-Solaris (64bit/jdk1.8.0) - Build # 338 -
Still Unstable!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-7.x-Solaris/338/
Java: 64bit/jdk1.8.0 -XX:-UseCompressedOops -XX:+UseParallelGC
1 tests failed.
FAILED: org.apache.solr.cloud.autoscaling.TriggerIntegrationTest.testTriggerThrottling
Error Message:
Both triggers should have fired by now
Stack Trace:
java.lang.AssertionError: Both triggers should have fired by now
at __randomizedtesting.SeedInfo.seed([E2568CD93EF1559E:197424FCEC5BB60C]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.autoscaling.TriggerIntegrationTest.testTriggerThrottling(TriggerIntegrationTest.java:257)
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 13632 lines...]
[junit4] Suite: org.apache.solr.cloud.autoscaling.TriggerIntegrationTest
[junit4] 2> 3717481 INFO (SUITE-TriggerIntegrationTest-seed#[E2568CD93EF1559E]-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/J0/temp/solr.cloud.autoscaling.TriggerIntegrationTest_E2568CD93EF1559E-001/init-core-data-001
[junit4] 2> 3717482 WARN (SUITE-TriggerIntegrationTest-seed#[E2568CD93EF1559E]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=31 numCloses=31
[junit4] 2> 3717482 INFO (SUITE-TriggerIntegrationTest-seed#[E2568CD93EF1559E]-worker) [ ] o.a.s.SolrTestCaseJ4 Using TrieFields (NUMERIC_POINTS_SYSPROP=false) w/NUMERIC_DOCVALUES_SYSPROP=true
[junit4] 2> 3717484 INFO (SUITE-TriggerIntegrationTest-seed#[E2568CD93EF1559E]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, value=NaN, ssl=NaN, clientAuth=NaN)
[junit4] 2> 3717485 INFO (SUITE-TriggerIntegrationTest-seed#[E2568CD93EF1559E]-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/J0/temp/solr.cloud.autoscaling.TriggerIntegrationTest_E2568CD93EF1559E-001/tempDir-001
[junit4] 2> 3717485 INFO (SUITE-TriggerIntegrationTest-seed#[E2568CD93EF1559E]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 3717485 INFO (Thread-6551) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 3717485 INFO (Thread-6551) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 3717490 ERROR (Thread-6551) [ ] 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> 3717590 INFO (SUITE-TriggerIntegrationTest-seed#[E2568CD93EF1559E]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:54860
[junit4] 2> 3717592 INFO (zkConnectionManagerCallback-7891-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3717599 INFO (jetty-launcher-7888-thread-2) [ ] o.e.j.s.Server jetty-9.3.20.v20170531
[junit4] 2> 3717599 INFO (jetty-launcher-7888-thread-1) [ ] o.e.j.s.Server jetty-9.3.20.v20170531
[junit4] 2> 3717602 INFO (jetty-launcher-7888-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@41807d7b{/solr,null,AVAILABLE}
[junit4] 2> 3717602 INFO (jetty-launcher-7888-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@48bc9f13{/solr,null,AVAILABLE}
[junit4] 2> 3717603 INFO (jetty-launcher-7888-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@4f0224a3{SSL,[ssl, http/1.1]}{127.0.0.1:47508}
[junit4] 2> 3717604 INFO (jetty-launcher-7888-thread-2) [ ] o.e.j.s.Server Started @3723085ms
[junit4] 2> 3717604 INFO (jetty-launcher-7888-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=47508}
[junit4] 2> 3717604 INFO (jetty-launcher-7888-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@7afe6e6f{SSL,[ssl, http/1.1]}{127.0.0.1:34600}
[junit4] 2> 3717604 ERROR (jetty-launcher-7888-thread-2) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3717604 INFO (jetty-launcher-7888-thread-1) [ ] o.e.j.s.Server Started @3723086ms
[junit4] 2> 3717604 INFO (jetty-launcher-7888-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 3717604 INFO (jetty-launcher-7888-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=34600}
[junit4] 2> 3717604 INFO (jetty-launcher-7888-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3717605 INFO (jetty-launcher-7888-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 3717605 INFO (jetty-launcher-7888-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-12-17T02:47:00.388Z
[junit4] 2> 3717605 ERROR (jetty-launcher-7888-thread-1) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3717605 INFO (jetty-launcher-7888-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 3717605 INFO (jetty-launcher-7888-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3717605 INFO (jetty-launcher-7888-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 3717605 INFO (jetty-launcher-7888-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-12-17T02:47:00.388Z
[junit4] 2> 3717609 INFO (zkConnectionManagerCallback-7893-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3717609 INFO (zkConnectionManagerCallback-7895-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3717610 INFO (jetty-launcher-7888-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 3717610 INFO (jetty-launcher-7888-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 3717617 INFO (jetty-launcher-7888-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:54860/solr
[junit4] 2> 3717619 INFO (jetty-launcher-7888-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:54860/solr
[junit4] 2> 3717619 INFO (zkConnectionManagerCallback-7900-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3717621 INFO (zkConnectionManagerCallback-7903-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3717622 INFO (zkConnectionManagerCallback-7905-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3717627 INFO (zkConnectionManagerCallback-7907-thread-1-processing-n:127.0.0.1:34600_solr) [n:127.0.0.1:34600_solr ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3717760 INFO (jetty-launcher-7888-thread-2) [n:127.0.0.1:47508_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 3717762 INFO (jetty-launcher-7888-thread-2) [n:127.0.0.1:47508_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:47508_solr
[junit4] 2> 3717763 INFO (jetty-launcher-7888-thread-2) [n:127.0.0.1:47508_solr ] o.a.s.c.Overseer Overseer (id=99187347965345797-127.0.0.1:47508_solr-n_0000000000) starting
[junit4] 2> 3717775 INFO (jetty-launcher-7888-thread-2) [n:127.0.0.1:47508_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47508_solr
[junit4] 2> 3717775 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Adding .autoAddReplicas trigger
[junit4] 2> 3717777 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 3717778 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeLostTrigger Initial livenodes: []
[junit4] 2> 3717778 INFO (OverseerStateUpdate-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 3717778 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion -1
[junit4] 2> 3717778 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 3717781 INFO (zkCallback-7906-thread-1-processing-n:127.0.0.1:34600_solr) [n:127.0.0.1:34600_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 3717782 INFO (jetty-launcher-7888-thread-1) [n:127.0.0.1:34600_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 3717783 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 3717784 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 3717785 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 3717788 INFO (jetty-launcher-7888-thread-1) [n:127.0.0.1:34600_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34600_solr
[junit4] 2> 3717790 INFO (zkCallback-7904-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 3717790 INFO (zkCallback-7906-thread-1-processing-n:127.0.0.1:34600_solr) [n:127.0.0.1:34600_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 3717907 INFO (jetty-launcher-7888-thread-2) [n:127.0.0.1:47508_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_47508.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3717914 INFO (jetty-launcher-7888-thread-2) [n:127.0.0.1:47508_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_47508.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3717914 INFO (jetty-launcher-7888-thread-2) [n:127.0.0.1:47508_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_47508.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3717915 INFO (jetty-launcher-7888-thread-2) [n:127.0.0.1:47508_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/J0/temp/solr.cloud.autoscaling.TriggerIntegrationTest_E2568CD93EF1559E-001/tempDir-001/node2/.
[junit4] 2> 3717940 INFO (jetty-launcher-7888-thread-1) [n:127.0.0.1:34600_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34600.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3717948 INFO (jetty-launcher-7888-thread-1) [n:127.0.0.1:34600_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34600.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3717949 INFO (jetty-launcher-7888-thread-1) [n:127.0.0.1:34600_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34600.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3717950 INFO (jetty-launcher-7888-thread-1) [n:127.0.0.1:34600_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/J0/temp/solr.cloud.autoscaling.TriggerIntegrationTest_E2568CD93EF1559E-001/tempDir-001/node1/.
[junit4] 2> 3717981 INFO (zkConnectionManagerCallback-7913-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3717985 INFO (zkConnectionManagerCallback-7917-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3717986 INFO (SUITE-TriggerIntegrationTest-seed#[E2568CD93EF1559E]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 3717987 INFO (SUITE-TriggerIntegrationTest-seed#[E2568CD93EF1559E]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:54860/solr ready
[junit4] 2> 3718012 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCooldown
[junit4] 2> 3718012 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.c.a.TriggerIntegrationTest /autoscaling.json reset, new znode version 2
[junit4] 2> 3718017 DEBUG (zkCallback-7904-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 3718017 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 2
[junit4] 2> 3718020 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3718021 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 3718021 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 2
[junit4] 2> 3718045 INFO (qtp316838681-33252) [n:127.0.0.1:34600_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> 3718060 INFO (qtp523251706-33254) [n:127.0.0.1:47508_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> 3718060 DEBUG (qtp316838681-33250) [n:127.0.0.1:34600_solr ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 3718061 INFO (qtp316838681-33250) [n:127.0.0.1:34600_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/cluster/autoscaling params={wt=javabin&version=2} status=0 QTime=21
[junit4] 2> 3718062 DEBUG (zkCallback-7904-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 3
[junit4] 2> 3718065 DEBUG (zkCallback-7904-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:34600_solr, 127.0.0.1:47508_solr]
[junit4] 2> 3718065 DEBUG (zkCallback-7904-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_cooldown_trigger instantiated with properties: {event=nodeAdded, waitFor=1, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.TriggerIntegrationTest$TestTriggerAction}], enabled=true}
[junit4] 2> 3718065 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 3
[junit4] 2> 3718068 INFO (qtp316838681-33248) [n:127.0.0.1:34600_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> 3718070 INFO (qtp523251706-33255) [n:127.0.0.1:47508_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> 3718071 DEBUG (qtp316838681-33243) [n:127.0.0.1:34600_solr ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 3718071 INFO (qtp316838681-33243) [n:127.0.0.1:34600_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/cluster/autoscaling params={wt=javabin&version=2} status=0 QTime=7
[junit4] 2> 3718072 INFO (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.TriggerIntegrationTest TestTriggerAction init
[junit4] 2> 3718072 DEBUG (zkCallback-7904-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 4
[junit4] 2> 3718073 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3718073 DEBUG (zkCallback-7904-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:34600_solr, 127.0.0.1:47508_solr]
[junit4] 2> 3718074 DEBUG (zkCallback-7904-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_cooldown_trigger instantiated with properties: {event=nodeAdded, waitFor=1, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.TriggerIntegrationTest$TestTriggerAction}], enabled=true}
[junit4] 2> 3718074 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.Server jetty-9.3.20.v20170531
[junit4] 2> 3718075 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 4, lastZnodeVersion 3
[junit4] 2> 3718075 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 4
[junit4] 2> 3718075 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@412fe853{/solr,null,AVAILABLE}
[junit4] 2> 3718075 DEBUG (ScheduledTrigger-11781-thread-3) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3718076 DEBUG (ScheduledTrigger-11781-thread-3) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 2
[junit4] 2> 3718076 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@7a606128{SSL,[ssl, http/1.1]}{127.0.0.1:60901}
[junit4] 2> 3718076 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.Server Started @3723557ms
[junit4] 2> 3718076 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=60901}
[junit4] 2> 3718076 ERROR (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3718076 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 3718076 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3718076 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 3718076 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3718076 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-12-17T02:47:00.859Z
[junit4] 2> 3718077 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 4, lastZnodeVersion 4
[junit4] 2> 3718078 INFO (zkConnectionManagerCallback-7919-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3718079 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 3718085 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 0x160625e11b00009, 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> 3718087 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:54860/solr
[junit4] 2> 3718088 INFO (zkConnectionManagerCallback-7923-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3718090 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 0x160625e11b0000a, 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> 3718092 INFO (zkConnectionManagerCallback-7925-thread-1-processing-n:127.0.0.1:60901_solr) [n:127.0.0.1:60901_solr ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3718103 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:60901_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 3718107 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:60901_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 3718110 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:60901_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60901_solr
[junit4] 2> 3718112 INFO (zkCallback-7904-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 3718113 INFO (zkCallback-7916-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 3718113 INFO (zkCallback-7924-thread-1-processing-n:127.0.0.1:60901_solr) [n:127.0.0.1:60901_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 3718113 INFO (zkCallback-7906-thread-1-processing-n:127.0.0.1:34600_solr) [n:127.0.0.1:34600_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 3718217 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:60901_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_60901.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3718224 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:60901_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_60901.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3718224 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:60901_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_60901.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3718225 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:60901_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/J0/temp/solr.cloud.autoscaling.TriggerIntegrationTest_E2568CD93EF1559E-001/tempDir-001/node3/.
[junit4] 2> 3719079 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3719079 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3719079 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:60901_solr at time 1221721970842626
[junit4] 2> 3720082 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3720083 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3720083 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_cooldown_trigger firing registered processor for nodes: [127.0.0.1:60901_solr] added at times [1221721970842626], now=1221722975075537
[junit4] 2> 3720083 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"4572650161c02Tbxhx2dum9iok5c9tqj6bf72zp",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221721970842626,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221721970842626],
[junit4] 2> "nodeNames":["127.0.0.1:60901_solr"]}}
[junit4] 2> 3720084 INFO (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.SystemLogListener Collection .system does not exist, disabling logging.
[junit4] 2> 3720084 DEBUG (AutoscalingActionExecutor-11782-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"4572650161c02Tbxhx2dum9iok5c9tqj6bf72zp",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221721970842626,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221721970842626],
[junit4] 2> "_enqueue_time_":1221722975222476,
[junit4] 2> "nodeNames":["127.0.0.1:60901_solr"]}}
[junit4] 2> 3720087 DEBUG (AutoscalingActionExecutor-11782-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -- processing took 2 ms for event id=4572650161c02Tbxhx2dum9iok5c9tqj6bf72zp
[junit4] 2> 3721088 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3721088 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 3721090 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.Server jetty-9.3.20.v20170531
[junit4] 2> 3721092 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@7212d3ac{/solr,null,AVAILABLE}
[junit4] 2> 3721092 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@608658f8{SSL,[ssl, http/1.1]}{127.0.0.1:37299}
[junit4] 2> 3721093 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.Server Started @3726575ms
[junit4] 2> 3721093 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=37299}
[junit4] 2> 3721093 ERROR (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3721093 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 3721093 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3721093 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 3721093 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-12-17T02:47:03.876Z
[junit4] 2> 3721095 INFO (zkConnectionManagerCallback-7929-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3721096 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 3721105 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:54860/solr
[junit4] 2> 3721106 INFO (zkConnectionManagerCallback-7933-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3721109 INFO (zkConnectionManagerCallback-7935-thread-1-processing-n:127.0.0.1:37299_solr) [n:127.0.0.1:37299_solr ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3721117 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:37299_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3)
[junit4] 2> 3721120 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:37299_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 3721123 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:37299_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37299_solr
[junit4] 2> 3721125 INFO (zkCallback-7904-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3721125 INFO (zkCallback-7906-thread-1-processing-n:127.0.0.1:34600_solr) [n:127.0.0.1:34600_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3721126 INFO (zkCallback-7916-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3721126 INFO (zkCallback-7934-thread-1-processing-n:127.0.0.1:37299_solr) [n:127.0.0.1:37299_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3721126 INFO (zkCallback-7924-thread-1-processing-n:127.0.0.1:60901_solr) [n:127.0.0.1:60901_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3721225 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:37299_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_37299.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3721231 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:37299_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_37299.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3721232 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:37299_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_37299.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3721233 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:37299_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/J0/temp/solr.cloud.autoscaling.TriggerIntegrationTest_E2568CD93EF1559E-001/tempDir-001/node4/.
[junit4] 2> 3722089 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3722089 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3722089 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:37299_solr at time 1221724982082741
[junit4] 2> 3723091 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3723091 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3723091 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_cooldown_trigger firing registered processor for nodes: [127.0.0.1:37299_solr] added at times [1221724982082741], now=1221725984369792
[junit4] 2> 3723091 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"457270391fcb5Tbxhx2dum9iok5c9tqj6bf72zr",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221724982082741,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221724982082741],
[junit4] 2> "nodeNames":["127.0.0.1:37299_solr"]}}
[junit4] 2> 3724093 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3724093 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3724093 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_cooldown_trigger firing registered processor for nodes: [127.0.0.1:37299_solr] added at times [1221724982082741], now=1221726986516793
[junit4] 2> 3724093 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"457270391fcb5Tbxhx2dum9iok5c9tqj6bf72zs",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221724982082741,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221724982082741],
[junit4] 2> "nodeNames":["127.0.0.1:37299_solr"]}}
[junit4] 2> 3725094 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3725094 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3725095 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_cooldown_trigger firing registered processor for nodes: [127.0.0.1:37299_solr] added at times [1221724982082741], now=1221727988097288
[junit4] 2> 3725095 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"457270391fcb5Tbxhx2dum9iok5c9tqj6bf72zt",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221724982082741,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221724982082741],
[junit4] 2> "nodeNames":["127.0.0.1:37299_solr"]}}
[junit4] 2> 3725097 DEBUG (AutoscalingActionExecutor-11782-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"457270391fcb5Tbxhx2dum9iok5c9tqj6bf72zt",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221724982082741,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221724982082741],
[junit4] 2> "_enqueue_time_":1221727988299914,
[junit4] 2> "nodeNames":["127.0.0.1:37299_solr"]}}
[junit4] 2> 3725097 INFO (AutoscalingActionExecutor-11782-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.ActionThrottle The last action attempt started 5013ms ago.
[junit4] 2> 3725098 DEBUG (AutoscalingActionExecutor-11782-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -- processing took 1 ms for event id=457270391fcb5Tbxhx2dum9iok5c9tqj6bf72zt
[junit4] 2> 3726099 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3726099 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3727100 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3727100 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 4
[junit4] 2> 3727105 INFO (qtp316838681-33251) [n:127.0.0.1:34600_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> 3727130 INFO (qtp1932318737-33334) [n:127.0.0.1:37299_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> 3727137 INFO (qtp523251706-33256) [n:127.0.0.1:47508_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> 3727159 INFO (qtp1022873552-33308) [n:127.0.0.1:60901_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> 3727159 DEBUG (qtp316838681-33249) [n:127.0.0.1:34600_solr ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 3727159 INFO (qtp316838681-33249) [n:127.0.0.1:34600_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/autoscaling params={wt=javabin&version=2} status=0 QTime=58
[junit4] 2> 3727164 DEBUG (zkCallback-7904-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 5
[junit4] 2> 3727165 DEBUG (zkCallback-7904-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:60901_solr, 127.0.0.1:34600_solr, 127.0.0.1:47508_solr, 127.0.0.1:37299_solr]
[junit4] 2> 3727165 DEBUG (zkCallback-7904-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_cooldown_trigger instantiated with properties: {event=nodeAdded, waitFor=1, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.TriggerIntegrationTest$TestTriggerAction}], enabled=true}
[junit4] 2> 3727165 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 5
[junit4] 2> 3727165 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers Changing value of autoscaling property: triggerCooldownPeriodSeconds from: 5 to: 7
[junit4] 2> 3727166 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3727166 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 5, lastZnodeVersion 5
[junit4] 2> 3727166 INFO (qtp316838681-33253) [n:127.0.0.1:34600_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/autoscaling params={wt=javabin&version=2} status=0 QTime=2
[junit4] 2> 3727168 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.Server jetty-9.3.20.v20170531
[junit4] 2> 3727170 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@2b824fe2{/solr,null,AVAILABLE}
[junit4] 2> 3727170 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@7142becb{SSL,[ssl, http/1.1]}{127.0.0.1:51849}
[junit4] 2> 3727170 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.Server Started @3732654ms
[junit4] 2> 3727170 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=51849}
[junit4] 2> 3727170 ERROR (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3727171 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 3727171 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3727171 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 3727171 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-12-17T02:47:09.954Z
[junit4] 2> 3727173 INFO (zkConnectionManagerCallback-7939-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3727173 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 3727188 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:54860/solr
[junit4] 2> 3727190 INFO (zkConnectionManagerCallback-7943-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3727193 INFO (zkConnectionManagerCallback-7945-thread-1-processing-n:127.0.0.1:51849_solr) [n:127.0.0.1:51849_solr ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3727202 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:51849_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4)
[junit4] 2> 3727205 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:51849_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 3727208 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:51849_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51849_solr
[junit4] 2> 3727210 INFO (zkCallback-7906-thread-1-processing-n:127.0.0.1:34600_solr) [n:127.0.0.1:34600_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 3727210 INFO (zkCallback-7904-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 3727210 INFO (zkCallback-7916-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 3727210 INFO (zkCallback-7944-thread-1-processing-n:127.0.0.1:51849_solr) [n:127.0.0.1:51849_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 3727211 INFO (zkCallback-7934-thread-1-processing-n:127.0.0.1:37299_solr) [n:127.0.0.1:37299_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 3727211 INFO (zkCallback-7924-thread-1-processing-n:127.0.0.1:60901_solr) [n:127.0.0.1:60901_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 3727320 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:51849_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_51849.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3727326 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:51849_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_51849.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3727327 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:51849_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_51849.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3727328 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:51849_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/J0/temp/solr.cloud.autoscaling.TriggerIntegrationTest_E2568CD93EF1559E-001/tempDir-001/node5/.
[junit4] 2> 3728102 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3728102 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 5
[junit4] 2> 3728102 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:51849_solr at time 1221730996048074
[junit4] 2> 3729105 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3729105 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 5
[junit4] 2> 3729105 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_cooldown_trigger firing registered processor for nodes: [127.0.0.1:51849_solr] added at times [1221730996048074], now=1221731999655098
[junit4] 2> 3729105 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"457286a07d0caTbxhx2dum9iok5c9tqj6bf72zu",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221730996048074,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221730996048074],
[junit4] 2> "nodeNames":["127.0.0.1:51849_solr"]}}
[junit4] 2> 3729106 DEBUG (AutoscalingActionExecutor-11782-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"457286a07d0caTbxhx2dum9iok5c9tqj6bf72zu",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221730996048074,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221730996048074],
[junit4] 2> "_enqueue_time_":1221731999790462,
[junit4] 2> "nodeNames":["127.0.0.1:51849_solr"]}}
[junit4] 2> 3729108 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.Server jetty-9.3.20.v20170531
[junit4] 2> 3729109 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@6704b0c{/solr,null,AVAILABLE}
[junit4] 2> 3729109 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@36911d4d{SSL,[ssl, http/1.1]}{127.0.0.1:40461}
[junit4] 2> 3729109 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.Server Started @3734594ms
[junit4] 2> 3729109 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=40461}
[junit4] 2> 3729110 ERROR (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3729110 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 3729110 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3729110 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 3729110 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-12-17T02:47:11.893Z
[junit4] 2> 3729112 INFO (zkConnectionManagerCallback-7949-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3729112 DEBUG (AutoscalingActionExecutor-11782-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -- processing took 6 ms for event id=457286a07d0caTbxhx2dum9iok5c9tqj6bf72zu
[junit4] 2> 3729113 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 3729119 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:54860/solr
[junit4] 2> 3729120 INFO (zkConnectionManagerCallback-7953-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3729123 INFO (zkConnectionManagerCallback-7955-thread-1-processing-n:127.0.0.1:40461_solr) [n:127.0.0.1:40461_solr ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3729130 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:40461_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (5)
[junit4] 2> 3729132 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:40461_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 3729136 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:40461_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40461_solr
[junit4] 2> 3729137 INFO (zkCallback-7906-thread-1-processing-n:127.0.0.1:34600_solr) [n:127.0.0.1:34600_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (5) -> (6)
[junit4] 2> 3729137 INFO (zkCallback-7934-thread-1-processing-n:127.0.0.1:37299_solr) [n:127.0.0.1:37299_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (5) -> (6)
[junit4] 2> 3729138 INFO (zkCallback-7944-thread-1-processing-n:127.0.0.1:51849_solr) [n:127.0.0.1:51849_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (5) -> (6)
[junit4] 2> 3729139 INFO (zkCallback-7916-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (5) -> (6)
[junit4] 2> 3729139 INFO (zkCallback-7924-thread-1-processing-n:127.0.0.1:60901_solr) [n:127.0.0.1:60901_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (5) -> (6)
[junit4] 2> 3729139 INFO (zkCallback-7904-thread-2-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (5) -> (6)
[junit4] 2> 3729140 INFO (zkCallback-7954-thread-1-processing-n:127.0.0.1:40461_solr) [n:127.0.0.1:40461_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (5) -> (6)
[junit4] 2> 3729265 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:40461_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40461.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3729271 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:40461_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40461.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3729272 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:40461_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40461.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3729273 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [n:127.0.0.1:40461_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/J0/temp/solr.cloud.autoscaling.TriggerIntegrationTest_E2568CD93EF1559E-001/tempDir-001/node6/.
[junit4] 2> 3730117 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3730117 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 6
[junit4] 2> 3730117 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:40461_solr at time 1221733011859524
[junit4] 2> 3731119 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3731119 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 6
[junit4] 2> 3731119 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_cooldown_trigger firing registered processor for nodes: [127.0.0.1:40461_solr] added at times [1221733011859524], now=1221734014169278
[junit4] 2> 3731119 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"45728e22ea844Tbxhx2dum9iok5c9tqj6bf72zv",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221733011859524,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221733011859524],
[junit4] 2> "nodeNames":["127.0.0.1:40461_solr"]}}
[junit4] 2> 3732122 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3732122 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 6
[junit4] 2> 3732122 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_cooldown_trigger firing registered processor for nodes: [127.0.0.1:40461_solr] added at times [1221733011859524], now=1221735017223834
[junit4] 2> 3732122 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"45728e22ea844Tbxhx2dum9iok5c9tqj6bf72zw",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221733011859524,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221733011859524],
[junit4] 2> "nodeNames":["127.0.0.1:40461_solr"]}}
[junit4] 2> 3733123 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3733123 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 6
[junit4] 2> 3733124 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_cooldown_trigger firing registered processor for nodes: [127.0.0.1:40461_solr] added at times [1221733011859524], now=1221736019014478
[junit4] 2> 3733124 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"45728e22ea844Tbxhx2dum9iok5c9tqj6bf72zx",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221733011859524,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221733011859524],
[junit4] 2> "nodeNames":["127.0.0.1:40461_solr"]}}
[junit4] 2> 3734125 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3734126 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 6
[junit4] 2> 3734126 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_cooldown_trigger firing registered processor for nodes: [127.0.0.1:40461_solr] added at times [1221733011859524], now=1221737021365453
[junit4] 2> 3734126 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"45728e22ea844Tbxhx2dum9iok5c9tqj6bf72zy",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221733011859524,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221733011859524],
[junit4] 2> "nodeNames":["127.0.0.1:40461_solr"]}}
[junit4] 2> 3735126 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3735127 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 6
[junit4] 2> 3735127 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_cooldown_trigger firing registered processor for nodes: [127.0.0.1:40461_solr] added at times [1221733011859524], now=1221738022791255
[junit4] 2> 3735127 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -------- Cooldown period - rejecting event: {
[junit4] 2> "id":"45728e22ea844Tbxhx2dum9iok5c9tqj6bf72zz",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221733011859524,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221733011859524],
[junit4] 2> "nodeNames":["127.0.0.1:40461_solr"]}}
[junit4] 2> 3736131 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3736131 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 6
[junit4] 2> 3736131 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_cooldown_trigger firing registered processor for nodes: [127.0.0.1:40461_solr] added at times [1221733011859524], now=1221739027228613
[junit4] 2> 3736131 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"45728e22ea844Tbxhx2dum9iok5c9tqj6bf7300",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221733011859524,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221733011859524],
[junit4] 2> "nodeNames":["127.0.0.1:40461_solr"]}}
[junit4] 2> 3736133 DEBUG (AutoscalingActionExecutor-11782-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"45728e22ea844Tbxhx2dum9iok5c9tqj6bf7300",
[junit4] 2> "source":"node_added_cooldown_trigger",
[junit4] 2> "eventTime":1221733011859524,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221733011859524],
[junit4] 2> "_enqueue_time_":1221739027516348,
[junit4] 2> "nodeNames":["127.0.0.1:40461_solr"]}}
[junit4] 2> 3736133 INFO (AutoscalingActionExecutor-11782-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.ActionThrottle The last action attempt started 7028ms ago.
[junit4] 2> 3736135 DEBUG (AutoscalingActionExecutor-11782-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -- processing took 2 ms for event id=45728e22ea844Tbxhx2dum9iok5c9tqj6bf7300
[junit4] 2> 3737140 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3737140 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 6
[junit4] 2> 3738134 INFO (TEST-TriggerIntegrationTest.testCooldown-seed#[E2568CD93EF1559E]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testCooldown
[junit4] 2> 3738141 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_cooldown_trigger
[junit4] 2> 3738141 DEBUG (ScheduledTrigger-11781-thread-1) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 6
[junit4] 2> 3738211 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNodeAddedTriggerRestoreState
[junit4] 2> 3738212 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.a.s.c.a.TriggerIntegrationTest /autoscaling.json reset, new znode version 6
[junit4] 2> 3738212 DEBUG (zkCallback-7904-thread-2-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 6
[junit4] 2> 3738213 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 6
[junit4] 2> 3738214 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3738214 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 3738215 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 6, lastZnodeVersion 6
[junit4] 2> 3738232 INFO (qtp316838681-33252) [n:127.0.0.1:34600_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> 3738236 INFO (qtp1932318737-33337) [n:127.0.0.1:37299_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> 3738251 INFO (qtp939830869-33384) [n:127.0.0.1:40461_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> 3738254 INFO (qtp523251706-33246) [n:127.0.0.1:47508_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> 3738271 INFO (qtp2075236781-33359) [n:127.0.0.1:51849_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> 3738277 INFO (qtp1022873552-33311) [n:127.0.0.1:60901_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> 3738277 DEBUG (qtp2075236781-33362) [n:127.0.0.1:51849_solr ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 3738278 INFO (qtp2075236781-33362) [n:127.0.0.1:51849_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/cluster/autoscaling params={wt=javabin&version=2} status=0 QTime=49
[junit4] 2> 3738279 DEBUG (zkCallback-7904-thread-2-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 7
[junit4] 2> 3738281 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.Server jetty-9.3.20.v20170531
[junit4] 2> 3738282 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@52a2659c{/solr,null,AVAILABLE}
[junit4] 2> 3738283 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@3a27f02f{SSL,[ssl, http/1.1]}{127.0.0.1:44988}
[junit4] 2> 3738283 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.e.j.s.Server Started @3743769ms
[junit4] 2> 3738283 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=44988}
[junit4] 2> 3738283 ERROR (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3738283 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 3738283 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3738283 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 3738283 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-12-17T02:47:21.066Z
[junit4] 2> 3738287 DEBUG (zkCallback-7904-thread-2-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:51849_solr, 127.0.0.1:60901_solr, 127.0.0.1:40461_solr, 127.0.0.1:34600_solr, 127.0.0.1:47508_solr, 127.0.0.1:37299_solr]
[junit4] 2> 3738287 DEBUG (zkCallback-7904-thread-2-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_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> 3738288 INFO (zkConnectionManagerCallback-7959-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3738288 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 7
[junit4] 2> 3738289 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 3738295 INFO (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.TriggerIntegrationTest TestTriggerAction init
[junit4] 2> 3738295 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3738296 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 7, lastZnodeVersion 7
[junit4] 2> 3738296 DEBUG (ScheduledTrigger-11781-thread-4) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_restore_trigger
[junit4] 2> 3738296 DEBUG (ScheduledTrigger-11781-thread-4) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 6
[junit4] 2> 3738299 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:54860/solr
[junit4] 2> 3738301 INFO (zkConnectionManagerCallback-7963-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3738303 INFO (zkConnectionManagerCallback-7965-thread-1-processing-n:127.0.0.1:44988_solr) [n:127.0.0.1:44988_solr ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3738311 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [n:127.0.0.1:44988_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (6)
[junit4] 2> 3738316 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [n:127.0.0.1:44988_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 3738319 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [n:127.0.0.1:44988_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44988_solr
[junit4] 2> 3738324 INFO (zkCallback-7924-thread-1-processing-n:127.0.0.1:60901_solr) [n:127.0.0.1:60901_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (6) -> (7)
[junit4] 2> 3738325 INFO (zkCallback-7944-thread-1-processing-n:127.0.0.1:51849_solr) [n:127.0.0.1:51849_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (6) -> (7)
[junit4] 2> 3738325 INFO (zkCallback-7934-thread-1-processing-n:127.0.0.1:37299_solr) [n:127.0.0.1:37299_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (6) -> (7)
[junit4] 2> 3738325 INFO (zkCallback-7916-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (6) -> (7)
[junit4] 2> 3738325 INFO (zkCallback-7964-thread-1-processing-n:127.0.0.1:44988_solr) [n:127.0.0.1:44988_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (6) -> (7)
[junit4] 2> 3738325 INFO (zkCallback-7904-thread-2-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (6) -> (7)
[junit4] 2> 3738326 INFO (zkCallback-7954-thread-1-processing-n:127.0.0.1:40461_solr) [n:127.0.0.1:40461_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (6) -> (7)
[junit4] 2> 3738326 INFO (zkCallback-7906-thread-1-processing-n:127.0.0.1:34600_solr) [n:127.0.0.1:34600_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (6) -> (7)
[junit4] 2> 3738466 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [n:127.0.0.1:44988_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_44988.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3738473 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [n:127.0.0.1:44988_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_44988.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3738473 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [n:127.0.0.1:44988_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_44988.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@30736a14
[junit4] 2> 3738474 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [n:127.0.0.1:44988_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/J0/temp/solr.cloud.autoscaling.TriggerIntegrationTest_E2568CD93EF1559E-001/tempDir-001/node7/.
[junit4] 2> 3739298 DEBUG (ScheduledTrigger-11781-thread-4) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_restore_trigger
[junit4] 2> 3739298 DEBUG (ScheduledTrigger-11781-thread-4) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 7
[junit4] 2> 3739298 DEBUG (ScheduledTrigger-11781-thread-4) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:44988_solr at time 1221742195152505
[junit4] 2> 3740031 INFO (qtp316838681-33243) [n:127.0.0.1:34600_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> 3740035 INFO (qtp1932318737-33338) [n:127.0.0.1:37299_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> 3740039 INFO (qtp939830869-33386) [n:127.0.0.1:40461_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> 3740062 INFO (qtp1778831141-33415) [n:127.0.0.1:44988_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> 3740064 INFO (qtp523251706-33254) [n:127.0.0.1:47508_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> 3740067 INFO (qtp2075236781-33363) [n:127.0.0.1:51849_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> 3740072 INFO (qtp1022873552-33304) [n:127.0.0.1:60901_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> 3740072 DEBUG (qtp316838681-33248) [n:127.0.0.1:34600_solr ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 3740073 INFO (qtp316838681-33248) [n:127.0.0.1:34600_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/cluster/autoscaling params={wt=javabin&version=2} status=0 QTime=46
[junit4] 2> 3740074 DEBUG (zkCallback-7904-thread-2-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 8
[junit4] 2> 3740074 DEBUG (zkCallback-7904-thread-2-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:51849_solr, 127.0.0.1:60901_solr, 127.0.0.1:40461_solr, 127.0.0.1:34600_solr, 127.0.0.1:47508_solr, 127.0.0.1:44988_solr, 127.0.0.1:37299_solr]
[junit4] 2> 3740074 DEBUG (zkCallback-7904-thread-2-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_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> 3740075 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 8
[junit4] 2> 3740076 INFO (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.TriggerIntegrationTest TestTriggerAction init
[junit4] 2> 3740076 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Adding node from marker path: 127.0.0.1:44988_solr
[junit4] 2> 3740077 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3740077 DEBUG (ScheduledTrigger-11781-thread-2) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_restore_trigger
[junit4] 2> 3740077 DEBUG (ScheduledTrigger-11781-thread-2) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 7
[junit4] 2> 3740077 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 8, lastZnodeVersion 8
[junit4] 2> 3740078 DEBUG (ScheduledTrigger-11781-thread-2) [n:127.0.0.1:47508_solr ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_restore_trigger firing registered processor for nodes: [127.0.0.1:44988_solr] added at times [1221742973662805], now=1221742974758005
[junit4] 2> 3740078 DEBUG (ScheduledTrigger-11781-thread-2) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"4572b33f3b655Tbxhx2dum9iok5c9tqj6bf7301",
[junit4] 2> "source":"node_added_restore_trigger",
[junit4] 2> "eventTime":1221742973662805,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221742973662805],
[junit4] 2> "nodeNames":["127.0.0.1:44988_solr"]}}
[junit4] 2> 3740079 INFO (ScheduledTrigger-11781-thread-2) [n:127.0.0.1:47508_solr ] o.a.s.c.a.SystemLogListener Collection .system does not exist, disabling logging.
[junit4] 2> 3740079 DEBUG (AutoscalingActionExecutor-11782-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"4572b33f3b655Tbxhx2dum9iok5c9tqj6bf7301",
[junit4] 2> "source":"node_added_restore_trigger",
[junit4] 2> "eventTime":1221742973662805,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[1221742973662805],
[junit4] 2> "_enqueue_time_":1221742975002878,
[junit4] 2> "nodeNames":["127.0.0.1:44988_solr"]}}
[junit4] 2> 3740079 INFO (TEST-TriggerIntegrationTest.testNodeAddedTriggerRestoreState-seed#[E2568CD93EF1559E]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testNodeAddedTriggerRestoreState
[junit4] 2> 3740094 DEBUG (AutoscalingActionExecutor-11782-thread-1-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.ScheduledTriggers -- processing took 15 ms for event id=4572b33f3b655Tbxhx2dum9iok5c9tqj6bf7301
[junit4] 2> 3740161 INFO (TEST-TriggerIntegrationTest.testEventFromRestoredState-seed#[E2568CD93EF1559E]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testEventFromRestoredState
[junit4] 2> 3740162 INFO (TEST-TriggerIntegrationTest.testEventFromRestoredState-seed#[E2568CD93EF1559E]) [ ] o.a.s.c.a.TriggerIntegrationTest /autoscaling.json reset, new znode version 9
[junit4] 2> 3740162 DEBUG (zkCallback-7904-thread-2-processing-n:127.0.0.1:47508_solr) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 9
[junit4] 2> 3740162 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 9
[junit4] 2> 3740165 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 3740166 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 3740166 DEBUG (OverseerAutoScalingTriggerThread-99187347965345797-127.0.0.1:47508_solr-n_0000000000) [n:127.0.0.1:47508_solr ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 9, lastZnodeVersion 9
[junit4] 2> 3740171 INFO (qtp316838681-33249) [n:127.0.0.1:34600_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> 3740174 INFO (qtp1932318737-33335) [n:127.0.0.1:37299_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> 3740177 INFO (qtp939830869-33382) [n:127.0.0.1:40461_solr ] o.a.s.s.HttpSol
[...truncated too long message...]
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> 3890366 INFO (jetty-closer-7889-thread-8) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@d003032{/solr,null,UNAVAILABLE}
[junit4] 2> 3890371 ERROR (SUITE-TriggerIntegrationTest-seed#[E2568CD93EF1559E]-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> 3890373 INFO (SUITE-TriggerIntegrationTest-seed#[E2568CD93EF1559E]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:54860 54860
[junit4] 2> 3900511 INFO (Thread-6551) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:54860 54860
[junit4] 2> 3900512 WARN (Thread-6551) [ ] 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> 19 /solr/security.json
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 20 /solr/clusterprops.json
[junit4] 2> 20 /solr/clusterstate.json
[junit4] 2> 6 /solr/autoscaling.json
[junit4] 2> 3 /solr/overseer_elect/election/99187347965345830-127.0.0.1:40024_solr-n_0000000011
[junit4] 2> 2 /solr/overseer_elect/election/99187347965345827-127.0.0.1:48978_solr-n_0000000010
[junit4] 2> 2 /solr/overseer_elect/election/99187347965345845-127.0.0.1:62533_solr-n_0000000016
[junit4] 2> 2 /solr/overseer_elect/election/99187347965345812-127.0.0.1:40461_solr-n_0000000005
[junit4] 2> 2 /solr/overseer_elect/election/99187347965345815-127.0.0.1:44988_solr-n_0000000006
[junit4] 2> 2 /solr/overseer_elect/election/99187347965345842-127.0.0.1:44114_solr-n_0000000015
[junit4] 2> 2 /solr/overseer_elect/election/99187347965345818-127.0.0.1:48228_solr-n_0000000007
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 20 /solr/collections
[junit4] 2> 19 /solr/live_nodes
[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_added_trigger1
[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/J0/temp/solr.cloud.autoscaling.TriggerIntegrationTest_E2568CD93EF1559E-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene70): {}, docValues:{}, maxPointsInLeafNode=1807, maxMBSortInHeap=7.4406063392543915, sim=RandomSimilarity(queryNorm=false): {}, locale=es-EC, timezone=Africa/Windhoek
[junit4] 2> NOTE: SunOS 5.11 amd64/Oracle Corporation 1.8.0_152 (64-bit)/cpus=3,threads=1,free=147584584,total=509607936
[junit4] 2> NOTE: All tests run in this JVM: [TestDistribIDF, DateRangeFieldTest, TestQuerySenderNoQuery, TestRestManager, TestStressUserVersions, TestLocalFSCloudBackupRestore, SolrCmdDistributorTest, TestNestedDocsSort, PathHierarchyTokenizerFactoryTest, TestOmitPositions, TestGeoJSONResponseWriter, DistributedSpellCheckComponentTest, TestTolerantSearch, SolrGraphiteReporterTest, DistributedQueryComponentCustomSortTest, TestQuerySenderListener, SmileWriterTest, TestConfigSetProperties, DistanceUnitsTest, BlockCacheTest, TestReplicationHandler, CdcrReplicationHandlerTest, TestLFUCache, FastVectorHighlighterTest, TestStressInPlaceUpdates, TestComplexPhraseQParserPlugin, SuggesterTest, ChaosMonkeySafeLeaderWithPullReplicasTest, TestPhraseSuggestions, ResourceLoaderTest, TestCollectionAPI, TestCorePropertiesReload, BlockJoinFacetRandomTest, TestDynamicLoading, TestWriterPerf, InfixSuggestersTest, TestImpersonationWithHadoopAuth, OutputWriterTest, TestJmxIntegration, TestNumericRangeQuery64, TestChildDocTransformer, SolrJmxReporterTest, TestHttpShardHandlerFactory, SpellCheckCollatorTest, TestComputePlanAction, TestFreeTextSuggestions, OverseerStatusTest, AnalyticsMergeStrategyTest, TestSha256AuthenticationProvider, TestCoreBackup, TestFieldTypeResource, TestSolrConfigHandlerConcurrent, TestXIncludeConfig, SortSpecParsingTest, TestSimpleQParserPlugin, CollectionReloadTest, TestSolrFieldCacheBean, LeaderFailureAfterFreshStartTest, MinimalSchemaTest, CursorPagingTest, BigEndianAscendingWordSerializerTest, BJQParserTest, TestReversedWildcardFilterFactory, PropertiesRequestHandlerTest, HLLSerializationTest, TestCloudJSONFacetJoinDomain, TestStreamBody, TestPayloadScoreQParserPlugin, DistributedQueryElevationComponentTest, TestDocBasedVersionConstraints, BasicDistributedZkTest, MergeStrategyTest, TestUtils, HdfsRecoveryZkTest, SuggesterTSTTest, TestBlobHandler, DistributedVersionInfoTest, TestManagedSchema, TestSQLHandlerNonCloud, DistributedFacetSimpleRefinementLongTailTest, TestSolrCoreProperties, ZkCLITest, CdcrVersionReplicationTest, TestEmbeddedSolrServerAdminHandler, ClassificationUpdateProcessorTest, AsyncCallRequestStatusResponseTest, BasicAuthIntegrationTest, DistributedFacetExistsSmallTest, HighlighterTest, HighlighterConfigTest, TestMiniSolrCloudClusterSSL, HdfsWriteToMultipleCollectionsTest, TestSurroundQueryParser, LeaderElectionTest, CoreAdminRequestStatusTest, TestConfigSetsAPI, AtomicUpdateProcessorFactoryTest, TestReplicationHandlerBackup, TestRequestStatusCollectionAPI, SolrXmlInZkTest, CSVRequestHandlerTest, ParsingFieldUpdateProcessorsTest, SolrTestCaseJ4Test, TestLeaderElectionZkExpiry, SharedFSAutoReplicaFailoverTest, CircularListTest, TestXmlQParser, PeerSyncReplicationTest, TestPseudoReturnFields, TestMaxTokenLenTokenizer, ClusterStateTest, BadCopyFieldTest, ConnectionReuseTest, TestApiFramework, SparseHLLTest, ForceLeaderTest, TestClusterStateMutator, TestPKIAuthenticationPlugin, TestJsonFacets, DistributedSuggestComponentTest, DeleteInactiveReplicaTest, TestScoreJoinQPScore, DistanceFunctionTest, WordBreakSolrSpellCheckerTest, BinaryUpdateRequestHandlerTest, TestManagedSchemaThreadSafety, TestMacros, DirectUpdateHandlerOptimizeTest, DistributedDebugComponentTest, DistributedTermsComponentTest, TestCoreDiscovery, PrimUtilsTest, ChaosMonkeyNothingIsSafeTest, QueryResultKeyTest, ConfigSetsAPITest, TestTolerantUpdateProcessorRandomCloud, DistributedFacetPivotLongTailTest, TestDFRSimilarityFactory, PeerSyncWithIndexFingerprintCachingTest, TestSchemaVersionResource, TestFieldCacheSort, LeaderInitiatedRecoveryOnShardRestartTest, TlogReplayBufferedWhileIndexingTest, HdfsTlogReplayBufferedWhileIndexingTest, ExitableDirectoryReaderTest, TestManagedSynonymFilterFactory, BlobRepositoryCloudTest, TestFieldSortValues, TestOverriddenPrefixQueryForCustomFieldType, TestIndexingPerformance, ShowFileRequestHandlerTest, TestCustomDocTransformer, HdfsSyncSliceTest, ShardRoutingTest, TestReRankQParserPlugin, TestRealTimeGet, TestDownShardTolerantSearch, GraphQueryTest, DateMathParserTest, UUIDFieldTest, AddReplicaTest, TestUpdate, IndexSchemaTest, TestUniqueKeyFieldResource, DeleteNodeTest, TestCloudDeleteByQuery, TestManagedResource, TestTrackingShardHandlerFactory, HighlighterMaxOffsetTest, TestMultiValuedNumericRangeQuery, NumericFieldsTest, UniqFieldsUpdateProcessorFactoryTest, TestNodeLostTrigger, TestGraphTermsQParserPlugin, SystemLogListenerTest, TestBlendedInfixSuggestions, ExecutePlanActionTest, TestShardHandlerFactory, TestSizeLimitedDistributedMap, ZkControllerTest, FieldAnalysisRequestHandlerTest, XmlUpdateRequestHandlerTest, RemoteQueryErrorTest, RuleEngineTest, TestCollapseQParserPlugin, HdfsNNFailoverTest, ChaosMonkeySafeLeaderTest, UnloadDistributedZkTest, SyncSliceTest, OverseerTest, BasicZkTest, FullSolrCloudDistribCmdsTest, TestFaceting, TestRecovery, TestHashPartitioner, TermVectorComponentDistributedTest, TestReload, TestRangeQuery, StatsComponentTest, ConvertedLegacyTest, TestFiltering, DirectUpdateHandlerTest, SoftAutoCommitTest, AssignBackwardCompatibilityTest, CreateCollectionCleanupTest, CustomCollectionTest, DeleteLastCustomShardedReplicaTest, DeleteReplicaTest, DeleteStatusTest, DistribDocExpirationUpdateProcessorTest, DocValuesNotIndexedTest, LeaderElectionContextKeyTest, LegacyCloudClusterPropTest, MigrateRouteKeyTest, MoveReplicaTest, MultiThreadedOCPTest, OverseerCollectionConfigSetProcessorTest, OverseerModifyCollectionTest, ReplicationFactorTest, RollingRestartTest, SolrCLIZkUtilsTest, TestCloudPivotFacet, TestCloudPseudoReturnFields, TestClusterProperties, TestCollectionsAPIViaSolrCloudCluster, TestConfigSetsAPIZkFailure, TestCryptoKeys, TestExclusionRuleCollectionAccess, TestHdfsCloudBackupRestore, TestPrepRecovery, TestRandomRequestDistribution, TestRebalanceLeaders, TestSSLRandomization, TestSegmentSorting, TestSolrCloudWithSecureImpersonation, TestStressLiveNodes, TestTlogReplica, AutoAddReplicasIntegrationTest, HttpTriggerListenerTest, NodeLostTriggerTest, TestPolicyCloud, TriggerIntegrationTest]
[junit4] Completed [596/763 (1!)] on J0 in 183.07s, 13 tests, 1 failure, 1 skipped <<< FAILURES!
[...truncated 48646 lines...]
[JENKINS] Lucene-Solr-7.x-Solaris (64bit/jdk1.8.0) - Build # 339 -
Still Unstable!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-7.x-Solaris/339/
Java: 64bit/jdk1.8.0 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
2 tests failed.
FAILED: org.apache.solr.cloud.autoscaling.sim.TestDistribStateManager.testGetSetRemoveData
Error Message:
Node watch should have fired!
Stack Trace:
java.lang.AssertionError: Node watch should have fired!
at __randomizedtesting.SeedInfo.seed([F2373428F8C0E3A8:D4A7DB7AAC4E25A2]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.autoscaling.sim.TestDistribStateManager.testGetSetRemoveData(TestDistribStateManager.java:256)
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)
FAILED: org.apache.solr.cloud.autoscaling.sim.TestPolicyCloud.testCreateCollectionSplitShard
Error Message:
Timed out waiting to see 6 replicas for collection: testCreateCollectionSplitShard Live Nodes: null Last available state: null
Stack Trace:
java.lang.AssertionError: Timed out waiting to see 6 replicas for collection: testCreateCollectionSplitShard
Live Nodes: null
Last available state: null
at __randomizedtesting.SeedInfo.seed([F2373428F8C0E3A8:27B947D3488A6216]:0)
at org.apache.solr.cloud.autoscaling.sim.SimSolrCloudTestCase.waitForState(SimSolrCloudTestCase.java:147)
at org.apache.solr.cloud.autoscaling.sim.TestPolicyCloud.testCreateCollectionSplitShard(TestPolicyCloud.java:164)
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 org.junit.rules.ExpectedException$ExpectedExceptionStatement.evaluate(ExpectedException.java:110)
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)
Caused by: java.io.IOException: org.apache.solr.client.solrj.cloud.autoscaling.BadVersionException: /clusterstate.json
at org.apache.solr.cloud.autoscaling.sim.SimClusterStateProvider.saveClusterState(SimClusterStateProvider.java:494)
at org.apache.solr.cloud.autoscaling.sim.SimClusterStateProvider.getClusterState(SimClusterStateProvider.java:1192)
at org.apache.solr.cloud.autoscaling.sim.SimSolrCloudTestCase.waitForState(SimSolrCloudTestCase.java:171)
at org.apache.solr.cloud.autoscaling.sim.SimSolrCloudTestCase.waitForState(SimSolrCloudTestCase.java:141)
... 41 more
Caused by: org.apache.solr.client.solrj.cloud.autoscaling.BadVersionException: /clusterstate.json
at org.apache.solr.cloud.autoscaling.sim.SimDistribStateManager$Node.setData(SimDistribStateManager.java:114)
at org.apache.solr.cloud.autoscaling.sim.SimDistribStateManager.setData(SimDistribStateManager.java:502)
at org.apache.solr.cloud.autoscaling.sim.SimClusterStateProvider.saveClusterState(SimClusterStateProvider.java:490)
... 44 more
Build Log:
[...truncated 11985 lines...]
[junit4] Suite: org.apache.solr.cloud.autoscaling.sim.TestDistribStateManager
[junit4] 2> 637580 INFO (SUITE-TestDistribStateManager-seed#[F2373428F8C0E3A8]-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.sim.TestDistribStateManager_F2373428F8C0E3A8-001/init-core-data-001
[junit4] 2> 637581 WARN (SUITE-TestDistribStateManager-seed#[F2373428F8C0E3A8]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=13 numCloses=13
[junit4] 2> 637581 INFO (SUITE-TestDistribStateManager-seed#[F2373428F8C0E3A8]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=true
[junit4] 2> 637582 INFO (SUITE-TestDistribStateManager-seed#[F2373428F8C0E3A8]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, value=NaN, ssl=NaN, clientAuth=NaN)
[junit4] 2> 637584 INFO (TEST-TestDistribStateManager.testGetSetRemoveData-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testGetSetRemoveData
[junit4] 2> 637584 INFO (TEST-TestDistribStateManager.testGetSetRemoveData-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 637584 INFO (Thread-731) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 637584 INFO (Thread-731) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 637586 ERROR (Thread-731) [ ] 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> 637684 INFO (TEST-TestDistribStateManager.testGetSetRemoveData-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.ZkTestServer start zk server on port:59842
[junit4] 2> 637687 INFO (zkConnectionManagerCallback-925-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 637688 INFO (TEST-TestDistribStateManager.testGetSetRemoveData-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.TestDistribStateManager Using org.apache.solr.client.solrj.impl.ZkDistribStateManager
[junit4] 2> 637697 INFO (zkConnectionManagerCallback-927-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 637697 INFO (TEST-TestDistribStateManager.testGetSetRemoveData-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.TestDistribStateManager Using org.apache.solr.client.solrj.impl.ZkDistribStateManager
[junit4] 2> 642702 ERROR (TEST-TestDistribStateManager.testGetSetRemoveData-seed#[F2373428F8C0E3A8]) [ ] 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> 642703 INFO (TEST-TestDistribStateManager.testGetSetRemoveData-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:59842 59842
[junit4] 2> 647757 INFO (Thread-731) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:59842 59842
[junit4] 2> 647760 INFO (TEST-TestDistribStateManager.testGetSetRemoveData-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testGetSetRemoveData
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestDistribStateManager -Dtests.method=testGetSetRemoveData -Dtests.seed=F2373428F8C0E3A8 -Dtests.slow=true -Dtests.locale=en-MT -Dtests.timezone=Asia/Manila -Dtests.asserts=true -Dtests.file.encoding=US-ASCII
[junit4] FAILURE 10.2s J1 | TestDistribStateManager.testGetSetRemoveData <<<
[junit4] > Throwable #1: java.lang.AssertionError: Node watch should have fired!
[junit4] > at __randomizedtesting.SeedInfo.seed([F2373428F8C0E3A8:D4A7DB7AAC4E25A2]:0)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.TestDistribStateManager.testGetSetRemoveData(TestDistribStateManager.java:256)
[junit4] > at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 647765 INFO (TEST-TestDistribStateManager.testListData-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testListData
[junit4] 2> 647765 INFO (TEST-TestDistribStateManager.testListData-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.TestDistribStateManager Using org.apache.solr.cloud.autoscaling.sim.SimDistribStateManager
[junit4] 2> 647766 INFO (TEST-TestDistribStateManager.testListData-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testListData
[junit4] 2> 647767 INFO (TEST-TestDistribStateManager.testMulti-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testMulti
[junit4] 2> 647767 INFO (TEST-TestDistribStateManager.testMulti-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.TestDistribStateManager Using org.apache.solr.cloud.autoscaling.sim.SimDistribStateManager
[junit4] 2> 647767 INFO (TEST-TestDistribStateManager.testMulti-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testMulti
[junit4] 2> 647769 INFO (TEST-TestDistribStateManager.testCreateMode-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreateMode
[junit4] 2> 647770 INFO (TEST-TestDistribStateManager.testCreateMode-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 647770 INFO (Thread-732) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 647770 INFO (Thread-732) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 647772 ERROR (Thread-732) [ ] 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> 647876 INFO (TEST-TestDistribStateManager.testCreateMode-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.ZkTestServer start zk server on port:64407
[junit4] 2> 647879 INFO (zkConnectionManagerCallback-929-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 647879 INFO (TEST-TestDistribStateManager.testCreateMode-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.TestDistribStateManager Using org.apache.solr.client.solrj.impl.ZkDistribStateManager
[junit4] 2> 647907 INFO (zkConnectionManagerCallback-931-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 647907 INFO (TEST-TestDistribStateManager.testCreateMode-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.TestDistribStateManager Using org.apache.solr.client.solrj.impl.ZkDistribStateManager
[junit4] 2> 647914 ERROR (TEST-TestDistribStateManager.testCreateMode-seed#[F2373428F8C0E3A8]) [ ] 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> 647916 INFO (TEST-TestDistribStateManager.testCreateMode-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:64407 64407
[junit4] 2> 650649 INFO (Thread-732) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:64407 64407
[junit4] 2> 650652 INFO (TEST-TestDistribStateManager.testCreateMode-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testCreateMode
[junit4] 2> 650654 INFO (TEST-TestDistribStateManager.testHasData-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testHasData
[junit4] 2> 650655 INFO (TEST-TestDistribStateManager.testHasData-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.TestDistribStateManager Using org.apache.solr.cloud.autoscaling.sim.SimDistribStateManager
[junit4] 2> 650655 INFO (TEST-TestDistribStateManager.testHasData-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testHasData
[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.sim.TestDistribStateManager_F2373428F8C0E3A8-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene70), sim=RandomSimilarity(queryNorm=false): {}, locale=en-MT, timezone=Asia/Manila
[junit4] 2> NOTE: SunOS 5.11 amd64/Oracle Corporation 1.8.0_152 (64-bit)/cpus=3,threads=1,free=154325608,total=371945472
[junit4] 2> NOTE: All tests run in this JVM: [TestSolrIndexConfig, TestDocTermOrds, TestPivotHelperCode, TestCloudSchemaless, ReplaceNodeTest, CollectionsAPIDistributedZkTest, SolrCoreTest, TestQueryUtils, LeaderElectionIntegrationTest, TestExpandComponent, SearchHandlerTest, TestCoreAdminApis, BasicDistributedZk2Test, TestUtilizeNode, TestManagedSchemaAPI, TestBM25SimilarityFactory, BitVectorTest, OpenCloseCoreStressTest, SearchRateTriggerTest, CollectionsAPIAsyncDistributedZkTest, UtilsToolTest, TestNodeAddedTrigger, SolrJmxReporterCloudTest, MetricsHandlerTest, CdcrBidirectionalTest, BasicAuthStandaloneTest, DistributedFacetPivotSmallAdvancedTest, CoreAdminCreateDiscoverTest, TestElisionMultitermQuery, NumberUtilsTest, RulesTest, TestDistribStateManager]
[junit4] Completed [112/763 (1!)] on J1 in 13.09s, 5 tests, 1 failure <<< FAILURES!
[...truncated 1541 lines...]
[junit4] Suite: org.apache.solr.cloud.autoscaling.sim.TestPolicyCloud
[junit4] 2> 4011768 INFO (SUITE-TestPolicyCloud-seed#[F2373428F8C0E3A8]-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.sim.TestPolicyCloud_F2373428F8C0E3A8-001/init-core-data-001
[junit4] 2> 4011769 INFO (SUITE-TestPolicyCloud-seed#[F2373428F8C0E3A8]-worker) [ ] o.a.s.SolrTestCaseJ4 Using TrieFields (NUMERIC_POINTS_SYSPROP=false) w/NUMERIC_DOCVALUES_SYSPROP=false
[junit4] 2> 4011770 INFO (SUITE-TestPolicyCloud-seed#[F2373428F8C0E3A8]-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> 4011783 INFO (TEST-TestPolicyCloud.testCreateCollectionAddShardWithReplicaTypeUsingPolicy-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreateCollectionAddShardWithReplicaTypeUsingPolicy
[junit4] 2> 4011787 INFO (TEST-TestPolicyCloud.testCreateCollectionAddShardWithReplicaTypeUsingPolicy-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 4011787 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 4011796 INFO (TEST-TestPolicyCloud.testCreateCollectionAddShardWithReplicaTypeUsingPolicy-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.TestPolicyCloud NRT 127.0.0.1:10139_solr PULL 127.0.0.1:10140_solr , TLOG 127.0.0.1:10140_solr
[junit4] 2> 4011813 INFO (simCloudManagerPool-12622-thread-2) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 1436881260 sessionWrapper.createTime 1436881175860361, this.sessionWrapper.createTime 1436881175860361
[junit4] 2> 4011956 INFO (simCloudManagerPool-12622-thread-7) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 1436888396 sessionWrapper.createTime 1436888343652061, this.sessionWrapper.createTime 1436888343652061
[junit4] 2> 4011992 INFO (TEST-TestPolicyCloud.testCreateCollectionAddShardWithReplicaTypeUsingPolicy-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testCreateCollectionAddShardWithReplicaTypeUsingPolicy
[junit4] 2> 4011992 INFO (simCloudManagerPool-12622-thread-8) [ ] o.a.s.c.ActionThrottle The last leader attempt started 8880ms ago.
[junit4] 2> 4012044 INFO (TEST-TestPolicyCloud.testCreateCollectionAddShardUsingPolicy-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreateCollectionAddShardUsingPolicy
[junit4] 2> 4012044 INFO (TEST-TestPolicyCloud.testCreateCollectionAddShardUsingPolicy-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 4012044 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Interrupted
[junit4] 2> java.lang.InterruptedException
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
[junit4] 2> at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
[junit4] 2> at org.apache.solr.cloud.autoscaling.OverseerTriggerThread.run(OverseerTriggerThread.java:154)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 4012072 INFO (simCloudManagerPool-12622-thread-10) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 1436894218 sessionWrapper.createTime 1436894169131011, this.sessionWrapper.createTime 1436894169131011
[junit4] 2> 4012198 INFO (simCloudManagerPool-12622-thread-14) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 1436900484 sessionWrapper.createTime 1436900388369311, this.sessionWrapper.createTime 1436900388369311
[junit4] 2> 4012209 INFO (simCloudManagerPool-12622-thread-15) [ ] o.a.s.c.ActionThrottle The last leader attempt started 6764ms ago.
[junit4] 2> 4012210 INFO (TEST-TestPolicyCloud.testCreateCollectionAddShardUsingPolicy-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testCreateCollectionAddShardUsingPolicy
[junit4] 2> 4012281 INFO (TEST-TestPolicyCloud.testCreateCollectionSplitShard-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreateCollectionSplitShard
[junit4] 2> 4012281 INFO (TEST-TestPolicyCloud.testCreateCollectionSplitShard-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 4012282 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 4012301 INFO (simCloudManagerPool-12622-thread-17) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 1436905668 sessionWrapper.createTime 1436905592221161, this.sessionWrapper.createTime 1436905592221161
[junit4] 2> 4012431 INFO (simCloudManagerPool-12622-thread-21) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 1436912134 sessionWrapper.createTime 1436912115650511, this.sessionWrapper.createTime 1436912115650511
[junit4] 2> 4012475 INFO (simCloudManagerPool-12622-thread-22) [ ] o.a.s.c.ActionThrottle The last leader attempt started 8614ms ago.
[junit4] 2> 4012476 INFO (TEST-TestPolicyCloud.testCreateCollectionSplitShard-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testCreateCollectionSplitShard
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestPolicyCloud -Dtests.method=testCreateCollectionSplitShard -Dtests.seed=F2373428F8C0E3A8 -Dtests.slow=true -Dtests.locale=sl-SI -Dtests.timezone=Australia/Lord_Howe -Dtests.asserts=true -Dtests.file.encoding=US-ASCII
[junit4] FAILURE 0.27s J1 | TestPolicyCloud.testCreateCollectionSplitShard <<<
[junit4] > Throwable #1: java.lang.AssertionError: Timed out waiting to see 6 replicas for collection: testCreateCollectionSplitShard
[junit4] > Live Nodes: null
[junit4] > Last available state: null
[junit4] > at __randomizedtesting.SeedInfo.seed([F2373428F8C0E3A8:27B947D3488A6216]:0)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.SimSolrCloudTestCase.waitForState(SimSolrCloudTestCase.java:147)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.TestPolicyCloud.testCreateCollectionSplitShard(TestPolicyCloud.java:164)
[junit4] > at java.lang.Thread.run(Thread.java:748)
[junit4] > Caused by: java.io.IOException: org.apache.solr.client.solrj.cloud.autoscaling.BadVersionException: /clusterstate.json
[junit4] > at org.apache.solr.cloud.autoscaling.sim.SimClusterStateProvider.saveClusterState(SimClusterStateProvider.java:494)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.SimClusterStateProvider.getClusterState(SimClusterStateProvider.java:1192)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.SimSolrCloudTestCase.waitForState(SimSolrCloudTestCase.java:171)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.SimSolrCloudTestCase.waitForState(SimSolrCloudTestCase.java:141)
[junit4] > ... 41 more
[junit4] > Caused by: org.apache.solr.client.solrj.cloud.autoscaling.BadVersionException: /clusterstate.json
[junit4] > at org.apache.solr.cloud.autoscaling.sim.SimDistribStateManager$Node.setData(SimDistribStateManager.java:114)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.SimDistribStateManager.setData(SimDistribStateManager.java:502)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.SimClusterStateProvider.saveClusterState(SimClusterStateProvider.java:490)
[junit4] > ... 44 more
[junit4] 2> 4012559 INFO (TEST-TestPolicyCloud.testMetricsTag-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testMetricsTag
[junit4] 2> 4012560 INFO (TEST-TestPolicyCloud.testMetricsTag-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 4012562 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Interrupted
[junit4] 2> java.lang.InterruptedException
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
[junit4] 2> at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
[junit4] 2> at org.apache.solr.cloud.autoscaling.OverseerTriggerThread.run(OverseerTriggerThread.java:154)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 4012565 ERROR (simCloudManagerPool-12622-thread-23) [ ] o.a.s.h.RequestHandlerBase org.apache.solr.api.ApiBag$ExceptionWithErrObject: Error in command payload, errors: [{set-cluster-policy=[{cores=<10, node=#ANY}, {replica=<2, shard=#EACH, node=#ANY}, {metrics:abc=overseer, replica=0}], errorMessages=[Invalid metrics: param in {
[junit4] 2> "metrics:abc":"overseer",
[junit4] 2> "replica":0} must have at 2 or 3 segments after 'metrics:' separated by ':']}],
[junit4] 2> at org.apache.solr.cloud.autoscaling.AutoScalingHandler.processOps(AutoScalingHandler.java:207)
[junit4] 2> at org.apache.solr.cloud.autoscaling.AutoScalingHandler.handleRequestBody(AutoScalingHandler.java:145)
[junit4] 2> at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:177)
[junit4] 2> at org.apache.solr.cloud.autoscaling.sim.SimCloudManager.simHandleSolrRequest(SimCloudManager.java:465)
[junit4] 2> at org.apache.solr.cloud.autoscaling.sim.SimCloudManager.lambda$request$0(SimCloudManager.java:427)
[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>
[junit4] 2> 4012582 INFO (simCloudManagerPool-12622-thread-25) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 1436919681 sessionWrapper.createTime 1436919613030061, this.sessionWrapper.createTime 1436919613030061
[junit4] 2> 4012594 INFO (TEST-TestPolicyCloud.testMetricsTag-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testMetricsTag
[junit4] 2> 4012692 INFO (TEST-TestPolicyCloud.testDataProviderPerReplicaDetails-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testDataProviderPerReplicaDetails
[junit4] 2> 4012692 INFO (TEST-TestPolicyCloud.testDataProviderPerReplicaDetails-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 4012692 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 4012867 INFO (TEST-TestPolicyCloud.testDataProviderPerReplicaDetails-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testDataProviderPerReplicaDetails
[junit4] 2> 4012995 INFO (TEST-TestPolicyCloud.testCreateCollectionAddReplica-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreateCollectionAddReplica
[junit4] 2> 4012996 INFO (TEST-TestPolicyCloud.testCreateCollectionAddReplica-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 4012996 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 4013024 INFO (simCloudManagerPool-12622-thread-37) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 1436941814 sessionWrapper.createTime 1436941795171711, this.sessionWrapper.createTime 1436941795171711
[junit4] 2> 4013039 INFO (simCloudManagerPool-12622-thread-40) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 1436942565 sessionWrapper.createTime 1436942536518861, this.sessionWrapper.createTime 1436942536518861
[junit4] 2> 4013039 INFO (simCloudManagerPool-12622-thread-40) [ ] o.a.s.c.AddReplicaCmd Node Identified 127.0.0.1:10142_solr for creating new replica
[junit4] 2> 4013051 INFO (simCloudManagerPool-12622-thread-41) [ ] o.a.s.c.ActionThrottle The last leader attempt started 1282ms ago.
[junit4] 2> 4013051 INFO (simCloudManagerPool-12622-thread-41) [ ] o.a.s.c.ActionThrottle Throttling leader attempts - waiting for 3717ms
[junit4] 2> 4013052 INFO (TEST-TestPolicyCloud.testCreateCollectionAddReplica-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testCreateCollectionAddReplica
[junit4] 2> 4013207 INFO (TEST-TestPolicyCloud.testDataProvider-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testDataProvider
[junit4] 2> 4013207 INFO (TEST-TestPolicyCloud.testDataProvider-seed#[F2373428F8C0E3A8]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 4013210 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 4013277 INFO (TEST-TestPolicyCloud.testDataProvider-seed#[F2373428F8C0E3A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testDataProvider
[junit4] 2> 4013278 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[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.sim.TestPolicyCloud_F2373428F8C0E3A8-001
[junit4] 2> Dec 17, 2017 3:27:01 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 11 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene70): {}, docValues:{}, maxPointsInLeafNode=1809, maxMBSortInHeap=6.045876696751995, sim=RandomSimilarity(queryNorm=false): {}, locale=sl-SI, timezone=Australia/Lord_Howe
[junit4] 2> NOTE: SunOS 5.11 amd64/Oracle Corporation 1.8.0_152 (64-bit)/cpus=3,threads=1,free=141420336,total=518979584
[junit4] 2> NOTE: All tests run in this JVM: [TestSolrIndexConfig, TestDocTermOrds, TestPivotHelperCode, TestCloudSchemaless, ReplaceNodeTest, CollectionsAPIDistributedZkTest, SolrCoreTest, TestQueryUtils, LeaderElectionIntegrationTest, TestExpandComponent, SearchHandlerTest, TestCoreAdminApis, BasicDistributedZk2Test, TestUtilizeNode, TestManagedSchemaAPI, TestBM25SimilarityFactory, BitVectorTest, OpenCloseCoreStressTest, SearchRateTriggerTest, CollectionsAPIAsyncDistributedZkTest, UtilsToolTest, TestNodeAddedTrigger, SolrJmxReporterCloudTest, MetricsHandlerTest, CdcrBidirectionalTest, BasicAuthStandaloneTest, DistributedFacetPivotSmallAdvancedTest, CoreAdminCreateDiscoverTest, TestElisionMultitermQuery, NumberUtilsTest, RulesTest, TestDistribStateManager, TestRebalanceLeaders, TestManagedResourceStorage, UUIDUpdateProcessorFallbackTest, TestDelegationWithHadoopAuth, ConjunctionSolrSpellCheckerTest, TestCollectionsAPIViaSolrCloudCluster, TestTrie, TestCloudNestedDocsSort, SolrShardReporterTest, TestDynamicFieldCollectionResource, TestReqParamsAPI, SynonymTokenizerTest, AddSchemaFieldsUpdateProcessorFactoryTest, TestComplexPhraseLeadingWildcard, TestFileDictionaryLookup, TestExclusionRuleCollectionAccess, JsonLoaderTest, TestExtendedDismaxParser, TestConfigSets, SolrCloudExampleTest, TestCloudRecovery, SolrIndexMetricsTest, PeerSyncTest, MoveReplicaHDFSTest, TemplateUpdateProcessorTest, TestSchemaSimilarityResource, TestCollationField, DocValuesTest, FileBasedSpellCheckerTest, TestComponentsName, EchoParamsTest, DirectSolrSpellCheckerTest, UpdateParamsTest, TestStressReorder, TestFilteredDocIdSet, HdfsBasicDistributedZk2Test, TestTriggerIntegration, DeleteReplicaTest, TestMissingGroups, TestReloadAndDeleteDocs, TestGroupingSearch, TestLuceneMatchVersion, TestPartialUpdateDeduplication, TestRemoteStreaming, BlockJoinFacetDistribTest, TestLRUStatsCache, HdfsDirectoryTest, TestSortByMinMaxFunction, FullHLLTest, IgnoreCommitOptimizeUpdateProcessorFactoryTest, AliasIntegrationTest, ShardSplitTest, SOLR749Test, BasicFunctionalityTest, TestLegacyFieldReuse, TestStandardQParsers, TestFunctionQuery, TermVectorComponentDistributedTest, TestRTGBase, TestCryptoKeys, AnalysisErrorHandlingTest, TestFieldCacheReopen, SSLMigrationTest, TestAnalyzeInfixSuggestions, TestOnReconnectListenerSupport, TestJsonRequest, PluginInfoTest, SampleTest, TestExportWriter, TestSimpleTrackingShardHandler, FileUtilsTest, HdfsRestartWhileUpdatingTest, TriLevelCompositeIdRoutingTest, StatelessScriptUpdateProcessorFactoryTest, TestGenericDistributedQueue, TestCustomSort, DistributedExpandComponentTest, TestFieldCollectionResource, HdfsAutoAddReplicasIntegrationTest, TestGraphMLResponseWriter, TestMacroExpander, CollectionStateFormat2Test, BlockJoinFacetSimpleTest, SpellPossibilityIteratorTest, AtomicUpdatesTest, TestFoldingMultitermQuery, TestPayloadCheckQParserPlugin, TestSearchPerf, MultiThreadedOCPTest, SecurityConfHandlerTest, DocValuesMissingTest, TermVectorComponentTest, LegacyCloudClusterPropTest, TestQueryTypes, TestLMJelinekMercerSimilarityFactory, TestSolrJ, TestHighFrequencyDictionaryFactory, TestFastOutputStream, TestLeaderInitiatedRecoveryThread, RankQueryTest, ComputePlanActionTest, SubstringBytesRefFilterTest, CloneFieldUpdateProcessorFactoryTest, TestSolrQueryResponse, SolrMetricReporterTest, ChaosMonkeySafeLeaderTest, OutOfBoxZkACLAndCredentialsProvidersTest, TestJettySolrRunner, StressHdfsTest, CopyFieldTest, TestPerFieldSimilarity, TestFastLRUCache, ImplicitSnitchTest, SystemInfoHandlerTest, LukeRequestHandlerTest, DeleteStatusTest, TestRequestForwarding, AssignTest, HdfsChaosMonkeyNothingIsSafeTest, DOMUtilTest, SolrCoreCheckLockOnStartupTest, TestMergePolicyConfig, BasicZkTest, HdfsRecoverLeaseTest, TestRandomFaceting, TestImplicitCoreProperties, HdfsCollectionsAPIDistributedZkTest, TestSolrDeletionPolicy1, CdcrRequestHandlerTest, TestAuthorizationFramework, SolrIndexConfigTest, DirectoryFactoryTest, TestSolrCloudWithKerberosAlt, TestManagedSynonymGraphFilterFactory, DocumentAnalysisRequestHandlerTest, TestCloudInspectUtil, TestPostingsSolrHighlighter, SpatialHeatmapFacetsTest, DistribDocExpirationUpdateProcessorTest, UninvertDocValuesMergePolicyTest, TestCustomStream, TestSerializedLuceneMatchVersion, TestDocSet, SimpleFacetsTest, TestSolrCoreParser, AnalysisAfterCoreReloadTest, TestSQLHandler, SearchHandlerTest, TestDFISimilarityFactory, TestLRUCache, TestEmbeddedSolrServerConstructors, TestAuthenticationFramework, DistributedIntervalFacetingTest, FacetPivotSmallTest, FullSolrCloudDistribCmdsTest, ClusterStateUpdateTest, ZkSolrClientTest, TestZkChroot, ZkCLITest, ShardRoutingCustomTest, TestDistributedSearch, TestDistributedGrouping, TestFaceting, TestHashPartitioner, ZkControllerTest, TestRealTimeGet, TestJoin, TestReload, TestStressVersions, TestCoreContainer, StatsComponentTest, SolrCmdDistributorTest, QueryElevationComponentTest, ConvertedLegacyTest, TestSort, TestFiltering, DirectUpdateHandlerTest, TestBadConfig, TestIndexSearcher, HighlighterTest, SoftAutoCommitTest, ShowFileRequestHandlerTest, SolrIndexSplitterTest, SimplePostToolTest, SignatureUpdateProcessorFactoryTest, CoreAdminHandlerTest, SuggesterTest, TestStressLucene, SpatialFilterTest, TestCSVLoader, PolyFieldTest, WordBreakSolrSpellCheckerTest, SchemaVersionSpecificBehaviorTest, TestPseudoReturnFields, TestUpdate, FieldMutatingUpdateProcessorTest, TestAtomicUpdateErrorCases, TestWordDelimiterFilterFactory, QueryEqualityTest, DefaultValueUpdateProcessorTest, SortByFunctionTest, DocValuesMultiTest, DebugComponentTest, CacheHeaderTest, DisMaxRequestHandlerTest, TestReversedWildcardFilterFactory, PrimitiveFieldTypeTest, TermsComponentTest, RequestHandlersTest, DocumentBuilderTest, TestValueSourceCache, PathHierarchyTokenizerFactoryTest, MoreLikeThisHandlerTest, RequiredFieldsTest, TestSolrQueryParser, FastVectorHighlighterTest, IndexSchemaRuntimeFieldTest, LoggingHandlerTest, SolrPluginUtilsTest, TestJmxIntegration, UpdateRequestProcessorFactoryTest, MBeansHandlerTest, QueryParsingTest, TestAnalyzedSuggestions, TestPHPSerializedResponseWriter, PingRequestHandlerTest, HighlighterConfigTest, AlternateDirectoryTest, TestQuerySenderNoQuery, BadComponentTest, TestStressRecovery, PreAnalyzedFieldTest, TestSystemIdResolver, PrimUtilsTest, TestSuggestSpellingConverter, DateFieldTest, SpellingQueryConverterTest, RAMDirectoryFactoryTest, ClusterStateTest, TestUtils, TestDocumentBuilder, ZkNodePropsTest, UUIDFieldTest, DistributedMLTComponentTest, SolrTestCaseJ4Test, TestCrossCoreJoin, TestDistributedMissingSort, TestTolerantSearch, TestLuceneIndexBackCompat, ConnectionReuseTest, ActionThrottleTest, AddReplicaTest, AssignBackwardCompatibilityTest, CleanupOldIndexTest, CloudExitableDirectoryReaderTest, CollectionReloadTest, CollectionsAPISolrJTest, DistribJoinFromCollectionTest, DocValuesNotIndexedTest, HttpPartitionTest, LeaderFailureAfterFreshStartTest, LeaderInitiatedRecoveryOnShardRestartTest, MissingSegmentRecoveryTest, NodeMutatorTest, OverriddenZkACLAndCredentialsProvidersTest, OverseerCollectionConfigSetProcessorTest, OverseerModifyCollectionTest, OverseerRolesTest, OverseerTaskQueueTest, ReplicationFactorTest, RestartWhileUpdatingTest, SimpleCollectionCreateDeleteTest, TestClusterProperties, TestConfigSetsAPIExclusivity, TestConfigSetsAPIZkFailure, TestDownShardTolerantSearch, TestHdfsCloudBackupRestore, TestLeaderElectionZkExpiry, TestPullReplica, TestRequestStatusCollectionAPI, TestShortCircuitedRequests, TestSizeLimitedDistributedMap, TestStressInPlaceUpdates, AutoAddReplicasIntegrationTest, AutoScalingHandlerTest, NodeLostTriggerTest, TestClusterStateProvider, TestComputePlanAction, TestExecutePlanAction, TestLargeCluster, TestNodeLostTrigger, TestPolicyCloud]
[junit4] Completed [575/763 (2!)] on J1 in 1.86s, 7 tests, 1 failure <<< FAILURES!
[...truncated 48768 lines...]