Build: https://builds.apache.org/job/Lucene-Solr-Tests-master/1897/
2 tests failed. FAILED: org.apache.solr.cloud.autoscaling.TestPolicyCloud.testCreateCollectionAddReplica Error Message: Error from server at http://127.0.0.1:46293/solr: delete the collection time out:180s Stack Trace: org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at http://127.0.0.1:46293/solr: delete the collection time out:180s at __randomizedtesting.SeedInfo.seed([7BB7E6E04C2F7DA2:FB9783CE5D6C9504]:0) at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:624) at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:250) at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:239) at org.apache.solr.client.solrj.impl.LBHttpSolrClient.doRequest(LBHttpSolrClient.java:470) at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:400) at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(CloudSolrClient.java:1102) at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:843) at org.apache.solr.client.solrj.impl.CloudSolrClient.request(CloudSolrClient.java:774) at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:178) at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:195) at org.apache.solr.cloud.MiniSolrCloudCluster.deleteAllCollections(MiniSolrCloudCluster.java:442) at org.apache.solr.cloud.autoscaling.TestPolicyCloud.after(TestPolicyCloud.java:63) 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:1713) at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:965) 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:916) at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802) at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852) at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863) 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.TestPolicyCloud.testDataProvider Error Message: Error from server at http://127.0.0.1:46293/solr: Could not find collection : testCreateCollectionAddReplica Stack Trace: org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at http://127.0.0.1:46293/solr: Could not find collection : testCreateCollectionAddReplica at __randomizedtesting.SeedInfo.seed([7BB7E6E04C2F7DA2:431C4ED5FEED797B]:0) at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:624) at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:250) at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:239) at org.apache.solr.client.solrj.impl.LBHttpSolrClient.doRequest(LBHttpSolrClient.java:470) at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:400) at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(CloudSolrClient.java:1102) at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:843) at org.apache.solr.client.solrj.impl.CloudSolrClient.request(CloudSolrClient.java:774) at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:178) at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:195) at org.apache.solr.cloud.MiniSolrCloudCluster.deleteAllCollections(MiniSolrCloudCluster.java:442) at org.apache.solr.cloud.autoscaling.TestPolicyCloud.after(TestPolicyCloud.java:63) 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:1713) at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:965) 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:916) at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802) at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852) at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863) 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 11125 lines...] [junit4] Suite: org.apache.solr.cloud.autoscaling.TestPolicyCloud [junit4] 2> Creating dataDir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/init-core-data-001 [junit4] 2> 9423 WARN (SUITE-TestPolicyCloud-seed#[7BB7E6E04C2F7DA2]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=1 numCloses=1 [junit4] 2> 9423 INFO (SUITE-TestPolicyCloud-seed#[7BB7E6E04C2F7DA2]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=true [junit4] 2> 9429 INFO (SUITE-TestPolicyCloud-seed#[7BB7E6E04C2F7DA2]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN) [junit4] 2> 9438 INFO (SUITE-TestPolicyCloud-seed#[7BB7E6E04C2F7DA2]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 5 servers in /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/tempDir-001 [junit4] 2> 9463 INFO (SUITE-TestPolicyCloud-seed#[7BB7E6E04C2F7DA2]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER [junit4] 2> 9474 INFO (Thread-3) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0 [junit4] 2> 9474 INFO (Thread-3) [ ] o.a.s.c.ZkTestServer Starting server [junit4] 2> 9573 INFO (SUITE-TestPolicyCloud-seed#[7BB7E6E04C2F7DA2]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:52066 [junit4] 2> 9590 ERROR (Thread-3) [ ] 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> 9962 INFO (jetty-launcher-5-thread-3) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 9968 INFO (jetty-launcher-5-thread-5) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 9968 INFO (jetty-launcher-5-thread-4) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 9962 INFO (jetty-launcher-5-thread-2) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 9968 INFO (jetty-launcher-5-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 10018 INFO (jetty-launcher-5-thread-3) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@64957fc1{/solr,null,AVAILABLE} [junit4] 2> 10022 INFO (jetty-launcher-5-thread-4) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@3b10f4aa{/solr,null,AVAILABLE} [junit4] 2> 10025 INFO (jetty-launcher-5-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@31b6e5dc{/solr,null,AVAILABLE} [junit4] 2> 10038 INFO (jetty-launcher-5-thread-5) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@4bbcbde3{/solr,null,AVAILABLE} [junit4] 2> 10050 INFO (jetty-launcher-5-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@209d6e6d{/solr,null,AVAILABLE} [junit4] 2> 10058 INFO (jetty-launcher-5-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@60edba39{HTTP/1.1,[http/1.1]}{127.0.0.1:56214} [junit4] 2> 10058 INFO (jetty-launcher-5-thread-1) [ ] o.e.j.s.Server Started @13283ms [junit4] 2> 10058 INFO (jetty-launcher-5-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=56214} [junit4] 2> 10059 INFO (jetty-launcher-5-thread-5) [ ] o.e.j.s.AbstractConnector Started ServerConnector@33b6f331{HTTP/1.1,[http/1.1]}{127.0.0.1:54640} [junit4] 2> 10060 INFO (jetty-launcher-5-thread-5) [ ] o.e.j.s.Server Started @13285ms [junit4] 2> 10059 INFO (jetty-launcher-5-thread-3) [ ] o.e.j.s.AbstractConnector Started ServerConnector@59ed65aa{HTTP/1.1,[http/1.1]}{127.0.0.1:34252} [junit4] 2> 10060 INFO (jetty-launcher-5-thread-3) [ ] o.e.j.s.Server Started @13286ms [junit4] 2> 10060 INFO (jetty-launcher-5-thread-5) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=54640} [junit4] 2> 10065 INFO (jetty-launcher-5-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@3849bc40{HTTP/1.1,[http/1.1]}{127.0.0.1:46293} [junit4] 2> 10065 INFO (jetty-launcher-5-thread-4) [ ] o.e.j.s.AbstractConnector Started ServerConnector@502d0292{HTTP/1.1,[http/1.1]}{127.0.0.1:34895} [junit4] 2> 10065 INFO (jetty-launcher-5-thread-2) [ ] o.e.j.s.Server Started @13290ms [junit4] 2> 10065 INFO (jetty-launcher-5-thread-4) [ ] o.e.j.s.Server Started @13290ms [junit4] 2> 10065 INFO (jetty-launcher-5-thread-4) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=34895} [junit4] 2> 10060 INFO (jetty-launcher-5-thread-3) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=34252} [junit4] 2> 10065 INFO (jetty-launcher-5-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=46293} [junit4] 2> 10090 ERROR (jetty-launcher-5-thread-3) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 10090 INFO (jetty-launcher-5-thread-3) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.0.0 [junit4] 2> 10091 INFO (jetty-launcher-5-thread-3) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 10091 INFO (jetty-launcher-5-thread-3) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 10092 ERROR (jetty-launcher-5-thread-4) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 10090 ERROR (jetty-launcher-5-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 10098 INFO (jetty-launcher-5-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.0.0 [junit4] 2> 10098 INFO (jetty-launcher-5-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 10098 INFO (jetty-launcher-5-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 10098 INFO (jetty-launcher-5-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-06-24T08:04:37.523Z [junit4] 2> 10091 ERROR (jetty-launcher-5-thread-5) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 10097 ERROR (jetty-launcher-5-thread-2) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 10100 INFO (jetty-launcher-5-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.0.0 [junit4] 2> 10100 INFO (jetty-launcher-5-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 10100 INFO (jetty-launcher-5-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 10100 INFO (jetty-launcher-5-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-06-24T08:04:37.525Z [junit4] 2> 10097 INFO (jetty-launcher-5-thread-3) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-06-24T08:04:37.519Z [junit4] 2> 10093 INFO (jetty-launcher-5-thread-4) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.0.0 [junit4] 2> 10102 INFO (jetty-launcher-5-thread-4) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 10102 INFO (jetty-launcher-5-thread-4) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 10102 INFO (jetty-launcher-5-thread-4) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-06-24T08:04:37.527Z [junit4] 2> 10100 INFO (jetty-launcher-5-thread-5) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.0.0 [junit4] 2> 10102 INFO (jetty-launcher-5-thread-5) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 10103 INFO (jetty-launcher-5-thread-5) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 10103 INFO (jetty-launcher-5-thread-5) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-06-24T08:04:37.528Z [junit4] 2> 10103 INFO (jetty-launcher-5-thread-1) [ ] o.a.s.c.SolrResourceLoader solr home defaulted to 'solr/' (could not find system property or JNDI) [junit4] 2> 10135 INFO (jetty-launcher-5-thread-3) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 10141 INFO (jetty-launcher-5-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 10144 INFO (jetty-launcher-5-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 10145 INFO (jetty-launcher-5-thread-5) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 10146 INFO (jetty-launcher-5-thread-4) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 10256 INFO (jetty-launcher-5-thread-4) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:52066/solr [junit4] 2> 10272 INFO (jetty-launcher-5-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:52066/solr [junit4] 2> 10282 INFO (jetty-launcher-5-thread-3) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:52066/solr [junit4] 2> 10280 INFO (jetty-launcher-5-thread-5) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:52066/solr [junit4] 2> 10325 INFO (jetty-launcher-5-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:52066/solr [junit4] 2> 10371 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 0x15cd92199ed0006, 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> 10393 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 0x15cd92199ed0009, 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> 10394 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 0x15cd92199ed0008, 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> 10395 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 0x15cd92199ed0007, 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> 10776 INFO (jetty-launcher-5-thread-3) [n:127.0.0.1:34252_solr ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 10777 INFO (jetty-launcher-5-thread-1) [n:127.0.0.1:56214_solr ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 10778 INFO (jetty-launcher-5-thread-4) [n:127.0.0.1:34895_solr ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 10778 INFO (jetty-launcher-5-thread-2) [n:127.0.0.1:46293_solr ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 10779 INFO (jetty-launcher-5-thread-5) [n:127.0.0.1:54640_solr ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 10781 INFO (jetty-launcher-5-thread-3) [n:127.0.0.1:34252_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:34252_solr [junit4] 2> 10788 INFO (jetty-launcher-5-thread-1) [n:127.0.0.1:56214_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56214_solr [junit4] 2> 10789 INFO (jetty-launcher-5-thread-2) [n:127.0.0.1:46293_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46293_solr [junit4] 2> 10805 INFO (jetty-launcher-5-thread-4) [n:127.0.0.1:34895_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34895_solr [junit4] 2> 10805 INFO (jetty-launcher-5-thread-5) [n:127.0.0.1:54640_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54640_solr [junit4] 2> 10806 INFO (jetty-launcher-5-thread-3) [n:127.0.0.1:34252_solr ] o.a.s.c.Overseer Overseer (id=98192030234902542-127.0.0.1:34252_solr-n_0000000000) starting [junit4] 2> 10812 INFO (zkCallback-32-thread-1-processing-n:127.0.0.1:54640_solr) [n:127.0.0.1:54640_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 10815 INFO (zkCallback-30-thread-1-processing-n:127.0.0.1:56214_solr) [n:127.0.0.1:56214_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 10827 INFO (zkCallback-29-thread-1-processing-n:127.0.0.1:46293_solr) [n:127.0.0.1:46293_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 10834 INFO (zkCallback-28-thread-1-processing-n:127.0.0.1:34895_solr) [n:127.0.0.1:34895_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 10834 INFO (zkCallback-31-thread-1-processing-n:127.0.0.1:34252_solr) [n:127.0.0.1:34252_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 11000 INFO (jetty-launcher-5-thread-3) [n:127.0.0.1:34252_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34252_solr [junit4] 2> 11003 INFO (zkCallback-30-thread-1-processing-n:127.0.0.1:56214_solr) [n:127.0.0.1:56214_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5) [junit4] 2> 11004 INFO (zkCallback-32-thread-1-processing-n:127.0.0.1:54640_solr) [n:127.0.0.1:54640_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5) [junit4] 2> 11004 INFO (zkCallback-28-thread-1-processing-n:127.0.0.1:34895_solr) [n:127.0.0.1:34895_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5) [junit4] 2> 11004 INFO (zkCallback-31-thread-1-processing-n:127.0.0.1:34252_solr) [n:127.0.0.1:34252_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5) [junit4] 2> 11004 INFO (zkCallback-29-thread-1-processing-n:127.0.0.1:46293_solr) [n:127.0.0.1:46293_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5) [junit4] 2> 11335 INFO (jetty-launcher-5-thread-4) [n:127.0.0.1:34895_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34895.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11335 INFO (jetty-launcher-5-thread-4) [n:127.0.0.1:34895_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34895.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11336 INFO (jetty-launcher-5-thread-4) [n:127.0.0.1:34895_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34895.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11374 INFO (jetty-launcher-5-thread-4) [n:127.0.0.1:34895_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/tempDir-001/node4/. [junit4] 2> 11379 INFO (jetty-launcher-5-thread-1) [n:127.0.0.1:56214_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_56214.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11402 INFO (jetty-launcher-5-thread-1) [n:127.0.0.1:56214_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_56214.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11402 INFO (jetty-launcher-5-thread-1) [n:127.0.0.1:56214_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_56214.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11408 INFO (jetty-launcher-5-thread-1) [n:127.0.0.1:56214_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/tempDir-001/node1/. [junit4] 2> 11547 INFO (jetty-launcher-5-thread-5) [n:127.0.0.1:54640_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_54640.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11572 INFO (jetty-launcher-5-thread-5) [n:127.0.0.1:54640_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_54640.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11572 INFO (jetty-launcher-5-thread-5) [n:127.0.0.1:54640_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_54640.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11578 INFO (jetty-launcher-5-thread-2) [n:127.0.0.1:46293_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_46293.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11581 INFO (jetty-launcher-5-thread-5) [n:127.0.0.1:54640_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/tempDir-001/node5/. [junit4] 2> 11582 INFO (jetty-launcher-5-thread-2) [n:127.0.0.1:46293_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_46293.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11582 INFO (jetty-launcher-5-thread-2) [n:127.0.0.1:46293_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_46293.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11584 INFO (jetty-launcher-5-thread-2) [n:127.0.0.1:46293_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/tempDir-001/node2/. [junit4] 2> 11615 INFO (jetty-launcher-5-thread-3) [n:127.0.0.1:34252_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34252.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11634 INFO (jetty-launcher-5-thread-3) [n:127.0.0.1:34252_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34252.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11634 INFO (jetty-launcher-5-thread-3) [n:127.0.0.1:34252_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34252.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 11644 INFO (jetty-launcher-5-thread-3) [n:127.0.0.1:34252_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/tempDir-001/node3/. [junit4] 2> 12195 INFO (SUITE-TestPolicyCloud-seed#[7BB7E6E04C2F7DA2]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (5) [junit4] 2> 12197 INFO (SUITE-TestPolicyCloud-seed#[7BB7E6E04C2F7DA2]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:52066/solr ready [junit4] 2> 12265 INFO (TEST-TestPolicyCloud.testCreateCollectionAddShardUsingPolicy-seed#[7BB7E6E04C2F7DA2]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreateCollectionAddShardUsingPolicy [junit4] 2> 12663 INFO (qtp1386392746-63) [n:127.0.0.1:54640_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (5) [junit4] 2> 12668 INFO (qtp1386392746-63) [n:127.0.0.1:54640_solr ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:52066/solr ready [junit4] 2> 12720 INFO (qtp463545395-64) [n:127.0.0.1:46293_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=9 [junit4] 2> 12763 INFO (qtp1386392746-79) [n:127.0.0.1:54640_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> 12771 INFO (qtp1074534984-74) [n:127.0.0.1:34895_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> 12779 INFO (qtp824508534-65) [n:127.0.0.1:56214_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> 12784 INFO (qtp984317077-60) [n:127.0.0.1:34252_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> 12797 INFO (qtp1386392746-63) [n:127.0.0.1:54640_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/cluster/autoscaling params={wt=javabin&version=2} status=0 QTime=202 [junit4] 2> 12813 INFO (qtp463545395-67) [n:127.0.0.1:46293_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params shards=s1,s2&replicationFactor=1&name=policiesTest&router.name=implicit&nrtReplicas=1&action=CREATE&wt=javabin&version=2&policy=c1 and sendToOCPQueue=true [junit4] 2> 12831 INFO (OverseerThreadFactory-47-thread-1-processing-n:127.0.0.1:34252_solr) [n:127.0.0.1:34252_solr ] o.a.s.c.CreateCollectionCmd Create collection policiesTest [junit4] 2> 12831 INFO (OverseerThreadFactory-47-thread-1-processing-n:127.0.0.1:34252_solr) [n:127.0.0.1:34252_solr ] o.a.s.c.CreateCollectionCmd Only one config set found in zk - using it:conf [junit4] 2> 12845 INFO (qtp463545395-68) [n:127.0.0.1:46293_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> 12848 INFO (qtp1386392746-85) [n:127.0.0.1:54640_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> 12851 INFO (qtp984317077-57) [n:127.0.0.1:34252_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> 12854 INFO (qtp1074534984-76) [n:127.0.0.1:34895_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> 12857 INFO (qtp824508534-51) [n:127.0.0.1:56214_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> 13015 INFO (OverseerStateUpdate-98192030234902542-127.0.0.1:34252_solr-n_0000000000) [n:127.0.0.1:34252_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"policiesTest", [junit4] 2> "shard":"s1", [junit4] 2> "core":"policiesTest_s1_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:46293/solr";, [junit4] 2> "type":"NRT"} [junit4] 2> 13027 INFO (OverseerStateUpdate-98192030234902542-127.0.0.1:34252_solr-n_0000000000) [n:127.0.0.1:34252_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"policiesTest", [junit4] 2> "shard":"s2", [junit4] 2> "core":"policiesTest_s2_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:46293/solr";, [junit4] 2> "type":"NRT"} [junit4] 2> 13230 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node1&collection.configName=conf&newCollection=true&name=policiesTest_s1_replica_n1&action=CREATE&numShards=2&collection=policiesTest&shard=s1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 13230 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node2&collection.configName=conf&newCollection=true&name=policiesTest_s2_replica_n1&action=CREATE&numShards=2&collection=policiesTest&shard=s2&wt=javabin&version=2&replicaType=NRT [junit4] 2> 13233 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 13355 INFO (zkCallback-29-thread-1-processing-n:127.0.0.1:46293_solr) [n:127.0.0.1:46293_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/policiesTest/state.json] for collection [policiesTest] has occurred - updating... (live nodes size: [5]) [junit4] 2> 14265 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0 [junit4] 2> 14266 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0 [junit4] 2> 14289 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.s.IndexSchema [policiesTest_s2_replica_n1] Schema name=minimal [junit4] 2> 14289 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.s.IndexSchema [policiesTest_s1_replica_n1] Schema name=minimal [junit4] 2> 14300 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 14300 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 14300 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.c.CoreContainer Creating SolrCore 'policiesTest_s1_replica_n1' using configuration from collection policiesTest, trusted=true [junit4] 2> 14300 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.c.CoreContainer Creating SolrCore 'policiesTest_s2_replica_n1' using configuration from collection policiesTest, trusted=true [junit4] 2> 14302 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_46293.solr.core.policiesTest.s2.replica_n1' (registry 'solr.core.policiesTest.s2.replica_n1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 14302 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_46293.solr.core.policiesTest.s1.replica_n1' (registry 'solr.core.policiesTest.s1.replica_n1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 14303 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 14303 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 14304 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.c.SolrCore [[policiesTest_s1_replica_n1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/tempDir-001/node2/policiesTest_s1_replica_n1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/tempDir-001/node2/./policiesTest_s1_replica_n1/data/] [junit4] 2> 14304 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.c.SolrCore [[policiesTest_s2_replica_n1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/tempDir-001/node2/policiesTest_s2_replica_n1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/tempDir-001/node2/./policiesTest_s2_replica_n1/data/] [junit4] 2> 14400 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 14400 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 14403 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 14403 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 14406 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@2ee55bac[policiesTest_s1_replica_n1] main] [junit4] 2> 14411 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 14412 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 14413 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 14417 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 14418 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 14419 INFO (searcherExecutor-58-thread-1-processing-n:127.0.0.1:46293_solr x:policiesTest_s1_replica_n1 s:s1 c:policiesTest r:core_node1) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.c.SolrCore [policiesTest_s1_replica_n1] Registered new searcher Searcher@2ee55bac[policiesTest_s1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 14420 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1571072488867102720 [junit4] 2> 14421 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 14421 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 14425 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1770d9f5[policiesTest_s2_replica_n1] main] [junit4] 2> 14428 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 14434 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 14439 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 14445 INFO (searcherExecutor-59-thread-1-processing-n:127.0.0.1:46293_solr x:policiesTest_s2_replica_n1 s:s2 c:policiesTest r:core_node2) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.c.SolrCore [policiesTest_s2_replica_n1] Registered new searcher Searcher@1770d9f5[policiesTest_s2_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 14449 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1571072488897511424 [junit4] 2> 14462 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 14463 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 14463 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:46293/solr/policiesTest_s1_replica_n1/ [junit4] 2> 14465 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 14465 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.c.SyncStrategy http://127.0.0.1:46293/solr/policiesTest_s1_replica_n1/ has no replicas [junit4] 2> 14465 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 14488 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 14489 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 14489 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:46293/solr/policiesTest_s2_replica_n1/ [junit4] 2> 14489 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 14489 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.c.SyncStrategy http://127.0.0.1:46293/solr/policiesTest_s2_replica_n1/ has no replicas [junit4] 2> 14489 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 14520 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:46293/solr/policiesTest_s1_replica_n1/ s1 [junit4] 2> 14521 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:46293/solr/policiesTest_s2_replica_n1/ s2 [junit4] 2> 14629 INFO (zkCallback-29-thread-1-processing-n:127.0.0.1:46293_solr) [n:127.0.0.1:46293_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/policiesTest/state.json] for collection [policiesTest] has occurred - updating... (live nodes size: [5]) [junit4] 2> 14673 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 14674 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 14686 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s1 r:core_node1 x:policiesTest_s1_replica_n1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node1&collection.configName=conf&newCollection=true&name=policiesTest_s1_replica_n1&action=CREATE&numShards=2&collection=policiesTest&shard=s1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1456 [junit4] 2> 14687 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr c:policiesTest s:s2 r:core_node2 x:policiesTest_s2_replica_n1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node2&collection.configName=conf&newCollection=true&name=policiesTest_s2_replica_n1&action=CREATE&numShards=2&collection=policiesTest&shard=s2&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1458 [junit4] 2> 14719 INFO (qtp463545395-67) [n:127.0.0.1:46293_solr ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas [junit4] 2> 14794 INFO (zkCallback-29-thread-1-processing-n:127.0.0.1:46293_solr) [n:127.0.0.1:46293_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/policiesTest/state.json] for collection [policiesTest] has occurred - updating... (live nodes size: [5]) [junit4] 2> 14840 INFO (OverseerCollectionConfigSetProcessor-98192030234902542-127.0.0.1:34252_solr-n_0000000000) [n:127.0.0.1:34252_solr ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000000 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 15719 INFO (qtp463545395-67) [n:127.0.0.1:46293_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={shards=s1,s2&replicationFactor=1&name=policiesTest&router.name=implicit&nrtReplicas=1&action=CREATE&wt=javabin&version=2&policy=c1} status=0 QTime=2906 [junit4] 2> 15727 INFO (qtp463545395-55) [n:127.0.0.1:46293_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :createshard with params action=CREATESHARD&collection=policiesTest&shard=s3&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 15732 INFO (OverseerThreadFactory-47-thread-2-processing-n:127.0.0.1:34252_solr) [n:127.0.0.1:34252_solr ] o.a.s.c.CreateShardCmd Create shard invoked: { [junit4] 2> "collection":"policiesTest", [junit4] 2> "shard":"s3", [junit4] 2> "operation":"createshard"} [junit4] 2> 15757 INFO (qtp463545395-69) [n:127.0.0.1:46293_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=10 [junit4] 2> 15760 INFO (qtp1386392746-63) [n:127.0.0.1:54640_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> 15763 INFO (qtp1074534984-78) [n:127.0.0.1:34895_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> 15770 INFO (qtp824508534-84) [n:127.0.0.1:56214_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> 15772 INFO (qtp984317077-60) [n:127.0.0.1:34252_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> 15883 INFO (zkCallback-29-thread-1-processing-n:127.0.0.1:46293_solr) [n:127.0.0.1:46293_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/policiesTest/state.json] for collection [policiesTest] has occurred - updating... (live nodes size: [5]) [junit4] 2> 16785 INFO (OverseerThreadFactory-47-thread-2-processing-n:127.0.0.1:34252_solr) [n:127.0.0.1:34252_solr ] o.a.s.c.CreateShardCmd Creating replica policiesTest_s3_replica_n1 as part of slice s3 of collection policiesTest on 127.0.0.1:46293_solr [junit4] 2> 16786 INFO (OverseerThreadFactory-47-thread-2-processing-n:127.0.0.1:34252_solr) [n:127.0.0.1:34252_solr ] o.a.s.c.AddReplicaCmd addReplica() : { [junit4] 2> "collection":"policiesTest", [junit4] 2> "shard":"s3", [junit4] 2> "replicaType":"NRT", [junit4] 2> "node":"127.0.0.1:46293_solr", [junit4] 2> "name":"policiesTest_s3_replica_n1"} [junit4] 2> 16823 INFO (qtp463545395-66) [n:127.0.0.1:46293_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=5 [junit4] 2> 16826 INFO (qtp1386392746-86) [n:127.0.0.1:54640_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> 16829 INFO (qtp1074534984-76) [n:127.0.0.1:34895_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> 16835 INFO (qtp824508534-65) [n:127.0.0.1:56214_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> 16838 INFO (qtp984317077-60) [n:127.0.0.1:34252_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> 16840 INFO (OverseerThreadFactory-47-thread-2-processing-n:127.0.0.1:34252_solr) [n:127.0.0.1:34252_solr ] o.a.s.c.AddReplicaCmd Node Identified 127.0.0.1:46293_solr for creating new replica [junit4] 2> 16851 INFO (OverseerStateUpdate-98192030234902542-127.0.0.1:34252_solr-n_0000000000) [n:127.0.0.1:34252_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"addreplica", [junit4] 2> "collection":"policiesTest", [junit4] 2> "shard":"s3", [junit4] 2> "core":"policiesTest_s3_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:46293/solr";, [junit4] 2> "node_name":"127.0.0.1:46293_solr", [junit4] 2> "type":"NRT"} [junit4] 2> 16956 INFO (zkCallback-29-thread-1-processing-n:127.0.0.1:46293_solr) [n:127.0.0.1:46293_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/policiesTest/state.json] for collection [policiesTest] has occurred - updating... (live nodes size: [5]) [junit4] 2> 16964 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node3&collection.configName=conf&name=policiesTest_s3_replica_n1&action=CREATE&collection=policiesTest&shard=s3&wt=javabin&version=2&replicaType=NRT [junit4] 2> 16994 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0 [junit4] 2> 17045 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.s.IndexSchema [policiesTest_s3_replica_n1] Schema name=minimal [junit4] 2> 17050 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 17053 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.c.CoreContainer Creating SolrCore 'policiesTest_s3_replica_n1' using configuration from collection policiesTest, trusted=true [junit4] 2> 17061 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_46293.solr.core.policiesTest.s3.replica_n1' (registry 'solr.core.policiesTest.s3.replica_n1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 17061 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 17062 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.c.SolrCore [[policiesTest_s3_replica_n1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/tempDir-001/node2/policiesTest_s3_replica_n1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/tempDir-001/node2/./policiesTest_s3_replica_n1/data/] [junit4] 2> 17077 INFO (zkCallback-29-thread-1-processing-n:127.0.0.1:46293_solr) [n:127.0.0.1:46293_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/policiesTest/state.json] for collection [policiesTest] has occurred - updating... (live nodes size: [5]) [junit4] 2> 17229 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 17229 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 17257 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 17257 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 17259 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@573f406b[policiesTest_s3_replica_n1] main] [junit4] 2> 17262 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 17263 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 17264 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 17273 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1571072491858690048 [junit4] 2> 17284 INFO (searcherExecutor-68-thread-1-processing-n:127.0.0.1:46293_solr x:policiesTest_s3_replica_n1 s:s3 c:policiesTest r:core_node3) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.c.SolrCore [policiesTest_s3_replica_n1] Registered new searcher Searcher@573f406b[policiesTest_s3_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 17292 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 17292 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 17292 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:46293/solr/policiesTest_s3_replica_n1/ [junit4] 2> 17292 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 17292 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.c.SyncStrategy http://127.0.0.1:46293/solr/policiesTest_s3_replica_n1/ has no replicas [junit4] 2> 17292 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 17307 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:46293/solr/policiesTest_s3_replica_n1/ s3 [junit4] 2> 17417 INFO (zkCallback-29-thread-1-processing-n:127.0.0.1:46293_solr) [n:127.0.0.1:46293_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/policiesTest/state.json] for collection [policiesTest] has occurred - updating... (live nodes size: [5]) [junit4] 2> 17460 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 17468 INFO (qtp463545395-68) [n:127.0.0.1:46293_solr c:policiesTest s:s3 r:core_node3 x:policiesTest_s3_replica_n1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node3&collection.configName=conf&name=policiesTest_s3_replica_n1&action=CREATE&collection=policiesTest&shard=s3&wt=javabin&version=2&replicaType=NRT} status=0 QTime=504 [junit4] 2> 17471 INFO (OverseerThreadFactory-47-thread-2-processing-n:127.0.0.1:34252_solr) [n:127.0.0.1:34252_solr ] o.a.s.c.CreateShardCmd Finished create command on all shards for collection: policiesTest [junit4] 2> 17475 INFO (qtp463545395-55) [n:127.0.0.1:46293_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=CREATESHARD&collection=policiesTest&shard=s3&wt=javabin&version=2} status=0 QTime=1748 [junit4] 2> 17477 INFO (OverseerCollectionConfigSetProcessor-98192030234902542-127.0.0.1:34252_solr-n_0000000000) [n:127.0.0.1:34252_solr ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000002 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 17481 INFO (TEST-TestPolicyCloud.testCreateCollectionAddShardUsingPolicy-seed#[7BB7E6E04C2F7DA2]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (5) [junit4] 2> 17485 INFO (qtp463545395-69) [n:127.0.0.1:46293_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=policiesTest&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 17515 INFO (OverseerThreadFactory-47-thread-3-processing-n:127.0.0.1:34252_solr) [n:127.0.0.1:34252_solr ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true [junit4] 2> 17540 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.policiesTest.s1.replica_n1, tag=null [junit4] 2> 17568 INFO (qtp463545395-66) [n:127.0.0.1:46293_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.policiesTest.s2.replica_n1, tag=null [junit4] 2> 17574 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr ] o.a.s.c.SolrCore [policiesTest_s1_replica_n1] CLOSING SolrCore org.apache.solr.core.SolrCore@63d43189 [junit4] 2> 17577 INFO (zkCallback-29-thread-1-processing-n:127.0.0.1:46293_solr) [n:127.0.0.1:46293_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/policiesTest/state.json] for collection [policiesTest] has occurred - updating... (live nodes size: [5]) [junit4] 2> 17582 INFO (qtp463545395-64) [n:127.0.0.1:46293_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.policiesTest.s3.replica_n1, tag=null [junit4] 2> 17596 INFO (qtp463545395-66) [n:127.0.0.1:46293_solr ] o.a.s.c.SolrCore [policiesTest_s2_replica_n1] CLOSING SolrCore org.apache.solr.core.SolrCore@4adcf862 [junit4] 2> 17661 INFO (qtp463545395-66) [n:127.0.0.1:46293_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.policiesTest.s2.replica_n1, tag=1255995490 [junit4] 2> 17661 INFO (qtp463545395-66) [n:127.0.0.1:46293_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.policiesTest.s2.leader, tag=1255995490 [junit4] 2> 17662 INFO (qtp463545395-64) [n:127.0.0.1:46293_solr ] o.a.s.c.SolrCore [policiesTest_s3_replica_n1] CLOSING SolrCore org.apache.solr.core.SolrCore@6cfe9519 [junit4] 2> 17690 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.policiesTest.s1.replica_n1, tag=1674850697 [junit4] 2> 17690 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.policiesTest.s1.leader, tag=1674850697 [junit4] 2> 17717 INFO (qtp463545395-66) [n:127.0.0.1:46293_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=policiesTest_s2_replica_n1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=180 [junit4] 2> 17718 INFO (qtp463545395-48) [n:127.0.0.1:46293_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=policiesTest_s1_replica_n1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=182 [junit4] 2> 17732 INFO (qtp463545395-64) [n:127.0.0.1:46293_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.policiesTest.s3.replica_n1, tag=1828623641 [junit4] 2> 17733 INFO (qtp463545395-64) [n:127.0.0.1:46293_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.policiesTest.s3.leader, tag=1828623641 [junit4] 2> 17736 INFO (qtp463545395-64) [n:127.0.0.1:46293_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=policiesTest_s3_replica_n1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=186 [junit4] 2> 18447 INFO (qtp463545395-69) [n:127.0.0.1:46293_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=policiesTest&action=DELETE&wt=javabin&version=2} status=0 QTime=962 [junit4] 2> 18451 INFO (TEST-TestPolicyCloud.testCreateCollectionAddShardUsingPolicy-seed#[7BB7E6E04C2F7DA2]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testCreateCollectionAddShardUsingPolicy [junit4] 2> 18455 INFO (OverseerCollectionConfigSetProcessor-98192030234902542-127.0.0.1:34252_solr-n_0000000000) [n:127.0.0.1:34252_solr ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000004 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 18498 INFO (TEST-TestPolicyCloud.testCreateCollectionAddReplica-seed#[7BB7E6E04C2F7DA2]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreateCollectionAddReplica [junit4] 2> 18526 INFO (qtp463545395-55) [n:127.0.0.1:46293_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (5) [junit4] 2> 18527 INFO (qtp463545395-55) [n:127.0.0.1:46293_solr ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:52066/solr ready [junit4] 2> 18530 INFO (qtp463545395-67) [n:127.0.0.1:46293_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> 18535 INFO (qtp1386392746-86) [n:127.0.0.1:54640_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> 18538 INFO (qtp1074534984-77) [n:127.0.0.1:34895_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> 18540 INFO (qtp824508534-84) [n:127.0.0.1:56214_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> 18543 INFO (qtp984317077-60) [n:127.0.0.1:34252_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> 18553 INFO (qtp463545395-55) [n:127.0.0.1:46293_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/autoscaling params={wt=javabin&version=2} status=0 QTime=53 [junit4] 2> 18556 INFO (qtp463545395-55) [n:127.0.0.1:46293_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params pullReplicas=0&replicationFactor=1&name=testCreateCollectionAddReplica&nrtReplicas=1&action=CREATE&numShards=1&tlogReplicas=0&wt=javabin&version=2&policy=c1 and sendToOCPQueue=true [junit4] 2> 18561 INFO (OverseerThreadFactory-47-thread-4-processing-n:127.0.0.1:34252_solr) [n:127.0.0.1:34252_solr ] o.a.s.c.CreateCollectionCmd Create collection testCreateCollectionAddReplica [junit4] 2> 18561 INFO (OverseerThreadFactory-47-thread-4-processing-n:127.0.0.1:34252_solr) [n:127.0.0.1:34252_solr ] o.a.s.c.CreateCollectionCmd Only one config set found in zk - using it:conf [junit4] 2> 18567 INFO (qtp463545395-48) [n:127.0.0.1:46293_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> 18569 INFO (qtp1386392746-63) [n:127.0.0.1:54640_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> 18571 INFO (qtp1074534984-53) [n:127.0.0.1:34895_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> 18574 INFO (qtp824508534-51) [n:127.0.0.1:56214_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> 18576 INFO (qtp984317077-60) [n:127.0.0.1:34252_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> 18795 INFO (OverseerStateUpdate-98192030234902542-127.0.0.1:34252_solr-n_0000000000) [n:127.0.0.1:34252_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"testCreateCollectionAddReplica", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"testCreateCollectionAddReplica_shard1_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:56214/solr";, [junit4] 2> "type":"NRT"} [junit4] 2> 19004 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node1&collection.configName=conf&newCollection=true&name=testCreateCollectionAddReplica_shard1_replica_n1&action=CREATE&numShards=1&collection=testCreateCollectionAddReplica&shard=shard1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 19005 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 19120 INFO (zkCallback-30-thread-1-processing-n:127.0.0.1:56214_solr) [n:127.0.0.1:56214_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testCreateCollectionAddReplica/state.json] for collection [testCreateCollectionAddReplica] has occurred - updating... (live nodes size: [5]) [junit4] 2> 19131 INFO (zkCallback-30-thread-2-processing-n:127.0.0.1:56214_solr) [n:127.0.0.1:56214_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testCreateCollectionAddReplica/state.json] for collection [testCreateCollectionAddReplica] has occurred - updating... (live nodes size: [5]) [junit4] 2> 20038 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0 [junit4] 2> 20050 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.s.IndexSchema [testCreateCollectionAddReplica_shard1_replica_n1] Schema name=minimal [junit4] 2> 20054 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 20054 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.c.CoreContainer Creating SolrCore 'testCreateCollectionAddReplica_shard1_replica_n1' using configuration from collection testCreateCollectionAddReplica, trusted=true [junit4] 2> 20055 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_56214.solr.core.testCreateCollectionAddReplica.shard1.replica_n1' (registry 'solr.core.testCreateCollectionAddReplica.shard1.replica_n1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@60ce22b5 [junit4] 2> 20055 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 20055 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.c.SolrCore [[testCreateCollectionAddReplica_shard1_replica_n1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/tempDir-001/node1/testCreateCollectionAddReplica_shard1_replica_n1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001/tempDir-001/node1/./testCreateCollectionAddReplica_shard1_replica_n1/data/] [junit4] 2> 20127 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 20127 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 20129 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 20129 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 20132 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@6bb8e336[testCreateCollectionAddReplica_shard1_replica_n1] main] [junit4] 2> 20136 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 20137 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 20138 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 20140 INFO (searcherExecutor-73-thread-1-processing-n:127.0.0.1:56214_solr x:testCreateCollectionAddReplica_shard1_replica_n1 s:shard1 c:testCreateCollectionAddReplica r:core_node1) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.c.SolrCore [testCreateCollectionAddReplica_shard1_replica_n1] Registered new searcher Searcher@6bb8e336[testCreateCollectionAddReplica_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 20141 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1571072494866006016 [junit4] 2> 20150 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 20150 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 20150 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:56214/solr/testCreateCollectionAddReplica_shard1_replica_n1/ [junit4] 2> 20150 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 20150 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.c.SyncStrategy http://127.0.0.1:56214/solr/testCreateCollectionAddReplica_shard1_replica_n1/ has no replicas [junit4] 2> 20150 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 20157 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:56214/solr/testCreateCollectionAddReplica_shard1_replica_n1/ shard1 [junit4] 2> 20265 INFO (zkCallback-30-thread-2-processing-n:127.0.0.1:56214_solr) [n:127.0.0.1:56214_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testCreateCollectionAddReplica/state.json] for collection [testCreateCollectionAddReplica] has occurred - updating... (live nodes size: [5]) [junit4] 2> 20265 INFO (zkCallback-30-thread-1-processing-n:127.0.0.1:56214_solr) [n:127.0.0.1:56214_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testCreateCollectionAddReplica/state.json] for collection [testCreateCollectionAddReplica] has occurred - updating... (live nodes size: [5]) [junit4] 2> 20308 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 20313 INFO (qtp824508534-47) [n:127.0.0.1:56214_solr c:testCreateCollectionAddReplica s:shard1 r:core_node1 x:testCreateCollectionAddReplica_shard1_replica_n1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node1&collection.configName=conf&newCollection=true&name=testCreateCollectionAddReplica_shard1_replica_n1&action=CREATE&numShards=1&collection=testCreateCollectionAddReplica&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1308 [junit4] 2> 20317 INFO (qtp463545395-55) [n:127.0.0.1:46293_solr ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas [junit4] 2> 20417 INFO (zkCallback-30-thread-1-processing-n:127.0.0.1:56214_solr) [n:127.0.0.1:56214_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testCreateCollectionAddReplica/state.json] for collection [testCreateCollectionAddReplica] has occurred - updating... (live nodes size: [5]) [junit4] 2> 20417 INFO (zkCallback-30-thread-2-processing-n:127.0.0.1:56214_solr) [n:127.0.0.1:56214_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testCreateCollectionAddReplica/state.json] for collection [testCreateCollectionAddReplica] has occurred - updating... (live nodes size: [5]) [junit4] 2> 20564 INFO (OverseerCollectionConfigSetProcessor-98192030234902542-127.0.0.1:34252_solr-n_0000000000) [n:127.0.0.1:34252_solr ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000006 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 21319 INFO (qtp463545395-55) [n:127.0.0.1:46293_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={pullReplicas=0&replicationFactor=1&name=testCreateCollectionAddReplica&nrtReplicas=1&action=CREATE&numShards=1&tlogReplicas=0&wt=javabin&version=2&policy=c1} status=0 QTime=2763 [junit4] 2> 21326 INFO (qtp463545395-69) [n:127.0.0.1:46293_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :addreplica with params action=ADDREPLICA&collection=testCreateCollectionAddReplica&shard=shard1&type=NRT&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 21337 INFO (OverseerThreadFactory-47-thread-5-processing-n:127.0.0.1:34252_solr) [n:127.0.0.1:34252_solr ] o.a.s.c.AddReplicaCmd addReplica() : { [junit4] 2> "collection":"testCreateCollectionAddReplica", [junit4] 2> "shard":"shard1", [junit4] 2> "type":"NRT", [junit4] 2> "operation":"addreplica"} [junit4] 2> 21355 INFO (qtp463545395-67) [n:127.0.0.1:46293_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> 21359 INFO (qtp1386392746-52) [n:127.0.0.1:54640_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> 21370 INFO (qtp1074534984-49) [n:127.0.0.1:34895_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> 21376 INFO (qtp824508534-80) [n:127.0.0.1:56214_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=1 [junit4] 2> 21378 INFO (qtp984317077-54) [n:127.0.0.1:34252_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> 21381 INFO (OverseerThreadFactory-47-thread-5-processing-n:127.0.0.1:34252_solr) [n:127.0.0.1:34252_solr ] o.a.s.c.AddReplicaCmd Node Identified 127.0.0.1:56214_solr for creating new replica [junit4] 2> 21395 INFO (OverseerStateUpdate-98192030234902542-127.0.0.1:34252_solr-n_0000000000) [n:127.0.0.1:34252_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"addreplica", [junit4] 2> "collection":"testCreateCollectionAddReplica", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"testCreateCollectionAddReplica_shard1_replica_n2", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:56214/solr";, [junit4] 2> "node_name":"127.0.0.1:56214_solr", [junit4] 2> "type":"NRT"} [junit4] 2> 21499 INFO (zkCallback-30-thread-2-processing-n:127.0.0.1:56214_solr) [n:127.0.0.1:56214_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testCreateCollectionAddReplica/state.json] for collection [testCreateCollectionAddReplica] has occurred - updating... (live nodes size: [5]) [junit4] 2> 21499 INFO (zkCallback-30-thread-1-processing-n:127.0.0.1:56214_solr) [n:127.0.0.1:56214_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testCreateCollectionAddReplica/state.json] for collection [testCreateCollectionAddReplica] has occurred - updating... (live nodes size: [5]) [junit4] 2> 21602 [...truncated too long message...] extHandler.java:1180) [junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) [junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) [junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [junit4] 2> at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:462) [junit4] 2> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) [junit4] 2> at org.eclipse.jetty.server.Server.handle(Server.java:534) [junit4] 2> at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320) [junit4] 2> at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [junit4] 2> at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273) [junit4] 2> at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95) [junit4] 2> at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [junit4] 2> at java.lang.Thread.run(Thread.java:748) [junit4] 2> [junit4] 2> 333427 INFO (qtp824508534-233) [n:127.0.0.1:56214_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={nodeName=127.0.0.1:56214_solr&onlyIfLeaderActive=true&core=testCreateCollectionAddReplica_shard1_replica_n1&coreNodeName=core_node2&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=400 QTime=21006 [junit4] 2> 333578 ERROR (qtp463545395-55) [n:127.0.0.1:46293_solr ] o.a.s.h.RequestHandlerBase org.apache.solr.common.SolrException: Solr is shutting down [junit4] 2> at org.apache.solr.handler.admin.PrepRecoveryOp.execute(PrepRecoveryOp.java:177) [junit4] 2> at org.apache.solr.handler.admin.CoreAdminOperation.execute(CoreAdminOperation.java:384) [junit4] 2> at org.apache.solr.handler.admin.CoreAdminHandler$CallInfo.call(CoreAdminHandler.java:389) [junit4] 2> at org.apache.solr.handler.admin.CoreAdminHandler.handleRequestBody(CoreAdminHandler.java:174) [junit4] 2> at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:178) [junit4] 2> at org.apache.solr.servlet.HttpSolrCall.handleAdmin(HttpSolrCall.java:747) [junit4] 2> at org.apache.solr.servlet.HttpSolrCall.handleAdminRequest(HttpSolrCall.java:728) [junit4] 2> at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:509) [junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:374) [junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:318) [junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1699) [junit4] 2> at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:139) [junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1699) [junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:582) [junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:224) [junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) [junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) [junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) [junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [junit4] 2> at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:462) [junit4] 2> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) [junit4] 2> at org.eclipse.jetty.server.Server.handle(Server.java:534) [junit4] 2> at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320) [junit4] 2> at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [junit4] 2> at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273) [junit4] 2> at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95) [junit4] 2> at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [junit4] 2> at java.lang.Thread.run(Thread.java:748) [junit4] 2> [junit4] 2> 333579 INFO (qtp463545395-55) [n:127.0.0.1:46293_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={nodeName=127.0.0.1:34895_solr&core=testCreateCollectionSplitShard_shard1_1_replica_n1&coreNodeName=core_node5&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=400 QTime=2002 [junit4] 2> 334215 WARN (zkCallback-30-thread-6-processing-n:127.0.0.1:56214_solr) [n:127.0.0.1:56214_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 334215 INFO (jetty-closer-6-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@209d6e6d{/solr,null,UNAVAILABLE} [junit4] 2> 334243 WARN (zkCallback-28-thread-4-processing-n:127.0.0.1:34895_solr) [n:127.0.0.1:34895_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 334243 INFO (jetty-closer-6-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@3b10f4aa{/solr,null,UNAVAILABLE} [junit4] 2> 334244 WARN (zkCallback-32-thread-4-processing-n:127.0.0.1:54640_solr) [n:127.0.0.1:54640_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 334245 INFO (jetty-closer-6-thread-5) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@4bbcbde3{/solr,null,UNAVAILABLE} [junit4] 2> 334247 ERROR (SUITE-TestPolicyCloud-seed#[7BB7E6E04C2F7DA2]-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> 334248 INFO (SUITE-TestPolicyCloud-seed#[7BB7E6E04C2F7DA2]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:52066 52066 [junit4] 2> 334350 INFO (Thread-3) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:52066 52066 [junit4] 2> 334353 WARN (Thread-3) [ ] o.a.s.c.ZkTestServer Watch limit violations: [junit4] 2> Maximum concurrent create/delete watches above limit: [junit4] 2> [junit4] 2> 13 /solr/clusterprops.json [junit4] 2> 13 /solr/aliases.json [junit4] 2> 5 /solr/security.json [junit4] 2> 5 /solr/configs/conf [junit4] 2> [junit4] 2> Maximum concurrent data watches above limit: [junit4] 2> [junit4] 2> 38 /solr/collections/testCreateCollectionSplitShard/state.json [junit4] 2> 15 /solr/collections/policiesTest/state.json [junit4] 2> 13 /solr/clusterstate.json [junit4] 2> 8 /solr/collections/testCreateCollectionAddReplica/state.json [junit4] 2> 2 /solr/overseer_elect/election/98192030234902539-127.0.0.1:34895_solr-n_0000000002 [junit4] 2> 2 /solr/overseer_elect/election/98192030234902542-127.0.0.1:34252_solr-n_0000000000 [junit4] 2> [junit4] 2> Maximum concurrent children watches above limit: [junit4] 2> [junit4] 2> 30 /solr/collections [junit4] 2> 13 /solr/live_nodes [junit4] 2> [junit4] 2> NOTE: leaving temporary files on disk at: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.autoscaling.TestPolicyCloud_7BB7E6E04C2F7DA2-001 [junit4] 2> Jun 24, 2017 8:10:01 AM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks [junit4] 2> WARNING: Will linger awaiting termination of 1 leaked thread(s). [junit4] 2> NOTE: test params are: codec=CheapBastard, sim=RandomSimilarity(queryNorm=false): {}, locale=en-CA, timezone=America/Phoenix [junit4] 2> NOTE: Linux 3.13.0-88-generic amd64/Oracle Corporation 1.8.0_131 (64-bit)/cpus=4,threads=1,free=145939000,total=291504128 [junit4] 2> NOTE: All tests run in this JVM: [TestJmxIntegration, TestPhraseSuggestions, TestPolicyCloud] [junit4] Completed [82/723 (1!)] on J2 in 325.25s, 4 tests, 2 errors <<< FAILURES! [...truncated 45357 lines...]
--------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org
