Build: https://jenkins.thetaphi.de/job/Lucene-Solr-master-MacOSX/4215/ Java: 64bit/jdk-9 -XX:-UseCompressedOops -XX:+UseG1GC --illegal-access=deny
1 tests failed. FAILED: org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollectionsAPI Error Message: Error from server at http://127.0.0.1:64603/solr/awhollynewcollection_0_shard2_replica_n2: ClusterState says we are the leader (http://127.0.0.1:64603/solr/awhollynewcollection_0_shard2_replica_n2), but locally we don't think so. Request came from null Stack Trace: org.apache.solr.client.solrj.impl.CloudSolrClient$RouteException: Error from server at http://127.0.0.1:64603/solr/awhollynewcollection_0_shard2_replica_n2: ClusterState says we are the leader (http://127.0.0.1:64603/solr/awhollynewcollection_0_shard2_replica_n2), but locally we don't think so. Request came from null at __randomizedtesting.SeedInfo.seed([FDA1C878594403EB:B5D4BCCC5F772C7E]:0) at org.apache.solr.client.solrj.impl.CloudSolrClient.directUpdate(CloudSolrClient.java:539) at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(CloudSolrClient.java:993) at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:862) at org.apache.solr.client.solrj.impl.CloudSolrClient.request(CloudSolrClient.java:793) at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:178) at org.apache.solr.client.solrj.request.UpdateRequest.commit(UpdateRequest.java:233) at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollectionsAPI(CollectionsAPIDistributedZkTest.java:459) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:564) at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1737) at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:934) at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:970) at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:984) at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57) at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49) at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45) at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48) at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64) at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368) at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817) at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468) at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:943) at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829) at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879) at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57) at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41) at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at 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.base/java.lang.Thread.run(Thread.java:844) Caused by: org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at http://127.0.0.1:64603/solr/awhollynewcollection_0_shard2_replica_n2: ClusterState says we are the leader (http://127.0.0.1:64603/solr/awhollynewcollection_0_shard2_replica_n2), but locally we don't think so. Request came from null at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:626) at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:253) at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:242) at org.apache.solr.client.solrj.impl.LBHttpSolrClient.doRequest(LBHttpSolrClient.java:483) at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:413) at org.apache.solr.client.solrj.impl.CloudSolrClient.lambda$directUpdate$0(CloudSolrClient.java:516) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) ... 1 more Build Log: [...truncated 11919 lines...] [junit4] Suite: org.apache.solr.cloud.CollectionsAPIDistributedZkTest [junit4] 2> 1273829 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[FDA1C878594403EB]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom [junit4] 2> Creating dataDir: /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001/init-core-data-001 [junit4] 2> 1273829 WARN (SUITE-CollectionsAPIDistributedZkTest-seed#[FDA1C878594403EB]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=94 numCloses=94 [junit4] 2> 1273829 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[FDA1C878594403EB]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=true [junit4] 2> 1273830 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[FDA1C878594403EB]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason="", value=0.0/0.0, ssl=0.0/0.0, clientAuth=0.0/0.0) w/ MAC_OS_X supressed clientAuth [junit4] 2> 1273832 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[FDA1C878594403EB]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 4 servers in /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001/tempDir-001 [junit4] 2> 1273832 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[FDA1C878594403EB]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER [junit4] 2> 1273832 INFO (Thread-2343) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0 [junit4] 2> 1273832 INFO (Thread-2343) [ ] o.a.s.c.ZkTestServer Starting server [junit4] 2> 1273837 ERROR (Thread-2343) [ ] 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> 1273942 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[FDA1C878594403EB]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:64599 [junit4] 2> 1273958 INFO (jetty-launcher-1757-thread-1) [ ] o.e.j.s.Server jetty-9.3.20.v20170531 [junit4] 2> 1273958 INFO (jetty-launcher-1757-thread-3) [ ] o.e.j.s.Server jetty-9.3.20.v20170531 [junit4] 2> 1273958 INFO (jetty-launcher-1757-thread-2) [ ] o.e.j.s.Server jetty-9.3.20.v20170531 [junit4] 2> 1273959 INFO (jetty-launcher-1757-thread-4) [ ] o.e.j.s.Server jetty-9.3.20.v20170531 [junit4] 2> 1273960 INFO (jetty-launcher-1757-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@43743530{/solr,null,AVAILABLE} [junit4] 2> 1273962 INFO (jetty-launcher-1757-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@7126cda6{HTTP/1.1,[http/1.1]}{127.0.0.1:64601} [junit4] 2> 1273962 INFO (jetty-launcher-1757-thread-1) [ ] o.e.j.s.Server Started @1275632ms [junit4] 2> 1273962 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=64601} [junit4] 2> 1273962 ERROR (jetty-launcher-1757-thread-1) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 1273962 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 8.0.0 [junit4] 2> 1273962 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 1273962 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null, Default config dir: null [junit4] 2> 1273962 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-10-09T16:46:36.838927Z [junit4] 2> 1273963 INFO (jetty-launcher-1757-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@5e009b41{/solr,null,AVAILABLE} [junit4] 2> 1273963 INFO (jetty-launcher-1757-thread-3) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@58ae7e5f{/solr,null,AVAILABLE} [junit4] 2> 1273964 INFO (jetty-launcher-1757-thread-3) [ ] o.e.j.s.AbstractConnector Started ServerConnector@b8e09e3{HTTP/1.1,[http/1.1]}{127.0.0.1:64603} [junit4] 2> 1273964 INFO (jetty-launcher-1757-thread-3) [ ] o.e.j.s.Server Started @1275634ms [junit4] 2> 1273964 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=64603} [junit4] 2> 1273964 ERROR (jetty-launcher-1757-thread-3) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 1273964 INFO (jetty-launcher-1757-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@1feefab{HTTP/1.1,[http/1.1]}{127.0.0.1:64602} [junit4] 2> 1273964 INFO (jetty-launcher-1757-thread-4) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@1c44bb30{/solr,null,AVAILABLE} [junit4] 2> 1273964 INFO (jetty-launcher-1757-thread-2) [ ] o.e.j.s.Server Started @1275634ms [junit4] 2> 1273964 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=64602} [junit4] 2> 1273964 ERROR (jetty-launcher-1757-thread-2) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 1273964 INFO (jetty-launcher-1757-thread-4) [ ] o.e.j.s.AbstractConnector Started ServerConnector@20bed557{HTTP/1.1,[http/1.1]}{127.0.0.1:64605} [junit4] 2> 1273964 INFO (jetty-launcher-1757-thread-4) [ ] o.e.j.s.Server Started @1275634ms [junit4] 2> 1273964 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 8.0.0 [junit4] 2> 1273964 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=64605} [junit4] 2> 1273964 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 1273964 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null, Default config dir: null [junit4] 2> 1273964 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-10-09T16:46:36.840863Z [junit4] 2> 1273964 ERROR (jetty-launcher-1757-thread-4) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 1273965 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 8.0.0 [junit4] 2> 1273965 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 1273965 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null, Default config dir: null [junit4] 2> 1273965 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-10-09T16:46:36.841237Z [junit4] 2> 1273965 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 8.0.0 [junit4] 2> 1273965 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 1273965 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null, Default config dir: null [junit4] 2> 1273965 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-10-09T16:46:36.841463Z [junit4] 2> 1273966 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 1273968 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 1273968 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 1273968 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 1273969 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored [junit4] 2> 1273969 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored [junit4] 2> 1273977 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored [junit4] 2> 1273977 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored [junit4] 2> 1273977 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored [junit4] 2> 1273977 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored [junit4] 2> 1273979 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored [junit4] 2> 1273979 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored [junit4] 2> 1273981 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:64599/solr [junit4] 2> 1273982 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:64599/solr [junit4] 2> 1273982 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:64599/solr [junit4] 2> 1273983 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:64599/solr [junit4] 2> 1274145 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 1274145 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 1274145 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 1274146 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:64603_solr [junit4] 2> 1274146 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 1274147 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64601_solr [junit4] 2> 1274147 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64605_solr [junit4] 2> 1274148 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.c.Overseer Overseer (id=98799950018052105-127.0.0.1:64603_solr-n_0000000000) starting [junit4] 2> 1274149 INFO (zkCallback-1776-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 1274149 INFO (zkCallback-1779-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 1274149 INFO (zkCallback-1777-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 1274150 INFO (zkCallback-1778-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2) [junit4] 2> 1274151 INFO (zkCallback-1779-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 1274152 INFO (zkCallback-1777-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 1274152 INFO (zkCallback-1776-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 1274153 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64602_solr [junit4] 2> 1274170 INFO (zkCallback-1776-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 1274170 INFO (zkCallback-1777-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 1274170 INFO (zkCallback-1779-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 1274170 INFO (zkCallback-1778-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 1274184 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1274184 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1274190 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64603_solr [junit4] 2> 1274192 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1274192 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1274193 INFO (jetty-launcher-1757-thread-1) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001/tempDir-001/node1 [junit4] 2> 1274194 INFO (zkCallback-1778-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 1274194 INFO (zkCallback-1777-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 1274194 INFO (zkCallback-1779-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 1274194 INFO (zkCallback-1776-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 1274195 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1274195 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1274196 INFO (jetty-launcher-1757-thread-4) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001/tempDir-001/node4 [junit4] 2> 1274210 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1274218 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1274218 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1274219 INFO (jetty-launcher-1757-thread-2) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001/tempDir-001/node2 [junit4] 2> 1274229 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1274244 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1274244 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1274245 INFO (jetty-launcher-1757-thread-3) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001/tempDir-001/node3 [junit4] 2> 1274293 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[FDA1C878594403EB]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 1274295 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[FDA1C878594403EB]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:64599/solr ready [junit4] 2> 1274323 INFO (TEST-CollectionsAPIDistributedZkTest.testCreateShouldFailOnExistingCore-seed#[FDA1C878594403EB]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreateShouldFailOnExistingCore [junit4] 2> 1274325 INFO (TEST-CollectionsAPIDistributedZkTest.testCreateShouldFailOnExistingCore-seed#[FDA1C878594403EB]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 1274331 INFO (qtp781741865-11469) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf&name=halfcollectionblocker&nrtReplicas=1&action=CREATE&numShards=1&createNodeSet=&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 1274333 INFO (OverseerThreadFactory-5315-thread-1) [ ] o.a.s.c.CreateCollectionCmd Create collection halfcollectionblocker [junit4] 2> 1274334 WARN (OverseerThreadFactory-5315-thread-1) [ ] o.a.s.c.CreateCollectionCmd It is unusual to create a collection (halfcollectionblocker) without cores. [junit4] 2> 1274454 INFO (qtp781741865-11469) [ ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas [junit4] 2> 1274455 INFO (qtp781741865-11469) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf&name=halfcollectionblocker&nrtReplicas=1&action=CREATE&numShards=1&createNodeSet=&wt=javabin&version=2} status=0 QTime=124 [junit4] 2> 1274456 INFO (qtp781741865-11471) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :addreplica with params node=127.0.0.1:64605_solr&name=halfcollection_shard1_replica_n1&action=ADDREPLICA&collection=halfcollectionblocker&shard=shard1&type=NRT&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 1274458 INFO (OverseerCollectionConfigSetProcessor-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] 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> 1274459 INFO (OverseerThreadFactory-5315-thread-2) [ ] o.a.s.c.AddReplicaCmd Node Identified 127.0.0.1:64605_solr for creating new replica [junit4] 2> 1274462 INFO (OverseerStateUpdate-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"addreplica", [junit4] 2> "collection":"halfcollectionblocker", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"halfcollection_shard1_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:64605/solr";, [junit4] 2> "node_name":"127.0.0.1:64605_solr", [junit4] 2> "type":"NRT"} [junit4] 2> 1274685 INFO (qtp2108073622-11488) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node21&collection.configName=conf&name=halfcollection_shard1_replica_n1&action=CREATE&collection=halfcollectionblocker&shard=shard1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 1274685 INFO (qtp2108073622-11488) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 1274711 INFO (qtp2108073622-11488) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.0 [junit4] 2> 1274720 INFO (qtp2108073622-11488) [ ] o.a.s.s.IndexSchema [halfcollection_shard1_replica_n1] Schema name=minimal [junit4] 2> 1274724 INFO (qtp2108073622-11488) [ ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 1274724 INFO (qtp2108073622-11488) [ ] o.a.s.c.CoreContainer Creating SolrCore 'halfcollection_shard1_replica_n1' using configuration from collection halfcollectionblocker, trusted=true [junit4] 2> 1274725 INFO (qtp2108073622-11488) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.halfcollectionblocker.shard1.core_node21' (registry 'solr.core.halfcollectionblocker.shard1.core_node21') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1274725 INFO (qtp2108073622-11488) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 1274725 INFO (qtp2108073622-11488) [ ] o.a.s.c.SolrCore [[halfcollection_shard1_replica_n1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001/tempDir-001/node4/halfcollection_shard1_replica_n1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001/tempDir-001/node4/halfcollection_shard1_replica_n1/data/] [junit4] 2> 1274785 INFO (qtp2108073622-11488) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 1274785 INFO (qtp2108073622-11488) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 1274794 INFO (qtp2108073622-11488) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 1274795 INFO (qtp2108073622-11488) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 1274796 INFO (qtp2108073622-11488) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@7af9e559[halfcollection_shard1_replica_n1] main] [junit4] 2> 1274797 INFO (qtp2108073622-11488) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 1274798 INFO (qtp2108073622-11488) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 1274798 INFO (qtp2108073622-11488) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 1274798 INFO (qtp2108073622-11488) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1580799201298612224 [junit4] 2> 1274799 INFO (searcherExecutor-5321-thread-1) [ ] o.a.s.c.SolrCore [halfcollection_shard1_replica_n1] Registered new searcher Searcher@7af9e559[halfcollection_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 1274805 INFO (zkCallback-1779-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfcollectionblocker/state.json] for collection [halfcollectionblocker] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1274806 INFO (zkCallback-1779-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfcollectionblocker/state.json] for collection [halfcollectionblocker] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1274808 INFO (qtp2108073622-11488) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 1274808 INFO (qtp2108073622-11488) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 1274808 INFO (qtp2108073622-11488) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:64605/solr/halfcollection_shard1_replica_n1/ [junit4] 2> 1274808 INFO (qtp2108073622-11488) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 1274808 INFO (qtp2108073622-11488) [ ] o.a.s.c.SyncStrategy http://127.0.0.1:64605/solr/halfcollection_shard1_replica_n1/ has no replicas [junit4] 2> 1274808 INFO (qtp2108073622-11488) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 1274813 INFO (qtp2108073622-11488) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:64605/solr/halfcollection_shard1_replica_n1/ shard1 [junit4] 2> 1274918 INFO (zkCallback-1779-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfcollectionblocker/state.json] for collection [halfcollectionblocker] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1274918 INFO (zkCallback-1779-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfcollectionblocker/state.json] for collection [halfcollectionblocker] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1274949 INFO (qtp2108073622-11488) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 1274951 INFO (qtp2108073622-11488) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node21&collection.configName=conf&name=halfcollection_shard1_replica_n1&action=CREATE&collection=halfcollectionblocker&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=270 [junit4] 2> 1274954 INFO (qtp781741865-11471) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={node=127.0.0.1:64605_solr&name=halfcollection_shard1_replica_n1&action=ADDREPLICA&collection=halfcollectionblocker&shard=shard1&type=NRT&wt=javabin&version=2} status=0 QTime=498 [junit4] 2> 1274955 INFO (qtp781741865-11472) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf&name=halfcollectionblocker2&nrtReplicas=1&action=CREATE&numShards=1&createNodeSet=&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 1274958 INFO (OverseerThreadFactory-5315-thread-3) [ ] o.a.s.c.CreateCollectionCmd Create collection halfcollectionblocker2 [junit4] 2> 1274958 INFO (OverseerCollectionConfigSetProcessor-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] 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> 1274958 WARN (OverseerThreadFactory-5315-thread-3) [ ] o.a.s.c.CreateCollectionCmd It is unusual to create a collection (halfcollectionblocker2) without cores. [junit4] 2> 1275069 INFO (zkCallback-1779-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfcollectionblocker/state.json] for collection [halfcollectionblocker] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1275069 INFO (zkCallback-1779-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfcollectionblocker/state.json] for collection [halfcollectionblocker] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1275172 INFO (qtp781741865-11472) [ ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas [junit4] 2> 1275173 INFO (qtp781741865-11472) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf&name=halfcollectionblocker2&nrtReplicas=1&action=CREATE&numShards=1&createNodeSet=&wt=javabin&version=2} status=0 QTime=217 [junit4] 2> 1275173 INFO (qtp781741865-11473) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :addreplica with params node=127.0.0.1:64601_solr&name=halfcollection_shard1_replica_n1&action=ADDREPLICA&collection=halfcollectionblocker2&shard=shard1&type=NRT&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 1275177 INFO (OverseerCollectionConfigSetProcessor-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] 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> 1275177 INFO (OverseerThreadFactory-5315-thread-4) [ ] o.a.s.c.AddReplicaCmd Node Identified 127.0.0.1:64601_solr for creating new replica [junit4] 2> 1275180 INFO (OverseerStateUpdate-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"addreplica", [junit4] 2> "collection":"halfcollectionblocker2", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"halfcollection_shard1_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:64601/solr";, [junit4] 2> "node_name":"127.0.0.1:64601_solr", [junit4] 2> "type":"NRT"} [junit4] 2> 1275399 INFO (qtp781741865-11476) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node21&collection.configName=conf&name=halfcollection_shard1_replica_n1&action=CREATE&collection=halfcollectionblocker2&shard=shard1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 1275399 INFO (qtp781741865-11476) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 1275409 INFO (qtp781741865-11476) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.0 [junit4] 2> 1275414 INFO (qtp781741865-11476) [ ] o.a.s.s.IndexSchema [halfcollection_shard1_replica_n1] Schema name=minimal [junit4] 2> 1275416 INFO (qtp781741865-11476) [ ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 1275416 INFO (qtp781741865-11476) [ ] o.a.s.c.CoreContainer Creating SolrCore 'halfcollection_shard1_replica_n1' using configuration from collection halfcollectionblocker2, trusted=true [junit4] 2> 1275416 INFO (qtp781741865-11476) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.halfcollectionblocker2.shard1.core_node21' (registry 'solr.core.halfcollectionblocker2.shard1.core_node21') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1275416 INFO (qtp781741865-11476) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 1275416 INFO (qtp781741865-11476) [ ] o.a.s.c.SolrCore [[halfcollection_shard1_replica_n1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001/tempDir-001/node1/halfcollection_shard1_replica_n1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001/tempDir-001/node1/halfcollection_shard1_replica_n1/data/] [junit4] 2> 1275467 INFO (qtp781741865-11476) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 1275467 INFO (qtp781741865-11476) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 1275469 INFO (qtp781741865-11476) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 1275469 INFO (qtp781741865-11476) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 1275471 INFO (qtp781741865-11476) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@7f4432cb[halfcollection_shard1_replica_n1] main] [junit4] 2> 1275473 INFO (qtp781741865-11476) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 1275473 INFO (qtp781741865-11476) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 1275474 INFO (qtp781741865-11476) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 1275474 INFO (qtp781741865-11476) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1580799202007449600 [junit4] 2> 1275475 INFO (searcherExecutor-5326-thread-1) [ ] o.a.s.c.SolrCore [halfcollection_shard1_replica_n1] Registered new searcher Searcher@7f4432cb[halfcollection_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 1275481 INFO (qtp781741865-11476) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 1275481 INFO (qtp781741865-11476) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 1275481 INFO (qtp781741865-11476) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:64601/solr/halfcollection_shard1_replica_n1/ [junit4] 2> 1275481 INFO (qtp781741865-11476) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 1275481 INFO (qtp781741865-11476) [ ] o.a.s.c.SyncStrategy http://127.0.0.1:64601/solr/halfcollection_shard1_replica_n1/ has no replicas [junit4] 2> 1275481 INFO (qtp781741865-11476) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 1275487 INFO (qtp781741865-11476) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:64601/solr/halfcollection_shard1_replica_n1/ shard1 [junit4] 2> 1275602 INFO (zkCallback-1777-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfcollectionblocker2/state.json] for collection [halfcollectionblocker2] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1275603 INFO (zkCallback-1777-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfcollectionblocker2/state.json] for collection [halfcollectionblocker2] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1275661 INFO (qtp781741865-11476) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 1275663 INFO (qtp781741865-11476) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node21&collection.configName=conf&name=halfcollection_shard1_replica_n1&action=CREATE&collection=halfcollectionblocker2&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=264 [junit4] 2> 1275667 INFO (qtp781741865-11473) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={node=127.0.0.1:64601_solr&name=halfcollection_shard1_replica_n1&action=ADDREPLICA&collection=halfcollectionblocker2&shard=shard1&type=NRT&wt=javabin&version=2} status=0 QTime=493 [junit4] 2> 1275668 INFO (qtp781741865-11467) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf&name=halfcollection&nrtReplicas=1&action=CREATE&numShards=2&createNodeSet=127.0.0.1:64605_solr,127.0.0.1:64601_solr&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 1275671 INFO (OverseerThreadFactory-5315-thread-5) [ ] o.a.s.c.CreateCollectionCmd Create collection halfcollection [junit4] 2> 1275672 INFO (OverseerCollectionConfigSetProcessor-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] 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> 1275796 INFO (zkCallback-1777-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfcollectionblocker2/state.json] for collection [halfcollectionblocker2] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1275796 INFO (zkCallback-1777-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfcollectionblocker2/state.json] for collection [halfcollectionblocker2] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1275903 INFO (OverseerStateUpdate-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"halfcollection", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"halfcollection_shard1_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:64605/solr";, [junit4] 2> "type":"NRT"} [junit4] 2> 1275909 INFO (OverseerStateUpdate-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"halfcollection", [junit4] 2> "shard":"shard2", [junit4] 2> "core":"halfcollection_shard2_replica_n2", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:64601/solr";, [junit4] 2> "type":"NRT"} [junit4] 2> 1276130 INFO (qtp781741865-11469) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node4&collection.configName=conf&newCollection=true&name=halfcollection_shard2_replica_n2&action=CREATE&numShards=2&collection=halfcollection&shard=shard2&wt=javabin&version=2&replicaType=NRT [junit4] 2> 1276131 INFO (qtp2108073622-11489) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node3&collection.configName=conf&newCollection=true&name=halfcollection_shard1_replica_n1&action=CREATE&numShards=2&collection=halfcollection&shard=shard1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 1276131 WARN (qtp2108073622-11489) [ ] o.a.s.c.CoreContainer Creating a core with existing name is not allowed [junit4] 2> 1276132 ERROR (qtp2108073622-11489) [ ] o.a.s.h.RequestHandlerBase org.apache.solr.common.SolrException: Core with name 'halfcollection_shard1_replica_n1' already exists. [junit4] 2> at org.apache.solr.core.CoreContainer.create(CoreContainer.java:925) [junit4] 2> at org.apache.solr.handler.admin.CoreAdminOperation.lambda$static$0(CoreAdminOperation.java:91) [junit4] 2> at org.apache.solr.handler.admin.CoreAdminOperation.execute(CoreAdminOperation.java:384) [junit4] 2> at org.apache.solr.handler.admin.CoreAdminHandler$CallInfo.call(CoreAdminHandler.java:389) [junit4] 2> at org.apache.solr.handler.admin.CoreAdminHandler.handleRequestBody(CoreAdminHandler.java:174) [junit4] 2> at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:177) [junit4] 2> at org.apache.solr.servlet.HttpSolrCall.handleAdmin(HttpSolrCall.java:745) [junit4] 2> at org.apache.solr.servlet.HttpSolrCall.handleAdminRequest(HttpSolrCall.java:726) [junit4] 2> at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:507) [junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:382) [junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:326) [junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759) [junit4] 2> at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:139) [junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759) [junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:582) [junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:224) [junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) [junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) [junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) [junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [junit4] 2> at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:426) [junit4] 2> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) [junit4] 2> at org.eclipse.jetty.server.Server.handle(Server.java:534) [junit4] 2> at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320) [junit4] 2> at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [junit4] 2> at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283) [junit4] 2> at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108) [junit4] 2> at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844) [junit4] 2> [junit4] 2> 1276132 INFO (qtp2108073622-11489) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node3&collection.configName=conf&newCollection=true&name=halfcollection_shard1_replica_n1&action=CREATE&numShards=2&collection=halfcollection&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=500 QTime=1 [junit4] 2> 1276132 ERROR (qtp2108073622-11489) [ ] o.a.s.s.HttpSolrCall null:org.apache.solr.common.SolrException: Core with name 'halfcollection_shard1_replica_n1' already exists. [junit4] 2> at org.apache.solr.core.CoreContainer.create(CoreContainer.java:925) [junit4] 2> at org.apache.solr.handler.admin.CoreAdminOperation.lambda$static$0(CoreAdminOperation.java:91) [junit4] 2> at org.apache.solr.handler.admin.CoreAdminOperation.execute(CoreAdminOperation.java:384) [junit4] 2> at org.apache.solr.handler.admin.CoreAdminHandler$CallInfo.call(CoreAdminHandler.java:389) [junit4] 2> at org.apache.solr.handler.admin.CoreAdminHandler.handleRequestBody(CoreAdminHandler.java:174) [junit4] 2> at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:177) [junit4] 2> at org.apache.solr.servlet.HttpSolrCall.handleAdmin(HttpSolrCall.java:745) [junit4] 2> at org.apache.solr.servlet.HttpSolrCall.handleAdminRequest(HttpSolrCall.java:726) [junit4] 2> at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:507) [junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:382) [junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:326) [junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759) [junit4] 2> at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:139) [junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759) [junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:582) [junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:224) [junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) [junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) [junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) [junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [junit4] 2> at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:426) [junit4] 2> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) [junit4] 2> at org.eclipse.jetty.server.Server.handle(Server.java:534) [junit4] 2> at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320) [junit4] 2> at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [junit4] 2> at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283) [junit4] 2> at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108) [junit4] 2> at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844) [junit4] 2> [junit4] 2> 1276133 ERROR (OverseerThreadFactory-5315-thread-5) [ ] o.a.s.c.OverseerCollectionMessageHandler Error from shard: http://127.0.0.1:64605/solr [junit4] 2> org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at http://127.0.0.1:64605/solr: Core with name 'halfcollection_shard1_replica_n1' already exists. [junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:626) [junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:253) [junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:242) [junit4] 2> at org.apache.solr.client.solrj.SolrClient.request(SolrClient.java:1219) [junit4] 2> at org.apache.solr.handler.component.HttpShardHandler.lambda$submit$0(HttpShardHandler.java:172) [junit4] 2> at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) [junit4] 2> at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514) [junit4] 2> at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) [junit4] 2> at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176) [junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188) [junit4] 2> at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) [junit4] 2> at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) [junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844) [junit4] 2> 1276240 INFO (zkCallback-1777-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfcollection/state.json] for collection [halfcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1276240 INFO (zkCallback-1777-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfcollection/state.json] for collection [halfcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1277157 INFO (qtp781741865-11469) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.0 [junit4] 2> 1277163 INFO (qtp781741865-11469) [ ] o.a.s.s.IndexSchema [halfcollection_shard2_replica_n2] Schema name=minimal [junit4] 2> 1277165 INFO (qtp781741865-11469) [ ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 1277165 INFO (qtp781741865-11469) [ ] o.a.s.c.CoreContainer Creating SolrCore 'halfcollection_shard2_replica_n2' using configuration from collection halfcollection, trusted=true [junit4] 2> 1277165 INFO (qtp781741865-11469) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.halfcollection.shard2.replica_n2' (registry 'solr.core.halfcollection.shard2.replica_n2') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1277165 INFO (qtp781741865-11469) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 1277165 INFO (qtp781741865-11469) [ ] o.a.s.c.SolrCore [[halfcollection_shard2_replica_n2] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001/tempDir-001/node1/halfcollection_shard2_replica_n2], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001/tempDir-001/node1/halfcollection_shard2_replica_n2/data/] [junit4] 2> 1277215 INFO (qtp781741865-11469) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 1277216 INFO (qtp781741865-11469) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 1277217 INFO (qtp781741865-11469) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 1277217 INFO (qtp781741865-11469) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 1277218 INFO (qtp781741865-11469) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@7af40367[halfcollection_shard2_replica_n2] main] [junit4] 2> 1277220 INFO (qtp781741865-11469) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 1277220 INFO (qtp781741865-11469) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 1277221 INFO (qtp781741865-11469) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 1277221 INFO (qtp781741865-11469) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1580799203839311872 [junit4] 2> 1277222 INFO (searcherExecutor-5331-thread-1) [ ] o.a.s.c.SolrCore [halfcollection_shard2_replica_n2] Registered new searcher Searcher@7af40367[halfcollection_shard2_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 1277226 INFO (qtp781741865-11469) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 1277227 INFO (qtp781741865-11469) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 1277227 INFO (qtp781741865-11469) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:64601/solr/halfcollection_shard2_replica_n2/ [junit4] 2> 1277227 INFO (qtp781741865-11469) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 1277227 INFO (qtp781741865-11469) [ ] o.a.s.c.SyncStrategy http://127.0.0.1:64601/solr/halfcollection_shard2_replica_n2/ has no replicas [junit4] 2> 1277227 INFO (qtp781741865-11469) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 1277231 INFO (qtp781741865-11469) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:64601/solr/halfcollection_shard2_replica_n2/ shard2 [junit4] 2> 1277343 INFO (zkCallback-1777-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfcollection/state.json] for collection [halfcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1277343 INFO (zkCallback-1777-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfcollection/state.json] for collection [halfcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1277402 INFO (qtp781741865-11469) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 1277404 INFO (qtp781741865-11469) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node4&collection.configName=conf&newCollection=true&name=halfcollection_shard2_replica_n2&action=CREATE&numShards=2&collection=halfcollection&shard=shard2&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1273 [junit4] 2> 1277404 ERROR (OverseerThreadFactory-5315-thread-5) [ ] o.a.s.c.OverseerCollectionMessageHandler Cleaning up collection [halfcollection]. [junit4] 2> 1277409 INFO (OverseerThreadFactory-5315-thread-5) [ ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true [junit4] 2> 1277410 INFO (qtp781741865-11471) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.halfcollection.shard2.replica_n2, tag=null [junit4] 2> 1277410 INFO (qtp781741865-11471) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@1aee214: rootName = null, domain = solr.core.halfcollection.shard2.replica_n2, service url = null, agent id = null] for registry solr.core.halfcollection.shard2.replica_n2 / com.codahale.metrics.MetricRegistry@ec882eb [junit4] 2> 1277420 INFO (qtp781741865-11471) [ ] o.a.s.c.SolrCore [halfcollection_shard2_replica_n2] CLOSING SolrCore org.apache.solr.core.SolrCore@20676ca3 [junit4] 2> 1277420 INFO (qtp781741865-11471) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.halfcollection.shard2.replica_n2, tag=543648931 [junit4] 2> 1277420 INFO (qtp781741865-11471) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.halfcollection.shard2.leader, tag=543648931 [junit4] 2> 1277425 INFO (qtp781741865-11471) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=halfcollection_shard2_replica_n2&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=15 [junit4] 2> 1278161 INFO (OverseerThreadFactory-5315-thread-5) [ ] o.a.s.c.CreateCollectionCmd Cleaned up artifacts for failed create collection for [halfcollection] [junit4] 2> 1278164 INFO (qtp781741865-11467) [ ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas [junit4] 2> 1279695 INFO (OverseerCollectionConfigSetProcessor-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] 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> 1308392 ERROR (qtp781741865-11467) [ ] o.a.s.h.a.CollectionsHandler Timed out waiting for new collection's replicas to become ACTIVE with timeout=30 [junit4] 2> 1308393 INFO (qtp781741865-11467) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf&name=halfcollection&nrtReplicas=1&action=CREATE&numShards=2&createNodeSet=127.0.0.1:64605_solr,127.0.0.1:64601_solr&wt=javabin&version=2} status=0 QTime=32724 [junit4] 2> 1308393 INFO (TEST-CollectionsAPIDistributedZkTest.testCreateShouldFailOnExistingCore-seed#[FDA1C878594403EB]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testCreateShouldFailOnExistingCore [junit4] 2> 1308415 INFO (TEST-CollectionsAPIDistributedZkTest.testTooManyReplicas-seed#[FDA1C878594403EB]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testTooManyReplicas [junit4] 2> 1308417 INFO (TEST-CollectionsAPIDistributedZkTest.testTooManyReplicas-seed#[FDA1C878594403EB]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 1308419 INFO (qtp781741865-11472) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=halfcollectionblocker2&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 1308422 INFO (OverseerThreadFactory-5315-thread-5) [ ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true [junit4] 2> 1308426 INFO (qtp781741865-11474) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.halfcollectionblocker2.shard1.core_node21, tag=null [junit4] 2> 1308426 INFO (qtp781741865-11474) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@11a870dd: rootName = null, domain = solr.core.halfcollectionblocker2.shard1.core_node21, service url = null, agent id = null] for registry solr.core.halfcollectionblocker2.shard1.core_node21 / com.codahale.metrics.MetricRegistry@78fdfc28 [junit4] 2> 1308440 INFO (qtp781741865-11474) [ ] o.a.s.c.SolrCore [halfcollection_shard1_replica_n1] CLOSING SolrCore org.apache.solr.core.SolrCore@3c392338 [junit4] 2> 1308440 INFO (qtp781741865-11474) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.halfcollectionblocker2.shard1.core_node21, tag=1010377528 [junit4] 2> 1308440 INFO (qtp781741865-11474) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.halfcollectionblocker2.shard1.leader, tag=1010377528 [junit4] 2> 1308445 INFO (qtp781741865-11474) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=halfcollection_shard1_replica_n1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=19 [junit4] 2> 1309182 INFO (qtp781741865-11472) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=halfcollectionblocker2&action=DELETE&wt=javabin&version=2} status=0 QTime=763 [junit4] 2> 1309183 INFO (qtp781741865-11476) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=halfcollectionblocker&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 1309189 INFO (OverseerCollectionConfigSetProcessor-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] 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> 1309191 INFO (OverseerThreadFactory-5315-thread-5) [ ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true [junit4] 2> 1309195 INFO (qtp2108073622-11500) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.halfcollectionblocker.shard1.core_node21, tag=null [junit4] 2> 1309195 INFO (qtp2108073622-11500) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@7a369342: rootName = null, domain = solr.core.halfcollectionblocker.shard1.core_node21, service url = null, agent id = null] for registry solr.core.halfcollectionblocker.shard1.core_node21 / com.codahale.metrics.MetricRegistry@d7a4bac [junit4] 2> 1309216 INFO (qtp2108073622-11500) [ ] o.a.s.c.SolrCore [halfcollection_shard1_replica_n1] CLOSING SolrCore org.apache.solr.core.SolrCore@2aa2dc33 [junit4] 2> 1309216 INFO (qtp2108073622-11500) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.halfcollectionblocker.shard1.core_node21, tag=715316275 [junit4] 2> 1309216 INFO (qtp2108073622-11500) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.halfcollectionblocker.shard1.leader, tag=715316275 [junit4] 2> 1309221 INFO (qtp2108073622-11500) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=halfcollection_shard1_replica_n1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=26 [junit4] 2> 1309959 INFO (qtp781741865-11476) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=halfcollectionblocker&action=DELETE&wt=javabin&version=2} status=0 QTime=775 [junit4] 2> 1309961 INFO (qtp781741865-11473) [ ] 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> 1309965 INFO (OverseerThreadFactory-5315-thread-5) [ ] o.a.s.c.CreateCollectionCmd Create collection collection [junit4] 2> 1309967 INFO (OverseerCollectionConfigSetProcessor-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] 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> 1309967 WARN (OverseerThreadFactory-5315-thread-5) [ ] 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> 1309968 ERROR (OverseerThreadFactory-5315-thread-5) [ ] 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:173) [junit4] 2> at org.apache.solr.cloud.OverseerCollectionMessageHandler.processMessage(OverseerCollectionMessageHandler.java:229) [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.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) [junit4] 2> at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) [junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844) [junit4] 2> [junit4] 2> 1309973 INFO (qtp781741865-11473) [ ] 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=12 [junit4] 2> 1309974 INFO (TEST-CollectionsAPIDistributedZkTest.testTooManyReplicas-seed#[FDA1C878594403EB]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testTooManyReplicas [junit4] 2> 1310008 INFO (TEST-CollectionsAPIDistributedZkTest.testMissingNumShards-seed#[FDA1C878594403EB]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testMissingNumShards [junit4] 2> 1310010 INFO (TEST-CollectionsAPIDistributedZkTest.testMissingNumShards-seed#[FDA1C878594403EB]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 1310012 INFO (qtp781741865-11469) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=10&collection.configName=conf&name=acollection&action=CREATE&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 1310015 INFO (OverseerThreadFactory-5315-thread-5) [ ] o.a.s.c.CreateCollectionCmd Create collection acollection [junit4] 2> 1310015 INFO (OverseerCollectionConfigSetProcessor-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] 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> 1310016 ERROR (OverseerThreadFactory-5315-thread-5) [ ] o.a.s.c.OverseerCollectionMessageHandler Collection: acollection operation: create failed:org.apache.solr.common.SolrException: numShards is a required param (when using CompositeId router). [junit4] 2> at org.apache.solr.cloud.CreateCollectionCmd.call(CreateCollectionCmd.java:126) [junit4] 2> at org.apache.solr.cloud.OverseerCollectionMessageHandler.processMessage(OverseerCollectionMessageHandler.java:229) [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.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) [junit4] 2> at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) [junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844) [junit4] 2> [junit4] 2> 1310018 INFO (qtp781741865-11469) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=10&collection.configName=conf&name=acollection&action=CREATE&wt=javabin&version=2} status=400 QTime=5 [junit4] 2> 1310018 INFO (TEST-CollectionsAPIDistributedZkTest.testMissingNumShards-seed#[FDA1C878594403EB]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testMissingNumShards [junit4] 2> 1310047 INFO (TEST-CollectionsAPIDistributedZkTest.testSpecificConfigsets-seed#[FDA1C878594403EB]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testSpecificConfigsets [junit4] 2> 1310049 INFO (TEST-CollectionsAPIDistributedZkTest.testSpecificConfigsets-seed#[FDA1C878594403EB]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 1310050 INFO (qtp781741865-11471) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf2&name=withconfigset2&nrtReplicas=1&action=CREATE&numShards=1&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 1310053 INFO (OverseerThreadFactory-5315-thread-5) [ ] o.a.s.c.CreateCollectionCmd Create collection withconfigset2 [junit4] 2> 1310054 INFO (OverseerCollectionConfigSetProcessor-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] 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> 1310282 INFO (OverseerStateUpdate-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"withconfigset2", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"withconfigset2_shard1_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:64603/solr";, [junit4] 2> "type":"NRT"} [junit4] 2> 1310496 INFO (qtp94493586-11491) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node2&collection.configName=conf2&newCollection=true&name=withconfigset2_shard1_replica_n1&action=CREATE&numShards=1&collection=withconfigset2&shard=shard1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 1310496 INFO (qtp94493586-11491) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 1310619 INFO (zkCallback-1776-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/withconfigset2/state.json] for collection [withconfigset2] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1310619 INFO (zkCallback-1776-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/withconfigset2/state.json] for collection [withconfigset2] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1311520 INFO (qtp94493586-11491) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.0 [junit4] 2> 1311527 INFO (qtp94493586-11491) [ ] o.a.s.s.IndexSchema [withconfigset2_shard1_replica_n1] Schema name=minimal [junit4] 2> 1311541 INFO (qtp94493586-11491) [ ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 1311541 INFO (qtp94493586-11491) [ ] o.a.s.c.CoreContainer Creating SolrCore 'withconfigset2_shard1_replica_n1' using configuration from collection withconfigset2, trusted=true [junit4] 2> 1311541 INFO (qtp94493586-11491) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.withconfigset2.shard1.replica_n1' (registry 'solr.core.withconfigset2.shard1.replica_n1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3b4987aa [junit4] 2> 1311541 INFO (qtp94493586-11491) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 1311541 INFO (qtp94493586-11491) [ ] o.a.s.c.SolrCore [[withconfigset2_shard1_replica_n1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001/tempDir-001/node3/withconfigset2_shard1_replica_n1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001/tempDir-001/node3/withconfigset2_shard1_replica_n1/data/] [junit4] 2> 1311597 INFO (qtp94493586-11491) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 1311597 INFO (qtp94493586-11491) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 1311599 INFO (qtp94493586-11491) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 1311599 INFO (qtp94493586-11491) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 1311600 INFO (qtp94493586-11491) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@1451bc55[withconfigset2_shard1_replica_n1] main] [junit4] 2> 1311602 INFO (qtp94493586-11491) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf2 [junit4] 2> 1311602 INFO (qtp94493586-11491) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf2 [junit4] 2> 1311603 INFO (qtp94493586-11491) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 1311603 INFO (qtp94493586-11491) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1580799239891451904 [junit4] 2> 1311603 INFO (searcherExecutor-5336-thread-1) [ ] o.a.s.c.SolrCore [withconfigset2_shard1_replica_n1] Registered new searcher Searcher@1451bc55[withconfigset2_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 1311609 INFO (qtp94493586-11491) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 1311609 INFO (qtp94493586-11491) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 1311609 INFO (qtp94493586-11491) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:64603/solr/withconfigset2_shard1_replica_n1/ [junit4] 2> 1311609 INFO (qtp94493586-11491) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 1311609 INFO (qtp94493586-11491) [ ] o.a.s.c.SyncStrategy http://127.0.0.1:64603/solr/withconfigset2_shard1_replica_n1/ has no replicas [junit4] 2> 1311609 INFO (qtp94493586-11491) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 1311614 INFO (qtp94493586-11491) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:64603/solr/withconfigset2_shard1_replica_n1/ shard1 [junit4] 2> 1311725 INFO (zkCallback-1776-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/withconfigset2/state.json] for collection [withconfigset2] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1311726 INFO (zkCallback-1776-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/withconfigset2/state.json] for collection [withconfigset2] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1311784 INFO (qtp94493586-11491) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 1311787 INFO (qtp94493586-11491) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node2&collection.configName=conf2&newCollection=true&name=withconfigset2_shard1_replica_n1&action=CREATE&numShards=1&collection=withconfigset2&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1291 [junit4] 2> 1311793 INFO (qtp781741865-11471) [ ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas [junit4] 2> 1311903 INFO (zkCallback-1776-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/withconfigset2/state.json] for collection [withconfigset2] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1311904 INFO (zkCallback-1776-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/withconfigset2/state.json] for collection [withconfigset2] has occurred - updating... (live nodes size: [4]) [junit4] 2> 1312066 INFO (OverseerCollectionConfigSetProcessor-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000018 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 1312804 INFO (qtp781741865-11471) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf2&name=withconfigset2&nrtReplicas=1&action=CREATE&numShards=1&wt=javabin&version=2} status=0 QTime=2754 [junit4] 2> 1312805 INFO (TEST-CollectionsAPIDistributedZkTest.testSpecificConfigsets-seed#[FDA1C878594403EB]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testSpecificConfigsets [junit4] 2> 1312833 INFO (TEST-CollectionsAPIDistributedZkTest.deleteCollectionRemovesStaleZkCollectionsNode-seed#[FDA1C878594403EB]) [ ] o.a.s.SolrTestCaseJ4 ###Starting deleteCollectionRemovesStaleZkCollectionsNode [junit4] 2> 1312835 INFO (TEST-CollectionsAPIDistributedZkTest.deleteCollectionRemovesStaleZkCollectionsNode-seed#[FDA1C878594403EB]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 1312837 INFO (qtp781741865-11467) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=withconfigset2&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 1312841 INFO (OverseerThreadFactory-5315-thread-5) [ ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true [junit4] 2> 1312843 INFO (qtp94493586-11492) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.withconfigset2.shard1.replica_n1, tag=null [junit4] 2> 1312843 INFO (qtp94493586-11492) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@6b7bcbe4: rootName = null, domain = solr.core.withconfigset2.shard1.replica_n1, service url = null, agent id = null] for registry solr.core.withconfigset2.shard1.replica_n1 / com.codahale.metrics.MetricRegistry@2d67d60f [junit4] 2> 1312852 INFO (qtp94493586-11492) [ ] o.a.s.c.SolrCore [withconfigset2_shard1_replica_n1] CLOSING SolrCore org.apache.solr.core.SolrCore@e94d59e [junit4] 2> 1312852 INFO (qtp94493586-11492) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.withconfigset2.shard1.replica_n1, tag=244635038 [junit4] 2> 1312852 INFO (qtp94493586-11492) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.withconfigset2.shard1.leader, tag=244635038 [junit4] 2> 1312859 INFO (qtp94493586-11492) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=withconfigset2_shard1_replica_n1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=16 [junit4] 2> 1313587 INFO (qtp781741865-11467) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=withconfigset2&action=DELETE&wt=javabin&version=2} status=0 QTime=749 [junit4] 2> 1313590 INFO (qtp781741865-11474) [ ] 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> 1313594 INFO (OverseerCollectionConfigSetProcessor-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000020 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 1313599 INFO (qtp781741865-11474) [ ] 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=8 [junit4] 2> 1313600 INFO (qtp781741865-11472) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 1313600 INFO (qtp781741865-11472) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 1313601 INFO (TEST-CollectionsAPIDistributedZkTest.deleteCollectionRemovesStaleZkCollectionsNode-seed#[FDA1C878594403EB]) [ ] o.a.s.SolrTestCaseJ4 ###Ending deleteCollectionRemovesStaleZkCollectionsNode [junit4] 2> 1313628 INFO (TEST-CollectionsAPIDistributedZkTest.deletePartiallyCreatedCollection-seed#[FDA1C878594403EB]) [ ] o.a.s.SolrTestCaseJ4 ###Starting deletePartiallyCreatedCollection [junit4] 2> 1313630 INFO (TEST-CollectionsAPIDistributedZkTest.deletePartiallyCreatedCollection-seed#[FDA1C878594403EB]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 1313632 INFO (qtp781741865-11476) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf&name=halfdeletedcollection&nrtReplicas=1&action=CREATE&numShards=2&createNodeSet=&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 1313635 INFO (OverseerThreadFactory-5315-thread-5) [ ] o.a.s.c.CreateCollectionCmd Create collection halfdeletedcollection [junit4] 2> 1313636 INFO (OverseerCollectionConfigSetProcessor-98799950018052105-127.0.0.1:64603_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000022 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 1313636 WARN (OverseerThreadFactory-5315-thread-5) [ ] o.a.s.c.CreateCollectionCmd It is unusual to create a collection (halfdeletedcollection) without cores. [junit4] 2> 1313857 INFO (qtp781741865-11476) [ ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas [junit4] 2> 1313857 INFO (qtp781741865-11476) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={ [...truncated too long message...] olExecutor.java:641) [junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844) [junit4] 2> [junit4] 2> 1355162 INFO (OverseerThreadFactory-5436-thread-5) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000081 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 1355163 WARN (OverseerAutoScalingTriggerThread-98799950018052107-127.0.0.1:64605_solr-n_0000000001) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting. [junit4] 2> 1356524 WARN (zkCallback-1777-thread-6) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 1356525 INFO (jetty-closer-1758-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@43743530{/solr,null,UNAVAILABLE} [junit4] 2> 1356569 WARN (zkCallback-1778-thread-5) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 1356570 WARN (zkCallback-1807-thread-5) [ ] o.a.s.c.ZkController Unable to read autoscaling.json [junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /autoscaling.json [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127) [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) [junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1212) [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:357) [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:354) [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:60) [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:354) [junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.getAutoScalingConfig(ZkStateReader.java:185) [junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.getAutoScalingConfig(ZkStateReader.java:171) [junit4] 2> at org.apache.solr.cloud.ZkController.lambda$registerLiveNodesListener$2(ZkController.java:843) [junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.lambda$refreshLiveNodes$1(ZkStateReader.java:747) [junit4] 2> at java.base/java.util.concurrent.ConcurrentHashMap$KeySetView.forEach(ConcurrentHashMap.java:4724) [junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.refreshLiveNodes(ZkStateReader.java:746) [junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.access$1000(ZkStateReader.java:72) [junit4] 2> at org.apache.solr.common.cloud.ZkStateReader$LiveNodeWatcher.refreshAndWatch(ZkStateReader.java:1152) [junit4] 2> at org.apache.solr.common.cloud.ZkStateReader$LiveNodeWatcher.process(ZkStateReader.java:1147) [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.lambda$process$0(SolrZkClient.java:269) [junit4] 2> at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514) [junit4] 2> at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) [junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188) [junit4] 2> at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) [junit4] 2> at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) [junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844) [junit4] 2> 1356571 INFO (jetty-closer-1758-thread-3) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@5e009b41{/solr,null,UNAVAILABLE} [junit4] 2> 1356570 WARN (zkCallback-1807-thread-2) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 1356575 INFO (jetty-closer-1758-thread-4) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@3c98aa42{/solr,null,UNAVAILABLE} [junit4] 2> 1356667 WARN (zkCallback-1779-thread-1) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 1356667 INFO (jetty-closer-1758-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@1c44bb30{/solr,null,UNAVAILABLE} [junit4] 2> 1356669 ERROR (SUITE-CollectionsAPIDistributedZkTest-seed#[FDA1C878594403EB]-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> 1356670 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[FDA1C878594403EB]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:64599 64599 [junit4] 2> 1356671 INFO (Thread-2389) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:64599 64599 [junit4] 2> 1356874 WARN (Thread-2389) [ ] o.a.s.c.ZkTestServer Watch limit violations: [junit4] 2> Maximum concurrent create/delete watches above limit: [junit4] 2> [junit4] 2> 10 /solr/configs/conf [junit4] 2> 7 /solr/clusterprops.json [junit4] 2> 7 /solr/aliases.json [junit4] 2> [junit4] 2> Maximum concurrent data watches above limit: [junit4] 2> [junit4] 2> 28 /solr/collections/nodes_used_collection/state.json [junit4] 2> 24 /solr/collections/reloaded_collection/state.json [junit4] 2> 15 /solr/collections/acollectionafterbaddelete/state.json [junit4] 2> 7 /solr/clusterstate.json [junit4] 2> 4 /solr/collections/awhollynewcollection_0/state.json [junit4] 2> 2 /solr/overseer_elect/election/98799950018052107-127.0.0.1:64605_solr-n_0000000001 [junit4] 2> [junit4] 2> Maximum concurrent children watches above limit: [junit4] 2> [junit4] 2> 103 /solr/collections [junit4] 2> 7 /solr/live_nodes [junit4] 2> [junit4] 2> NOTE: leaving temporary files on disk at: /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_FDA1C878594403EB-001 [junit4] 2> Oct 09, 2017 4:47:59 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks [junit4] 2> WARNING: Will linger awaiting termination of 1 leaked thread(s). [junit4] 2> NOTE: test params are: codec=Asserting(Lucene70): {id=PostingsFormat(name=Asserting)}, docValues:{_version_=DocValuesFormat(name=Memory)}, maxPointsInLeafNode=1335, maxMBSortInHeap=6.859960723941446, sim=RandomSimilarity(queryNorm=false): {}, locale=th, timezone=Asia/Tomsk [junit4] 2> NOTE: Mac OS X 10.11.6 x86_64/Oracle Corporation 9 (64-bit)/cpus=3,threads=1,free=188942736,total=536870912 [junit4] 2> NOTE: All tests run in this JVM: [ConfigSetsAPITest, UpdateRequestProcessorFactoryTest, HdfsWriteToMultipleCollectionsTest, CollectionReloadTest, ShowFileRequestHandlerTest, TestComplexPhraseQParserPlugin, ReplicationFactorTest, CdcrReplicationHandlerTest, SolrCoreCheckLockOnStartupTest, TestFileDictionaryLookup, TestHdfsCloudBackupRestore, TestLeaderElectionZkExpiry, AnalysisErrorHandlingTest, MoveReplicaHDFSFailoverTest, TestCollationFieldDocValues, TestUseDocValuesAsStored, TestUniqueKeyFieldResource, TestExactSharedStatsCache, BlockDirectoryTest, TestLuceneMatchVersion, TestCloudPseudoReturnFields, TestLuceneIndexBackCompat, MigrateRouteKeyTest, TestComponentsName, SpellCheckComponentTest, TestPullReplicaErrorHandling, TestSolrCLIRunExample, TestJavabinTupleStreamParser, TestRecovery, DateRangeFieldTest, TestStreamBody, TestUnifiedSolrHighlighter, OpenExchangeRatesOrgProviderTest, TestCloudNestedDocsSort, SolrXmlInZkTest, TestManagedSynonymFilterFactory, DistribJoinFromCollectionTest, TestSolrQueryParser, SpatialHeatmapFacetsTest, TestRemoteStreaming, DistributedVersionInfoTest, TestDocumentBuilder, AssignBackwardCompatibilityTest, TestSegmentSorting, TestCSVLoader, TestCoreDiscovery, CleanupOldIndexTest, MoveReplicaTest, DistributedFacetPivotWhiteBoxTest, TestCrossCoreJoin, DOMUtilTest, TestRTGBase, TestJsonRequest, OverseerModifyCollectionTest, TestCloudJSONFacetJoinDomain, OpenCloseCoreStressTest, HLLUtilTest, TestValueSourceCache, TestSimpleTrackingShardHandler, TestElisionMultitermQuery, TestFieldCacheWithThreads, TestRawResponseWriter, TestSolrJ, TestLocalFSCloudBackupRestore, TestCloudDeleteByQuery, TestExceedMaxTermLength, TestPerFieldSimilarityWithDefaultOverride, ForceLeaderTest, TestPrepRecovery, ExternalFileFieldSortTest, TestDynamicLoading, TestMinMaxOnMultiValuedField, TestManagedResource, SpellingQueryConverterTest, SolrShardReporterTest, TestHighFrequencyDictionaryFactory, BlockJoinFacetSimpleTest, TestSchemaVersionResource, SolrIndexConfigTest, TestSolrCloudWithSecureImpersonation, TestCollectionAPIs, TestTlogReplica, HttpPartitionTest, SystemInfoHandlerTest, ComputePlanActionTest, ChangedSchemaMergeTest, TestDistributedMissingSort, HdfsAutoAddReplicasIntegrationTest, CoreMergeIndexesAdminHandlerTest, BasicDistributedZk2Test, BitVectorTest, TestMaxScoreQueryParser, TestRequestStatusCollectionAPI, SolrCmdDistributorTest, SpellCheckCollatorTest, TestConfigOverlay, SolrPluginUtilsTest, TestRetrieveFieldsOptimizer, HttpSolrCallGetCoreTest, DistributedQueryElevationComponentTest, TestNRTOpen, DistributedQueryComponentOptimizationTest, StatsReloadRaceTest, TestSchemaResource, TestChildDocTransformer, TestFastOutputStream, PreAnalyzedFieldTest, ActionThrottleTest, TestTolerantUpdateProcessorRandomCloud, TestDFISimilarityFactory, TestRealTimeGet, TestSearchPerf, TestJoin, CollectionsAPIDistributedZkTest] [junit4] Completed [155/745 (1!)] on J1 in 83.32s, 19 tests, 1 error <<< FAILURES! [...truncated 41756 lines...]
--------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org
