Build: https://jenkins.thetaphi.de/job/Lucene-Solr-7.x-Linux/264/ Java: 32bit/jdk1.8.0_144 -client -XX:+UseParallelGC
1 tests failed. FAILED: org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollectionsAPI Error Message: Something is broken in the assert for no shards using the same indexDir - probably something was changed in the attributes published in the MBean of SolrCore : {} Stack Trace: java.lang.AssertionError: Something is broken in the assert for no shards using the same indexDir - probably something was changed in the attributes published in the MBean of SolrCore : {} at __randomizedtesting.SeedInfo.seed([F18C8E7BB0DC9844:B9F9FACFB6EFB7D1]:0) at org.junit.Assert.fail(Assert.java:93) at org.junit.Assert.assertTrue(Assert.java:43) at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.checkNoTwoShardsUseTheSameIndexDir(CollectionsAPIDistributedZkTest.java:581) at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollectionsAPI(CollectionsAPIDistributedZkTest.java:462) 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$8.evaluate(RandomizedRunner.java:907) at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943) at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957) 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 11854 lines...] [junit4] Suite: org.apache.solr.cloud.CollectionsAPIDistributedZkTest [junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_F18C8E7BB0DC9844-001/init-core-data-001 [junit4] 2> 908535 WARN (SUITE-CollectionsAPIDistributedZkTest-seed#[F18C8E7BB0DC9844]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=31 numCloses=31 [junit4] 2> 908535 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[F18C8E7BB0DC9844]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=false [junit4] 2> 908536 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[F18C8E7BB0DC9844]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN) [junit4] 2> 908537 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[F18C8E7BB0DC9844]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom [junit4] 2> 908537 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[F18C8E7BB0DC9844]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 4 servers in /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_F18C8E7BB0DC9844-001/tempDir-001 [junit4] 2> 908538 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[F18C8E7BB0DC9844]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER [junit4] 2> 908538 INFO (Thread-3405) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0 [junit4] 2> 908538 INFO (Thread-3405) [ ] o.a.s.c.ZkTestServer Starting server [junit4] 2> 908539 ERROR (Thread-3405) [ ] 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> 908638 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[F18C8E7BB0DC9844]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:37627 [junit4] 2> 908647 INFO (jetty-launcher-1437-thread-4) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 908647 INFO (jetty-launcher-1437-thread-3) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 908647 INFO (jetty-launcher-1437-thread-2) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 908647 INFO (jetty-launcher-1437-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 908649 INFO (jetty-launcher-1437-thread-3) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@1a9ef83{/solr,null,AVAILABLE} [junit4] 2> 908649 INFO (jetty-launcher-1437-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@8642b4{/solr,null,AVAILABLE} [junit4] 2> 908654 INFO (jetty-launcher-1437-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@105fde9{/solr,null,AVAILABLE} [junit4] 2> 908654 INFO (jetty-launcher-1437-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@ec07f9{SSL,[ssl, http/1.1]}{127.0.0.1:33271} [junit4] 2> 908654 INFO (jetty-launcher-1437-thread-3) [ ] o.e.j.s.AbstractConnector Started ServerConnector@3ed63a{SSL,[ssl, http/1.1]}{127.0.0.1:43179} [junit4] 2> 908654 INFO (jetty-launcher-1437-thread-1) [ ] o.e.j.s.Server Started @909833ms [junit4] 2> 908655 INFO (jetty-launcher-1437-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=33271} [junit4] 2> 908654 INFO (jetty-launcher-1437-thread-4) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@fce899{/solr,null,AVAILABLE} [junit4] 2> 908655 ERROR (jetty-launcher-1437-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 908655 INFO (jetty-launcher-1437-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 7.1.0 [junit4] 2> 908655 INFO (jetty-launcher-1437-thread-3) [ ] o.e.j.s.Server Started @909834ms [junit4] 2> 908656 INFO (jetty-launcher-1437-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 908656 INFO (jetty-launcher-1437-thread-3) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=43179} [junit4] 2> 908656 INFO (jetty-launcher-1437-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null, Default config dir: null [junit4] 2> 908655 INFO (jetty-launcher-1437-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@64a0d{SSL,[ssl, http/1.1]}{127.0.0.1:44865} [junit4] 2> 908656 INFO (jetty-launcher-1437-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-08-15T11:27:31.672Z [junit4] 2> 908656 INFO (jetty-launcher-1437-thread-2) [ ] o.e.j.s.Server Started @909835ms [junit4] 2> 908656 ERROR (jetty-launcher-1437-thread-3) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 908656 INFO (jetty-launcher-1437-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=44865} [junit4] 2> 908657 INFO (jetty-launcher-1437-thread-3) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 7.1.0 [junit4] 2> 908657 INFO (jetty-launcher-1437-thread-3) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 908657 INFO (jetty-launcher-1437-thread-3) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null, Default config dir: null [junit4] 2> 908657 INFO (jetty-launcher-1437-thread-3) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-08-15T11:27:31.673Z [junit4] 2> 908657 ERROR (jetty-launcher-1437-thread-2) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 908657 INFO (jetty-launcher-1437-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 7.1.0 [junit4] 2> 908657 INFO (jetty-launcher-1437-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 908657 INFO (jetty-launcher-1437-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null, Default config dir: null [junit4] 2> 908657 INFO (jetty-launcher-1437-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-08-15T11:27:31.673Z [junit4] 2> 908656 INFO (jetty-launcher-1437-thread-4) [ ] o.e.j.s.AbstractConnector Started ServerConnector@15c7d9f{SSL,[ssl, http/1.1]}{127.0.0.1:38517} [junit4] 2> 908657 INFO (jetty-launcher-1437-thread-4) [ ] o.e.j.s.Server Started @909837ms [junit4] 2> 908657 INFO (jetty-launcher-1437-thread-4) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=38517} [junit4] 2> 908658 ERROR (jetty-launcher-1437-thread-4) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 908658 INFO (jetty-launcher-1437-thread-4) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 7.1.0 [junit4] 2> 908658 INFO (jetty-launcher-1437-thread-4) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 908658 INFO (jetty-launcher-1437-thread-4) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null, Default config dir: null [junit4] 2> 908658 INFO (jetty-launcher-1437-thread-4) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-08-15T11:27:31.674Z [junit4] 2> 908663 INFO (jetty-launcher-1437-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 908664 INFO (jetty-launcher-1437-thread-4) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 908664 INFO (jetty-launcher-1437-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 908664 INFO (jetty-launcher-1437-thread-3) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 908679 INFO (jetty-launcher-1437-thread-4) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:37627/solr [junit4] 2> 908679 INFO (jetty-launcher-1437-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:37627/solr [junit4] 2> 908679 INFO (jetty-launcher-1437-thread-3) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:37627/solr [junit4] 2> 908679 INFO (jetty-launcher-1437-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:37627/solr [junit4] 2> 908744 INFO (jetty-launcher-1437-thread-2) [n:127.0.0.1:44865_solr ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 908744 INFO (jetty-launcher-1437-thread-4) [n:127.0.0.1:38517_solr ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 908745 INFO (jetty-launcher-1437-thread-4) [n:127.0.0.1:38517_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:38517_solr [junit4] 2> 908745 INFO (jetty-launcher-1437-thread-2) [n:127.0.0.1:44865_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44865_solr [junit4] 2> 908746 INFO (jetty-launcher-1437-thread-4) [n:127.0.0.1:38517_solr ] o.a.s.c.Overseer Overseer (id=98487268249042954-127.0.0.1:38517_solr-n_0000000000) starting [junit4] 2> 908747 INFO (zkCallback-1456-thread-1-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 908747 INFO (zkCallback-1459-thread-1-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 908751 INFO (jetty-launcher-1437-thread-3) [n:127.0.0.1:43179_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 908755 INFO (jetty-launcher-1437-thread-3) [n:127.0.0.1:43179_solr ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 908757 INFO (jetty-launcher-1437-thread-1) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 908758 INFO (jetty-launcher-1437-thread-1) [n:127.0.0.1:33271_solr ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 908759 INFO (jetty-launcher-1437-thread-1) [n:127.0.0.1:33271_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33271_solr [junit4] 2> 908761 INFO (zkCallback-1456-thread-1-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 908762 INFO (zkCallback-1459-thread-1-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 908762 INFO (zkCallback-1458-thread-1-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 908763 INFO (zkCallback-1457-thread-1-processing-n:127.0.0.1:43179_solr) [n:127.0.0.1:43179_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 908777 INFO (jetty-launcher-1437-thread-4) [n:127.0.0.1:38517_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38517_solr [junit4] 2> 908778 INFO (zkCallback-1456-thread-1-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 908778 INFO (zkCallback-1459-thread-1-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 908778 INFO (zkCallback-1457-thread-1-processing-n:127.0.0.1:43179_solr) [n:127.0.0.1:43179_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 908780 INFO (jetty-launcher-1437-thread-3) [n:127.0.0.1:43179_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43179_solr [junit4] 2> 908781 INFO (zkCallback-1459-thread-1-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 908785 INFO (zkCallback-1458-thread-1-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (4) [junit4] 2> 908785 INFO (zkCallback-1456-thread-1-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 908785 INFO (zkCallback-1457-thread-1-processing-n:127.0.0.1:43179_solr) [n:127.0.0.1:43179_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 908958 WARN (jetty-launcher-1437-thread-4) [n:127.0.0.1:38517_solr ] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 908958 WARN (jetty-launcher-1437-thread-4) [n:127.0.0.1:38517_solr ] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 908958 WARN (jetty-launcher-1437-thread-4) [n:127.0.0.1:38517_solr ] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 908959 INFO (jetty-launcher-1437-thread-4) [n:127.0.0.1:38517_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_F18C8E7BB0DC9844-001/tempDir-001/node4 [junit4] 2> 908965 WARN (jetty-launcher-1437-thread-2) [n:127.0.0.1:44865_solr ] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 908966 WARN (jetty-launcher-1437-thread-2) [n:127.0.0.1:44865_solr ] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 908966 WARN (jetty-launcher-1437-thread-2) [n:127.0.0.1:44865_solr ] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 908966 INFO (jetty-launcher-1437-thread-2) [n:127.0.0.1:44865_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_F18C8E7BB0DC9844-001/tempDir-001/node2 [junit4] 2> 909155 WARN (jetty-launcher-1437-thread-1) [n:127.0.0.1:33271_solr ] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 909155 WARN (jetty-launcher-1437-thread-1) [n:127.0.0.1:33271_solr ] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 909155 WARN (jetty-launcher-1437-thread-3) [n:127.0.0.1:43179_solr ] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 909155 WARN (jetty-launcher-1437-thread-1) [n:127.0.0.1:33271_solr ] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 909155 WARN (jetty-launcher-1437-thread-3) [n:127.0.0.1:43179_solr ] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 909156 WARN (jetty-launcher-1437-thread-3) [n:127.0.0.1:43179_solr ] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 909156 INFO (jetty-launcher-1437-thread-3) [n:127.0.0.1:43179_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_F18C8E7BB0DC9844-001/tempDir-001/node3 [junit4] 2> 909156 INFO (jetty-launcher-1437-thread-1) [n:127.0.0.1:33271_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_F18C8E7BB0DC9844-001/tempDir-001/node1 [junit4] 2> 909171 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[F18C8E7BB0DC9844]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 909172 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[F18C8E7BB0DC9844]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:37627/solr ready [junit4] 2> 909210 INFO (TEST-CollectionsAPIDistributedZkTest.deleteCollectionRemovesStaleZkCollectionsNode-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.SolrTestCaseJ4 ###Starting deleteCollectionRemovesStaleZkCollectionsNode [junit4] 2> 909210 INFO (TEST-CollectionsAPIDistributedZkTest.deleteCollectionRemovesStaleZkCollectionsNode-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 909260 INFO (qtp20401794-10131) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=out_of_sync_collection&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 909264 INFO (qtp20401794-10131) [n:127.0.0.1:33271_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=out_of_sync_collection&action=DELETE&wt=javabin&version=2} status=0 QTime=4 [junit4] 2> 909267 INFO (qtp20401794-10107) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 909267 INFO (qtp20401794-10107) [n:127.0.0.1:33271_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 909267 INFO (TEST-CollectionsAPIDistributedZkTest.deleteCollectionRemovesStaleZkCollectionsNode-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.SolrTestCaseJ4 ###Ending deleteCollectionRemovesStaleZkCollectionsNode [junit4] 2> 909292 INFO (TEST-CollectionsAPIDistributedZkTest.testMaxNodesPerShard-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testMaxNodesPerShard [junit4] 2> 909294 INFO (TEST-CollectionsAPIDistributedZkTest.testMaxNodesPerShard-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 909297 INFO (qtp20401794-10127) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=2&collection.configName=conf&name=oversharded&nrtReplicas=2&action=CREATE&numShards=3&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 909299 INFO (OverseerThreadFactory-4170-thread-2-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.CreateCollectionCmd Create collection oversharded [junit4] 2> 909299 INFO (OverseerCollectionConfigSetProcessor-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_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> 909299 ERROR (OverseerThreadFactory-4170-thread-2-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.OverseerCollectionMessageHandler Collection: oversharded operation: create failed:org.apache.solr.common.SolrException: Cannot create collection oversharded. Value of maxShardsPerNode is 1, and the number of nodes currently live or live and part of your createNodeSet is 4. This allows a maximum of 4 to be created. Value of numShards is 3, value of nrtReplicas is 2, value of tlogReplicas is 0 and value of pullReplicas is 0. This requires 6 shards to be created (higher than the allowed number) [junit4] 2> at org.apache.solr.cloud.CreateCollectionCmd.call(CreateCollectionCmd.java:157) [junit4] 2> at org.apache.solr.cloud.OverseerCollectionMessageHandler.processMessage(OverseerCollectionMessageHandler.java:227) [junit4] 2> at org.apache.solr.cloud.OverseerTaskProcessor$Runner.run(OverseerTaskProcessor.java:464) [junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] 2> at java.lang.Thread.run(Thread.java:748) [junit4] 2> [junit4] 2> 909301 INFO (qtp20401794-10127) [n:127.0.0.1:33271_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=2&collection.configName=conf&name=oversharded&nrtReplicas=2&action=CREATE&numShards=3&wt=javabin&version=2} status=400 QTime=4 [junit4] 2> 909302 INFO (TEST-CollectionsAPIDistributedZkTest.testMaxNodesPerShard-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testMaxNodesPerShard [junit4] 2> 909328 INFO (TEST-CollectionsAPIDistributedZkTest.testCreationAndDeletion-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreationAndDeletion [junit4] 2> 909328 INFO (TEST-CollectionsAPIDistributedZkTest.testCreationAndDeletion-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 909330 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf&name=created_and_deleted&nrtReplicas=1&action=CREATE&numShards=1&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 909332 INFO (OverseerThreadFactory-4170-thread-3-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.CreateCollectionCmd Create collection created_and_deleted [junit4] 2> 909332 INFO (OverseerCollectionConfigSetProcessor-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_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> 909438 INFO (OverseerStateUpdate-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"created_and_deleted", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"created_and_deleted_shard1_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:44865/solr", [junit4] 2> "type":"NRT"} [junit4] 2> 909694 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node2&collection.configName=conf&newCollection=true&name=created_and_deleted_shard1_replica_n1&action=CREATE&numShards=1&collection=created_and_deleted&shard=shard1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 909695 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 909806 INFO (zkCallback-1459-thread-1-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/created_and_deleted/state.json] for collection [created_and_deleted] has occurred - updating... (live nodes size: [4]) [junit4] 2> 909806 INFO (zkCallback-1459-thread-2-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/created_and_deleted/state.json] for collection [created_and_deleted] has occurred - updating... (live nodes size: [4]) [junit4] 2> 910714 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.1.0 [junit4] 2> 910722 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.s.IndexSchema [created_and_deleted_shard1_replica_n1] Schema name=minimal [junit4] 2> 910725 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 910725 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.c.CoreContainer Creating SolrCore 'created_and_deleted_shard1_replica_n1' using configuration from collection created_and_deleted, trusted=true [junit4] 2> 910726 WARN (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 910726 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 910726 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.c.SolrCore [[created_and_deleted_shard1_replica_n1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_F18C8E7BB0DC9844-001/tempDir-001/node2/created_and_deleted_shard1_replica_n1], dataDir=[/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_F18C8E7BB0DC9844-001/tempDir-001/node2/created_and_deleted_shard1_replica_n1/data/] [junit4] 2> 910765 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 910765 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 910765 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 910765 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 910766 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@16a8ae4[created_and_deleted_shard1_replica_n1] main] [junit4] 2> 910767 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 910767 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 910768 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 910768 INFO (searcherExecutor-4179-thread-1-processing-n:127.0.0.1:44865_solr x:created_and_deleted_shard1_replica_n1 s:shard1 c:created_and_deleted r:core_node2) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.c.SolrCore [created_and_deleted_shard1_replica_n1] Registered new searcher Searcher@16a8ae4[created_and_deleted_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 910768 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1575796294323011584 [junit4] 2> 910772 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 910772 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 910773 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:44865/solr/created_and_deleted_shard1_replica_n1/ [junit4] 2> 910773 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 910773 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.c.SyncStrategy https://127.0.0.1:44865/solr/created_and_deleted_shard1_replica_n1/ has no replicas [junit4] 2> 910773 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 910776 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:44865/solr/created_and_deleted_shard1_replica_n1/ shard1 [junit4] 2> 910878 INFO (zkCallback-1459-thread-2-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/created_and_deleted/state.json] for collection [created_and_deleted] has occurred - updating... (live nodes size: [4]) [junit4] 2> 910878 INFO (zkCallback-1459-thread-1-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/created_and_deleted/state.json] for collection [created_and_deleted] has occurred - updating... (live nodes size: [4]) [junit4] 2> 910927 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_replica_n1] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 910928 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:created_and_deleted s:shard1 r:core_node2 x:created_and_deleted_shard1_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=created_and_deleted_shard1_replica_n1&action=CREATE&numShards=1&collection=created_and_deleted&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1234 [junit4] 2> 910933 INFO (qtp20401794-10129) [n:127.0.0.1:33271_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> 911033 INFO (zkCallback-1459-thread-1-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/created_and_deleted/state.json] for collection [created_and_deleted] has occurred - updating... (live nodes size: [4]) [junit4] 2> 911033 INFO (zkCallback-1459-thread-2-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/created_and_deleted/state.json] for collection [created_and_deleted] has occurred - updating... (live nodes size: [4]) [junit4] 2> 911334 INFO (OverseerCollectionConfigSetProcessor-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_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> 911933 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf&name=created_and_deleted&nrtReplicas=1&action=CREATE&numShards=1&wt=javabin&version=2} status=0 QTime=2603 [junit4] 2> 911935 INFO (qtp20401794-10131) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 911935 INFO (qtp20401794-10131) [n:127.0.0.1:33271_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 911936 INFO (qtp20401794-10107) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=created_and_deleted&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 911938 INFO (OverseerThreadFactory-4170-thread-4-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true [junit4] 2> 911940 INFO (qtp33360035-10126) [n:127.0.0.1:44865_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.created_and_deleted.shard1.replica_n1, tag=null [junit4] 2> 911940 INFO (qtp33360035-10126) [n:127.0.0.1:44865_solr ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@15ceef3: rootName = null, domain = solr.core.created_and_deleted.shard1.replica_n1, service url = null, agent id = null] for registry solr.core.created_and_deleted.shard1.replica_n1 / null [junit4] 2> 911941 INFO (qtp33360035-10126) [n:127.0.0.1:44865_solr ] o.a.s.c.SolrCore [created_and_deleted_shard1_replica_n1] CLOSING SolrCore org.apache.solr.core.SolrCore@12315bc [junit4] 2> 911941 INFO (qtp33360035-10126) [n:127.0.0.1:44865_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.created_and_deleted.shard1.replica_n1, tag=19076540 [junit4] 2> 911941 INFO (qtp33360035-10126) [n:127.0.0.1:44865_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.created_and_deleted.shard1.leader, tag=19076540 [junit4] 2> 911943 INFO (qtp33360035-10126) [n:127.0.0.1:44865_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=created_and_deleted_shard1_replica_n1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=3 [junit4] 2> 912647 INFO (qtp20401794-10107) [n:127.0.0.1:33271_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=created_and_deleted&action=DELETE&wt=javabin&version=2} status=0 QTime=711 [junit4] 2> 912648 INFO (qtp20401794-10127) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 912648 INFO (qtp20401794-10127) [n:127.0.0.1:33271_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 912650 INFO (TEST-CollectionsAPIDistributedZkTest.testCreationAndDeletion-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testCreationAndDeletion [junit4] 2> 912691 INFO (TEST-CollectionsAPIDistributedZkTest.testDeleteNonExistentCollection-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testDeleteNonExistentCollection [junit4] 2> 912692 INFO (TEST-CollectionsAPIDistributedZkTest.testDeleteNonExistentCollection-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 912694 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=unknown_collection&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 912695 INFO (OverseerCollectionConfigSetProcessor-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_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> 912695 INFO (OverseerThreadFactory-4170-thread-5-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true [junit4] 2> 912695 ERROR (OverseerThreadFactory-4170-thread-5-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.OverseerCollectionMessageHandler Collection: unknown_collection operation: delete failed:org.apache.solr.common.SolrException: Could not find collection : unknown_collection [junit4] 2> at org.apache.solr.common.cloud.ClusterState.getCollection(ClusterState.java:109) [junit4] 2> at org.apache.solr.cloud.OverseerCollectionMessageHandler.collectionCmd(OverseerCollectionMessageHandler.java:795) [junit4] 2> at org.apache.solr.cloud.DeleteCollectionCmd.call(DeleteCollectionCmd.java:88) [junit4] 2> at org.apache.solr.cloud.OverseerCollectionMessageHandler.processMessage(OverseerCollectionMessageHandler.java:227) [junit4] 2> at org.apache.solr.cloud.OverseerTaskProcessor$Runner.run(OverseerTaskProcessor.java:464) [junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] 2> at java.lang.Thread.run(Thread.java:748) [junit4] 2> [junit4] 2> 912697 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=unknown_collection&action=DELETE&wt=javabin&version=2} status=400 QTime=3 [junit4] 2> 912698 INFO (qtp20401794-10131) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=2&collection.configName=conf&name=acollectionafterbaddelete&nrtReplicas=2&action=CREATE&numShards=1&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 912699 INFO (OverseerThreadFactory-4170-thread-5-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.CreateCollectionCmd Create collection acollectionafterbaddelete [junit4] 2> 912700 INFO (OverseerCollectionConfigSetProcessor-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_solr ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000008 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 912904 INFO (OverseerStateUpdate-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"acollectionafterbaddelete", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"acollectionafterbaddelete_shard1_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:44865/solr", [junit4] 2> "type":"NRT"} [junit4] 2> 912905 INFO (OverseerStateUpdate-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"acollectionafterbaddelete", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"acollectionafterbaddelete_shard1_replica_n2", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:33271/solr", [junit4] 2> "type":"NRT"} [junit4] 2> 913109 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node3&collection.configName=conf&newCollection=true&name=acollectionafterbaddelete_shard1_replica_n1&action=CREATE&numShards=1&collection=acollectionafterbaddelete&shard=shard1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 913112 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node4&collection.configName=conf&newCollection=true&name=acollectionafterbaddelete_shard1_replica_n2&action=CREATE&numShards=1&collection=acollectionafterbaddelete&shard=shard1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 913113 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 913215 INFO (zkCallback-1459-thread-2-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 913215 INFO (zkCallback-1459-thread-1-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 913215 INFO (zkCallback-1458-thread-1-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 913215 INFO (zkCallback-1458-thread-2-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 914120 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.1.0 [junit4] 2> 914121 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.1.0 [junit4] 2> 914136 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.s.IndexSchema [acollectionafterbaddelete_shard1_replica_n1] Schema name=minimal [junit4] 2> 914138 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.s.IndexSchema [acollectionafterbaddelete_shard1_replica_n2] Schema name=minimal [junit4] 2> 914140 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 914140 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.c.CoreContainer Creating SolrCore 'acollectionafterbaddelete_shard1_replica_n1' using configuration from collection acollectionafterbaddelete, trusted=true [junit4] 2> 914140 WARN (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 914141 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 914141 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 914141 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.c.CoreContainer Creating SolrCore 'acollectionafterbaddelete_shard1_replica_n2' using configuration from collection acollectionafterbaddelete, trusted=true [junit4] 2> 914141 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.c.SolrCore [[acollectionafterbaddelete_shard1_replica_n1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_F18C8E7BB0DC9844-001/tempDir-001/node2/acollectionafterbaddelete_shard1_replica_n1], dataDir=[/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_F18C8E7BB0DC9844-001/tempDir-001/node2/acollectionafterbaddelete_shard1_replica_n1/data/] [junit4] 2> 914141 WARN (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.m.r.SolrJmxReporter No JMX server found. Not exposing Solr metrics via JMX. [junit4] 2> 914141 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 914141 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.c.SolrCore [[acollectionafterbaddelete_shard1_replica_n2] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_F18C8E7BB0DC9844-001/tempDir-001/node1/acollectionafterbaddelete_shard1_replica_n2], dataDir=[/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_F18C8E7BB0DC9844-001/tempDir-001/node1/acollectionafterbaddelete_shard1_replica_n2/data/] [junit4] 2> 914187 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 914187 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 914187 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 914187 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 914188 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 914188 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 914188 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 914188 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 914189 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.s.SolrIndexSearcher Opening [Searcher@11ac0e5[acollectionafterbaddelete_shard1_replica_n2] main] [junit4] 2> 914189 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@195abab[acollectionafterbaddelete_shard1_replica_n1] main] [junit4] 2> 914190 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 914190 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 914190 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 914190 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 914191 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 914191 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 914191 INFO (searcherExecutor-4184-thread-1-processing-n:127.0.0.1:44865_solr x:acollectionafterbaddelete_shard1_replica_n1 s:shard1 c:acollectionafterbaddelete r:core_node3) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.c.SolrCore [acollectionafterbaddelete_shard1_replica_n1] Registered new searcher Searcher@195abab[acollectionafterbaddelete_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 914191 INFO (searcherExecutor-4185-thread-1-processing-n:127.0.0.1:33271_solr x:acollectionafterbaddelete_shard1_replica_n2 s:shard1 c:acollectionafterbaddelete r:core_node4) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.c.SolrCore [acollectionafterbaddelete_shard1_replica_n2] Registered new searcher Searcher@11ac0e5[acollectionafterbaddelete_shard1_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 914191 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1575796297912287232 [junit4] 2> 914191 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1575796297912287232 [junit4] 2> 914194 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 914195 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 914195 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:44865/solr/acollectionafterbaddelete_shard1_replica_n1/ [junit4] 2> 914195 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.u.PeerSync PeerSync: core=acollectionafterbaddelete_shard1_replica_n1 url=https://127.0.0.1:44865/solr START replicas=[https://127.0.0.1:33271/solr/acollectionafterbaddelete_shard1_replica_n2/] nUpdates=100 [junit4] 2> 914199 INFO (qtp20401794-10111) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.c.S.Request [acollectionafterbaddelete_shard1_replica_n2] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 914298 INFO (zkCallback-1458-thread-2-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 914298 INFO (zkCallback-1459-thread-2-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 914298 INFO (zkCallback-1458-thread-1-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 914298 INFO (zkCallback-1459-thread-1-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 914495 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.u.PeerSync PeerSync: core=acollectionafterbaddelete_shard1_replica_n1 url=https://127.0.0.1:44865/solr DONE. We have no versions. sync failed. [junit4] 2> 914495 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate [junit4] 2> 914495 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway [junit4] 2> 914495 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 914498 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:44865/solr/acollectionafterbaddelete_shard1_replica_n1/ shard1 [junit4] 2> 914599 INFO (zkCallback-1459-thread-1-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 914599 INFO (zkCallback-1458-thread-2-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 914599 INFO (zkCallback-1459-thread-2-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 914599 INFO (zkCallback-1458-thread-1-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 914648 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 914650 INFO (qtp33360035-10132) [n:127.0.0.1:44865_solr c:acollectionafterbaddelete s:shard1 r:core_node3 x:acollectionafterbaddelete_shard1_replica_n1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node3&collection.configName=conf&newCollection=true&name=acollectionafterbaddelete_shard1_replica_n1&action=CREATE&numShards=1&collection=acollectionafterbaddelete&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1541 [junit4] 2> 914751 INFO (zkCallback-1459-thread-2-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 914751 INFO (zkCallback-1458-thread-2-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 914751 INFO (zkCallback-1459-thread-1-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 914751 INFO (zkCallback-1458-thread-1-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 915196 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr c:acollectionafterbaddelete s:shard1 r:core_node4 x:acollectionafterbaddelete_shard1_replica_n2] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node4&collection.configName=conf&newCollection=true&name=acollectionafterbaddelete_shard1_replica_n2&action=CREATE&numShards=1&collection=acollectionafterbaddelete&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=2084 [junit4] 2> 915198 INFO (qtp20401794-10131) [n:127.0.0.1:33271_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> 915298 INFO (zkCallback-1458-thread-1-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 915298 INFO (zkCallback-1459-thread-1-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 915298 INFO (zkCallback-1459-thread-2-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 915298 INFO (zkCallback-1458-thread-2-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/acollectionafterbaddelete/state.json] for collection [acollectionafterbaddelete] has occurred - updating... (live nodes size: [4]) [junit4] 2> 916198 INFO (qtp20401794-10131) [n:127.0.0.1:33271_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=2&collection.configName=conf&name=acollectionafterbaddelete&nrtReplicas=2&action=CREATE&numShards=1&wt=javabin&version=2} status=0 QTime=3500 [junit4] 2> 916201 INFO (TEST-CollectionsAPIDistributedZkTest.testDeleteNonExistentCollection-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testDeleteNonExistentCollection [junit4] 2> 916231 INFO (TEST-CollectionsAPIDistributedZkTest.testNoConfigSetExist-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNoConfigSetExist [junit4] 2> 916231 INFO (TEST-CollectionsAPIDistributedZkTest.testNoConfigSetExist-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 916233 INFO (qtp20401794-10107) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=acollectionafterbaddelete&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 916234 INFO (OverseerCollectionConfigSetProcessor-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_solr ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000010 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 916234 INFO (OverseerThreadFactory-4170-thread-5-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true [junit4] 2> 916239 INFO (qtp33360035-10136) [n:127.0.0.1:44865_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.acollectionafterbaddelete.shard1.replica_n1, tag=null [junit4] 2> 916239 INFO (qtp33360035-10136) [n:127.0.0.1:44865_solr ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@d41f65: rootName = null, domain = solr.core.acollectionafterbaddelete.shard1.replica_n1, service url = null, agent id = null] for registry solr.core.acollectionafterbaddelete.shard1.replica_n1 / null [junit4] 2> 916239 INFO (qtp20401794-10127) [n:127.0.0.1:33271_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.acollectionafterbaddelete.shard1.replica_n2, tag=null [junit4] 2> 916239 INFO (qtp33360035-10136) [n:127.0.0.1:44865_solr ] o.a.s.c.SolrCore [acollectionafterbaddelete_shard1_replica_n1] CLOSING SolrCore org.apache.solr.core.SolrCore@29b0a2 [junit4] 2> 916239 INFO (qtp20401794-10127) [n:127.0.0.1:33271_solr ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@cfe42e: rootName = null, domain = solr.core.acollectionafterbaddelete.shard1.replica_n2, service url = null, agent id = null] for registry solr.core.acollectionafterbaddelete.shard1.replica_n2 / null [junit4] 2> 916239 INFO (qtp33360035-10136) [n:127.0.0.1:44865_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.acollectionafterbaddelete.shard1.replica_n1, tag=2732194 [junit4] 2> 916239 INFO (qtp20401794-10127) [n:127.0.0.1:33271_solr ] o.a.s.c.SolrCore [acollectionafterbaddelete_shard1_replica_n2] CLOSING SolrCore org.apache.solr.core.SolrCore@7f5dd2 [junit4] 2> 916239 INFO (qtp33360035-10136) [n:127.0.0.1:44865_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.acollectionafterbaddelete.shard1.leader, tag=2732194 [junit4] 2> 916239 INFO (qtp20401794-10127) [n:127.0.0.1:33271_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.acollectionafterbaddelete.shard1.replica_n2, tag=8347090 [junit4] 2> 916239 INFO (qtp20401794-10127) [n:127.0.0.1:33271_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.acollectionafterbaddelete.shard1.leader, tag=8347090 [junit4] 2> 916241 INFO (qtp20401794-10127) [n:127.0.0.1:33271_solr ] o.a.s.c.ShardLeaderElectionContextBase No version found for ephemeral leader parent node, won't remove previous leader registration. [junit4] 2> 916241 WARN (zkCallback-1458-thread-2-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.LeaderElector Our node is no longer in line to be leader [junit4] 2> 916242 INFO (qtp20401794-10127) [n:127.0.0.1:33271_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=acollectionafterbaddelete_shard1_replica_n2&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=2 [junit4] 2> 916242 INFO (qtp33360035-10136) [n:127.0.0.1:44865_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=acollectionafterbaddelete_shard1_replica_n1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=3 [junit4] 2> 916946 INFO (qtp20401794-10107) [n:127.0.0.1:33271_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=acollectionafterbaddelete&action=DELETE&wt=javabin&version=2} status=0 QTime=713 [junit4] 2> 916947 INFO (qtp20401794-10113) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf123&name=noconfig&nrtReplicas=1&action=CREATE&numShards=1&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 916949 INFO (OverseerThreadFactory-4170-thread-5-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.CreateCollectionCmd Create collection noconfig [junit4] 2> 916949 INFO (OverseerCollectionConfigSetProcessor-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_solr ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000012 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 916949 ERROR (OverseerThreadFactory-4170-thread-5-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.OverseerCollectionMessageHandler Collection: noconfig operation: create failed:org.apache.solr.common.SolrException: Can not find the specified config set: conf123 [junit4] 2> at org.apache.solr.cloud.OverseerCollectionMessageHandler.validateConfigOrThrowSolrException(OverseerCollectionMessageHandler.java:753) [junit4] 2> at org.apache.solr.cloud.CreateCollectionCmd.call(CreateCollectionCmd.java:94) [junit4] 2> at org.apache.solr.cloud.OverseerCollectionMessageHandler.processMessage(OverseerCollectionMessageHandler.java:227) [junit4] 2> at org.apache.solr.cloud.OverseerTaskProcessor$Runner.run(OverseerTaskProcessor.java:464) [junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] 2> at java.lang.Thread.run(Thread.java:748) [junit4] 2> [junit4] 2> 916951 INFO (qtp20401794-10113) [n:127.0.0.1:33271_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf123&name=noconfig&nrtReplicas=1&action=CREATE&numShards=1&wt=javabin&version=2} status=400 QTime=3 [junit4] 2> 917954 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 917954 INFO (qtp20401794-10129) [n:127.0.0.1:33271_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 917955 INFO (TEST-CollectionsAPIDistributedZkTest.testNoConfigSetExist-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testNoConfigSetExist [junit4] 2> 917996 INFO (TEST-CollectionsAPIDistributedZkTest.testTooManyReplicas-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testTooManyReplicas [junit4] 2> 917997 INFO (TEST-CollectionsAPIDistributedZkTest.testTooManyReplicas-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 917999 INFO (qtp20401794-10131) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=10&collection.configName=conf&name=collection&nrtReplicas=10&action=CREATE&numShards=2&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 918000 INFO (OverseerThreadFactory-4170-thread-5-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.CreateCollectionCmd Create collection collection [junit4] 2> 918000 WARN (OverseerThreadFactory-4170-thread-5-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.CreateCollectionCmd Specified number of replicas of 10 on collection collection is higher than the number of Solr instances currently live or live and part of your createNodeSet(4). It's unusual to run two replica of the same slice on the same Solr-instance. [junit4] 2> 918000 INFO (OverseerCollectionConfigSetProcessor-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_solr ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000014 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 918001 ERROR (OverseerThreadFactory-4170-thread-5-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.OverseerCollectionMessageHandler Collection: collection operation: create failed:org.apache.solr.common.SolrException: Cannot create collection collection. Value of maxShardsPerNode is 1, and the number of nodes currently live or live and part of your createNodeSet is 4. This allows a maximum of 4 to be created. Value of numShards is 2, value of nrtReplicas is 10, value of tlogReplicas is 0 and value of pullReplicas is 0. This requires 20 shards to be created (higher than the allowed number) [junit4] 2> at org.apache.solr.cloud.CreateCollectionCmd.call(CreateCollectionCmd.java:157) [junit4] 2> at org.apache.solr.cloud.OverseerCollectionMessageHandler.processMessage(OverseerCollectionMessageHandler.java:227) [junit4] 2> at org.apache.solr.cloud.OverseerTaskProcessor$Runner.run(OverseerTaskProcessor.java:464) [junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] 2> at java.lang.Thread.run(Thread.java:748) [junit4] 2> [junit4] 2> 918003 INFO (qtp20401794-10131) [n:127.0.0.1:33271_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=10&collection.configName=conf&name=collection&nrtReplicas=10&action=CREATE&numShards=2&wt=javabin&version=2} status=400 QTime=4 [junit4] 2> 918004 INFO (TEST-CollectionsAPIDistributedZkTest.testTooManyReplicas-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testTooManyReplicas [junit4] 2> 918040 INFO (TEST-CollectionsAPIDistributedZkTest.testCollectionReload-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCollectionReload [junit4] 2> 918041 INFO (TEST-CollectionsAPIDistributedZkTest.testCollectionReload-seed#[F18C8E7BB0DC9844]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 918043 INFO (qtp20401794-10127) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=2&collection.configName=conf&name=reloaded_collection&nrtReplicas=2&action=CREATE&numShards=2&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 918044 INFO (OverseerThreadFactory-4170-thread-5-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.CreateCollectionCmd Create collection reloaded_collection [junit4] 2> 918044 INFO (OverseerCollectionConfigSetProcessor-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_solr ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000016 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 918254 INFO (OverseerStateUpdate-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"reloaded_collection", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"reloaded_collection_shard1_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:44865/solr", [junit4] 2> "type":"NRT"} [junit4] 2> 918256 INFO (OverseerStateUpdate-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"reloaded_collection", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"reloaded_collection_shard1_replica_n2", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:43179/solr", [junit4] 2> "type":"NRT"} [junit4] 2> 918258 INFO (OverseerStateUpdate-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"reloaded_collection", [junit4] 2> "shard":"shard2", [junit4] 2> "core":"reloaded_collection_shard2_replica_n4", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:38517/solr", [junit4] 2> "type":"NRT"} [junit4] 2> 918259 INFO (OverseerStateUpdate-98487268249042954-127.0.0.1:38517_solr-n_0000000000) [n:127.0.0.1:38517_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"reloaded_collection", [junit4] 2> "shard":"shard2", [junit4] 2> "core":"reloaded_collection_shard2_replica_n6", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:33271/solr", [junit4] 2> "type":"NRT"} [junit4] 2> 918462 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node3&collection.configName=conf&newCollection=true&name=reloaded_collection_shard1_replica_n1&action=CREATE&numShards=2&collection=reloaded_collection&shard=shard1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 918469 INFO (qtp20401794-10111) [n:127.0.0.1:33271_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node8&collection.configName=conf&newCollection=true&name=reloaded_collection_shard2_replica_n6&action=CREATE&numShards=2&collection=reloaded_collection&shard=shard2&wt=javabin&version=2&replicaType=NRT [junit4] 2> 918507 INFO (qtp10530946-10110) [n:127.0.0.1:43179_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node5&collection.configName=conf&newCollection=true&name=reloaded_collection_shard1_replica_n2&action=CREATE&numShards=2&collection=reloaded_collection&shard=shard1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 918507 INFO (qtp6657384-10106) [n:127.0.0.1:38517_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node7&collection.configName=conf&newCollection=true&name=reloaded_collection_shard2_replica_n4&action=CREATE&numShards=2&collection=reloaded_collection&shard=shard2&wt=javabin&version=2&replicaType=NRT [junit4] 2> 918507 INFO (qtp10530946-10110) [n:127.0.0.1:43179_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 918507 INFO (qtp6657384-10106) [n:127.0.0.1:38517_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 918614 INFO (zkCallback-1456-thread-1-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/reloaded_collection/state.json] for collection [reloaded_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 918614 INFO (zkCallback-1458-thread-2-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/reloaded_collection/state.json] for collection [reloaded_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 918614 INFO (zkCallback-1459-thread-1-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/reloaded_collection/state.json] for collection [reloaded_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 918614 INFO (zkCallback-1459-thread-2-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/reloaded_collection/state.json] for collection [reloaded_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 918614 INFO (zkCallback-1456-thread-2-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/reloaded_collection/state.json] for collection [reloaded_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 918614 INFO (zkCallback-1457-thread-2-processing-n:127.0.0.1:43179_solr) [n:127.0.0.1:43179_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/reloaded_collection/state.json] for collection [reloaded_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 918614 INFO (zkCallback-1458-thread-1-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/reloaded_collection/state.json] for collection [reloaded_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 918614 INFO (zkCallback-1457-thread-1-processing-n:127.0.0.1:43179_solr) [n:127.0.0.1:43179_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/reloaded_collection/state.json] for collection [reloaded_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 919481 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:reloaded_collection s:shard1 r:core_node3 x:reloaded_collection_shard1_replica_n1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.1.0 [junit4] 2> 919482 INFO (qtp20401794-10111) [n:127.0.0.1:33271_solr c:reloaded_collection s:shard2 r:core_node8 x:reloaded_collection_shard2_replica_n6] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.1.0 [junit4] 2> 919489 INFO (qtp33360035-10109) [n:127.0.0.1:44865_solr c:reloaded_collection s:shard1 r:core_node3 x:reloaded_collection_shard1_replica_n1] o.a.s.s.IndexSchema [reloaded_collection_shard1_replica_n1] Schema name=minimal [junit4] 2> 919492 INFO [...truncated too long message...] whollynewcollection_0 r:core_node7) [n:127.0.0.1:43179_solr c:awhollynewcollection_0 s:shard2 r:core_node7 x:awhollynewcollection_0_shard2_replica_n4] o.a.s.c.ZkContainer [junit4] 2> java.lang.NullPointerException [junit4] 2> at org.apache.solr.cloud.ZkController.publish(ZkController.java:1242) [junit4] 2> at org.apache.solr.cloud.ZkController.publish(ZkController.java:1234) [junit4] 2> at org.apache.solr.cloud.ZkController.publish(ZkController.java:1230) [junit4] 2> at org.apache.solr.core.ZkContainer.lambda$registerInZk$0(ZkContainer.java:188) [junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] 2> at java.lang.Thread.run(Thread.java:748) [junit4] 2> 1016176 ERROR (coreZkRegister-4277-thread-1-processing-n:127.0.0.1:43179_solr x:awhollynewcollection_0_shard2_replica_n4 s:shard2 c:awhollynewcollection_0 r:core_node7) [n:127.0.0.1:43179_solr c:awhollynewcollection_0 s:shard2 r:core_node7 x:awhollynewcollection_0_shard2_replica_n4] o.a.s.c.ZkContainer :org.apache.solr.common.SolrException: Error getting leader from zk for shard shard2 [junit4] 2> at org.apache.solr.cloud.ZkController.getLeader(ZkController.java:1099) [junit4] 2> at org.apache.solr.cloud.ZkController.register(ZkController.java:971) [junit4] 2> at org.apache.solr.cloud.ZkController.register(ZkController.java:906) [junit4] 2> at org.apache.solr.core.ZkContainer.lambda$registerInZk$0(ZkContainer.java:181) [junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] 2> at java.lang.Thread.run(Thread.java:748) [junit4] 2> Caused by: org.apache.solr.common.SolrException: No registered leader was found after waiting for 1220000ms , collection: awhollynewcollection_0 slice: shard2 [junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.getLeaderRetry(ZkStateReader.java:758) [junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.getLeaderUrl(ZkStateReader.java:725) [junit4] 2> at org.apache.solr.cloud.ZkController.getLeader(ZkController.java:1070) [junit4] 2> ... 7 more [junit4] 2> [junit4] 2> 1017634 WARN (zkCallback-1459-thread-3-processing-n:127.0.0.1:44865_solr) [n:127.0.0.1:44865_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 1017634 INFO (jetty-closer-1438-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@105fde9{/solr,null,UNAVAILABLE} [junit4] 2> 1017641 WARN (zkCallback-1458-thread-1-processing-n:127.0.0.1:33271_solr) [n:127.0.0.1:33271_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 1017641 INFO (jetty-closer-1438-thread-3) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@8642b4{/solr,null,UNAVAILABLE} [junit4] 2> 1017645 WARN (zkCallback-1456-thread-5-processing-n:127.0.0.1:38517_solr) [n:127.0.0.1:38517_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 1017645 WARN (zkCallback-1483-thread-1-processing-n:127.0.0.1:43179_solr) [n:127.0.0.1:43179_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 1017645 INFO (jetty-closer-1438-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@fce899{/solr,null,UNAVAILABLE} [junit4] 2> 1017645 INFO (jetty-closer-1438-thread-4) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@19d37e9{/solr,null,UNAVAILABLE} [junit4] 2> 1017646 ERROR (SUITE-CollectionsAPIDistributedZkTest-seed#[F18C8E7BB0DC9844]-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> 1017646 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[F18C8E7BB0DC9844]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:37627 37627 [junit4] 2> 1027061 INFO (Thread-3454) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:37627 37627 [junit4] 2> 1027063 WARN (Thread-3454) [ ] o.a.s.c.ZkTestServer Watch limit violations: [junit4] 2> Maximum concurrent create/delete watches above limit: [junit4] 2> [junit4] 2> 15 /solr/configs/conf [junit4] 2> 8 /solr/aliases.json [junit4] 2> [junit4] 2> Maximum concurrent data watches above limit: [junit4] 2> [junit4] 2> 52 /solr/collections/addReplicaColl/state.json [junit4] 2> 31 /solr/collections/nodes_used_collection/state.json [junit4] 2> 13 /solr/collections/onlyinzk/state.json [junit4] 2> 13 /solr/collections/halfdeletedcollection/state.json [junit4] 2> 8 /solr/clusterprops.json [junit4] 2> 8 /solr/clusterstate.json [junit4] 2> 5 /solr/collections/halfcollectionblocker2/state.json [junit4] 2> 4 /solr/collections/halfcollectionblocker/state.json [junit4] 2> 4 /solr/collections/awhollynewcollection_0/state.json [junit4] 2> 4 /solr/collections/halfcollection/state.json [junit4] 2> 2 /solr/overseer_elect/election/98487268249042954-127.0.0.1:38517_solr-n_0000000000 [junit4] 2> [junit4] 2> Maximum concurrent children watches above limit: [junit4] 2> [junit4] 2> 303 /solr/collections [junit4] 2> 8 /solr/live_nodes [junit4] 2> [junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_F18C8E7BB0DC9844-001 [junit4] 2> NOTE: test params are: codec=FastCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=FAST, chunkSize=9, maxDocsPerChunk=1, blockSize=817), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=FAST, chunkSize=9, blockSize=817)), sim=RandomSimilarity(queryNorm=false): {}, locale=en-US, timezone=Australia/Victoria [junit4] 2> NOTE: Linux 4.10.0-27-generic i386/Oracle Corporation 1.8.0_144 (32-bit)/cpus=8,threads=1,free=57269264,total=371458048 [junit4] 2> NOTE: All tests run in this JVM: [CustomCollectionTest, TestReRankQParserPlugin, DistributedQueryComponentCustomSortTest, TestSerializedLuceneMatchVersion, ExplicitHLLTest, DirectUpdateHandlerOptimizeTest, HdfsBasicDistributedZkTest, TestTestInjection, FastVectorHighlighterTest, SolrCoreCheckLockOnStartupTest, SolrJmxReporterCloudTest, TestInitParams, TestFastWriter, HdfsDirectoryFactoryTest, SecurityConfHandlerTest, HdfsCollectionsAPIDistributedZkTest, TestReversedWildcardFilterFactory, TestConfigReload, TestMiniSolrCloudClusterSSL, TestHttpShardHandlerFactory, CheckHdfsIndexTest, ParsingFieldUpdateProcessorsTest, TestSolr4Spatial2, TestStandardQParsers, TlogReplayBufferedWhileIndexingTest, SearchHandlerTest, TestFieldTypeCollectionResource, BadIndexSchemaTest, ShufflingReplicaListTransformerTest, TestSolrCoreProperties, PeerSyncWithIndexFingerprintCachingTest, OverseerModifyCollectionTest, TestLegacyNumericUtils, DocumentBuilderTest, TestDelegationWithHadoopAuth, UUIDUpdateProcessorFallbackTest, SimplePostToolTest, TestRawTransformer, TestExceedMaxTermLength, TestCodecSupport, QueryEqualityTest, CdcrReplicationDistributedZkTest, RecoveryZkTest, SimpleFacetsTest, TestManagedResource, TestComplexPhraseQParserPlugin, TestNumericTerms64, ConjunctionSolrSpellCheckerTest, AnalysisErrorHandlingTest, TestQueryWrapperFilter, TestTrie, TestStressReorder, ManagedSchemaRoundRobinCloudTest, AnalyticsQueryTest, TestCloudNestedDocsSort, TestTolerantSearch, TestReload, JavabinLoaderTest, BufferStoreTest, TestFieldCacheSort, XsltUpdateRequestHandlerTest, TestSQLHandlerNonCloud, TestSurroundQueryParser, CloneFieldUpdateProcessorFactoryTest, RestartWhileUpdatingTest, UniqFieldsUpdateProcessorFactoryTest, TemplateUpdateProcessorTest, TestPullReplica, HdfsThreadLeakTest, TestSlowCompositeReaderWrapper, URLClassifyProcessorTest, SmileWriterTest, TestManagedSchema, CoreAdminCreateDiscoverTest, SignatureUpdateProcessorFactoryTest, TestQuerySenderListener, TestNonDefinedSimilarityFactory, TestSort, ConfigSetsAPITest, SharedFSAutoReplicaFailoverUtilsTest, TestSystemCollAutoCreate, TestInPlaceUpdatesStandalone, PrimitiveFieldTypeTest, BasicAuthStandaloneTest, MultiTermTest, TestSolrXml, TestDistributedMissingSort, MoveReplicaTest, DocValuesNotIndexedTest, SolrMetricsIntegrationTest, TestPseudoReturnFields, DateFieldTest, ZkStateReaderTest, AutoCommitTest, CdcrVersionReplicationTest, TestLMJelinekMercerSimilarityFactory, TestZkAclsWithHadoopAuth, SolrCloudExampleTest, TestApiFramework, TestFoldingMultitermQuery, SuggestComponentTest, ReturnFieldsTest, ResponseLogComponentTest, TestObjectReleaseTracker, TestJavabinTupleStreamParser, TestDefaultStatsCache, SolrTestCaseJ4Test, TestLeaderInitiatedRecoveryThread, DateMathParserTest, RemoteQueryErrorTest, TestStressCloudBlindAtomicUpdates, TestJsonFacets, NotRequiredUniqueKeyTest, TestJettySolrRunner, TestCloudSearcherWarming, RequiredFieldsTest, RuleEngineTest, BasicDistributedZk2Test, UnloadDistributedZkTest, CollectionsAPIDistributedZkTest] [junit4] Completed [311/729 (1!)] on J2 in 118.55s, 19 tests, 1 failure <<< FAILURES! [...truncated 40716 lines...]
--------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org