Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.6-Linux/73/ Java: 32bit/jdk-9-ea+181 -client -XX:+UseParallelGC --illegal-access=deny
1 tests failed. FAILED: org.apache.solr.common.cloud.TestCollectionStateWatchers.testWaitForStateWatcherIsRetainedOnPredicateFailure Error Message: Did not see a fully active cluster after 30 seconds Stack Trace: java.lang.AssertionError: Did not see a fully active cluster after 30 seconds at __randomizedtesting.SeedInfo.seed([EFF932D00BBAF2D6:67CF9083D3151AC4]:0) at org.junit.Assert.fail(Assert.java:93) at org.junit.Assert.assertTrue(Assert.java:43) at org.apache.solr.common.cloud.TestCollectionStateWatchers.testWaitForStateWatcherIsRetainedOnPredicateFailure(TestCollectionStateWatchers.java:250) 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:1713) at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:907) at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943) at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957) at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57) at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49) at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45) at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48) at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64) at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368) at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817) at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468) at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916) at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802) at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852) at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57) at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41) at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at 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) Build Log: [...truncated 13901 lines...] [junit4] Suite: org.apache.solr.common.cloud.TestCollectionStateWatchers [junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/init-core-data-001 [junit4] 2> 5350 WARN (SUITE-TestCollectionStateWatchers-seed#[EFF932D00BBAF2D6]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=6 numCloses=6 [junit4] 2> 5350 INFO (SUITE-TestCollectionStateWatchers-seed#[EFF932D00BBAF2D6]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields [junit4] 2> 5354 INFO (SUITE-TestCollectionStateWatchers-seed#[EFF932D00BBAF2D6]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason="", ssl=0.0/0.0, value=0.0/0.0, clientAuth=0.0/0.0) [junit4] 2> 5362 INFO (SUITE-TestCollectionStateWatchers-seed#[EFF932D00BBAF2D6]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 4 servers in /home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001 [junit4] 2> 5369 INFO (SUITE-TestCollectionStateWatchers-seed#[EFF932D00BBAF2D6]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER [junit4] 2> 5381 INFO (Thread-11) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0 [junit4] 2> 5381 INFO (Thread-11) [ ] o.a.s.c.ZkTestServer Starting server [junit4] 2> 5481 INFO (SUITE-TestCollectionStateWatchers-seed#[EFF932D00BBAF2D6]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:45197 [junit4] 2> 5524 ERROR (Thread-11) [ ] 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> 5646 INFO (jetty-launcher-4-thread-3) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 5648 INFO (jetty-launcher-4-thread-2) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 5650 INFO (jetty-launcher-4-thread-4) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 5651 INFO (jetty-launcher-4-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 5694 INFO (jetty-launcher-4-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@1779e46{/solr,null,AVAILABLE} [junit4] 2> 5702 INFO (jetty-launcher-4-thread-3) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@4a1f0b{/solr,null,AVAILABLE} [junit4] 2> 5720 INFO (jetty-launcher-4-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@1baae12{SSL,[ssl, http/1.1]}{127.0.0.1:36907} [junit4] 2> 5720 INFO (jetty-launcher-4-thread-1) [ ] o.e.j.s.Server Started @7560ms [junit4] 2> 5720 INFO (jetty-launcher-4-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=36907} [junit4] 2> 5720 ERROR (jetty-launcher-4-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 5720 INFO (jetty-launcher-4-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.6.1 [junit4] 2> 5721 INFO (jetty-launcher-4-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 5721 INFO (jetty-launcher-4-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 5721 INFO (jetty-launcher-4-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-08-21T01:00:39.855077Z [junit4] 2> 5721 INFO (jetty-launcher-4-thread-1) [ ] o.a.s.c.SolrResourceLoader solr home defaulted to 'solr/' (could not find system property or JNDI) [junit4] 2> 5732 INFO (jetty-launcher-4-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@a5283c{/solr,null,AVAILABLE} [junit4] 2> 5733 INFO (jetty-launcher-4-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@dd4cbb{SSL,[ssl, http/1.1]}{127.0.0.1:34799} [junit4] 2> 5733 INFO (jetty-launcher-4-thread-2) [ ] o.e.j.s.Server Started @7573ms [junit4] 2> 5733 INFO (jetty-launcher-4-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=34799} [junit4] 2> 5733 ERROR (jetty-launcher-4-thread-2) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 5733 INFO (jetty-launcher-4-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.6.1 [junit4] 2> 5733 INFO (jetty-launcher-4-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 5733 INFO (jetty-launcher-4-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 5733 INFO (jetty-launcher-4-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-08-21T01:00:39.867564Z [junit4] 2> 5738 INFO (jetty-launcher-4-thread-3) [ ] o.e.j.s.AbstractConnector Started ServerConnector@611e7f{SSL,[ssl, http/1.1]}{127.0.0.1:33057} [junit4] 2> 5739 INFO (jetty-launcher-4-thread-3) [ ] o.e.j.s.Server Started @7579ms [junit4] 2> 5739 INFO (jetty-launcher-4-thread-3) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=33057} [junit4] 2> 5739 ERROR (jetty-launcher-4-thread-3) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 5739 INFO (jetty-launcher-4-thread-3) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.6.1 [junit4] 2> 5739 INFO (jetty-launcher-4-thread-3) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 5739 INFO (jetty-launcher-4-thread-3) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 5739 INFO (jetty-launcher-4-thread-3) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-08-21T01:00:39.873500Z [junit4] 2> 5783 INFO (jetty-launcher-4-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 5812 INFO (jetty-launcher-4-thread-4) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@1c9f542{/solr,null,AVAILABLE} [junit4] 2> 5813 INFO (jetty-launcher-4-thread-4) [ ] o.e.j.s.AbstractConnector Started ServerConnector@191f58e{SSL,[ssl, http/1.1]}{127.0.0.1:44743} [junit4] 2> 5813 INFO (jetty-launcher-4-thread-4) [ ] o.e.j.s.Server Started @7653ms [junit4] 2> 5813 INFO (jetty-launcher-4-thread-4) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=44743} [junit4] 2> 5813 ERROR (jetty-launcher-4-thread-4) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 5813 INFO (jetty-launcher-4-thread-4) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.6.1 [junit4] 2> 5813 INFO (jetty-launcher-4-thread-4) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 5813 INFO (jetty-launcher-4-thread-4) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 5813 INFO (jetty-launcher-4-thread-4) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-08-21T01:00:39.947835Z [junit4] 2> 5820 INFO (jetty-launcher-4-thread-1) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true [junit4] 2> 5822 INFO (jetty-launcher-4-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:45197/solr [junit4] 2> 5838 INFO (jetty-launcher-4-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 5887 INFO (jetty-launcher-4-thread-2) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true [junit4] 2> 5888 INFO (jetty-launcher-4-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:45197/solr [junit4] 2> 5893 INFO (jetty-launcher-4-thread-3) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 5951 INFO (jetty-launcher-4-thread-3) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true [junit4] 2> 5953 INFO (jetty-launcher-4-thread-3) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:45197/solr [junit4] 2> 5963 INFO (jetty-launcher-4-thread-4) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 5966 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception [junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x15e024e4cf80006, likely client has closed socket [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239) [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203) [junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844) [junit4] 2> 6068 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception [junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x15e024e4cf80007, likely client has closed socket [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239) [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203) [junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844) [junit4] 2> 6163 INFO (jetty-launcher-4-thread-4) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true [junit4] 2> 6173 INFO (jetty-launcher-4-thread-4) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:45197/solr [junit4] 2> 6245 INFO (jetty-launcher-4-thread-1) [ ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 6246 INFO (jetty-launcher-4-thread-3) [ ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 6250 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception [junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x15e024e4cf8000b, likely client has closed socket [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239) [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203) [junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844) [junit4] 2> 6252 INFO (jetty-launcher-4-thread-3) [ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:33057_solr [junit4] 2> 6254 INFO (jetty-launcher-4-thread-2) [ ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 6255 INFO (jetty-launcher-4-thread-1) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36907_solr [junit4] 2> 6298 INFO (zkCallback-22-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 6291 INFO (jetty-launcher-4-thread-2) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34799_solr [junit4] 2> 6298 INFO (zkCallback-20-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 6306 INFO (zkCallback-20-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 6314 INFO (zkCallback-22-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 6315 INFO (jetty-launcher-4-thread-3) [ ] o.a.s.c.Overseer Overseer (id=98518777170755594-127.0.0.1:33057_solr-n_0000000000) starting [junit4] 2> 6320 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2) [junit4] 2> 6327 INFO (jetty-launcher-4-thread-4) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2) [junit4] 2> 6329 INFO (jetty-launcher-4-thread-4) [ ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 6332 INFO (jetty-launcher-4-thread-4) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44743_solr [junit4] 2> 6334 INFO (zkCallback-22-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 6334 INFO (zkCallback-20-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 6334 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 6346 INFO (zkCallback-29-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 6450 INFO (jetty-launcher-4-thread-3) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33057_solr [junit4] 2> 6453 INFO (zkCallback-20-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 6453 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 6453 INFO (zkCallback-29-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 6454 INFO (zkCallback-22-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 6867 INFO (jetty-launcher-4-thread-2) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node3/. [junit4] 2> 6873 INFO (jetty-launcher-4-thread-4) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node4/. [junit4] 2> 7136 INFO (jetty-launcher-4-thread-3) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node2/. [junit4] 2> 7151 INFO (jetty-launcher-4-thread-1) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node1/. [junit4] 2> 7231 INFO (SUITE-TestCollectionStateWatchers-seed#[EFF932D00BBAF2D6]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 7232 INFO (SUITE-TestCollectionStateWatchers-seed#[EFF932D00BBAF2D6]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:45197/solr ready [junit4] 2> 7291 INFO (TEST-TestCollectionStateWatchers.testDeletionsTriggerWatches-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testDeletionsTriggerWatches [junit4] 2> 7489 INFO (qtp20786761-59) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=config&name=tobedeleted&action=CREATE&numShards=1&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 7510 INFO (OverseerThreadFactory-31-thread-1) [ ] o.a.s.c.CreateCollectionCmd Create collection tobedeleted [junit4] 2> 7722 INFO (qtp29321600-56) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=config&newCollection=true&name=tobedeleted_shard1_replica1&action=CREATE&numShards=1&collection=tobedeleted&shard=shard1&wt=javabin&version=2 [junit4] 2> 7723 INFO (qtp29321600-56) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 7833 INFO (zkCallback-22-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tobedeleted/state.json] for collection [tobedeleted] has occurred - updating... (live nodes size: [4]) [junit4] 2> 8747 INFO (qtp29321600-56) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.1 [junit4] 2> 8767 INFO (qtp29321600-56) [ ] o.a.s.s.IndexSchema [tobedeleted_shard1_replica1] Schema name=test [junit4] 2> 8883 WARN (qtp29321600-56) [ ] o.a.s.c.SolrResourceLoader Solr loaded a deprecated plugin/analysis class [solr.GeoHashField]. Please consult documentation how to replace it accordingly. [junit4] 2> 8887 WARN (qtp29321600-56) [ ] o.a.s.c.SolrResourceLoader Solr loaded a deprecated plugin/analysis class [solr.LatLonType]. Please consult documentation how to replace it accordingly. [junit4] 2> 8891 WARN (qtp29321600-56) [ ] o.a.s.s.IndexSchema Field lowerfilt1and2 is not multivalued and destination for multiple copyFields (2) [junit4] 2> 8891 WARN (qtp29321600-56) [ ] o.a.s.s.IndexSchema Field text is not multivalued and destination for multiple copyFields (3) [junit4] 2> 8892 INFO (qtp29321600-56) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id [junit4] 2> 8893 INFO (qtp29321600-56) [ ] o.a.s.c.CoreContainer Creating SolrCore 'tobedeleted_shard1_replica1' using configuration from collection tobedeleted, trusted=true [junit4] 2> 8894 INFO (qtp29321600-56) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 8894 INFO (qtp29321600-56) [ ] o.a.s.c.SolrCore [[tobedeleted_shard1_replica1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node2/tobedeleted_shard1_replica1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node2/./tobedeleted_shard1_replica1/data/] [junit4] 2> 8937 INFO (qtp29321600-56) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 8938 INFO (qtp29321600-56) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 8940 INFO (qtp29321600-56) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 8942 INFO (qtp29321600-56) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 8944 INFO (qtp29321600-56) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@b1653c[tobedeleted_shard1_replica1] main] [junit4] 2> 8947 INFO (qtp29321600-56) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/config [junit4] 2> 8948 INFO (qtp29321600-56) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/config [junit4] 2> 8948 INFO (qtp29321600-56) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 8950 INFO (qtp29321600-56) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1576300438444048384 [junit4] 2> 8951 INFO (searcherExecutor-40-thread-1) [ ] o.a.s.c.SolrCore [tobedeleted_shard1_replica1] Registered new searcher Searcher@b1653c[tobedeleted_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 8979 INFO (qtp29321600-56) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 8979 INFO (qtp29321600-56) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 8980 INFO (qtp29321600-56) [ ] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:33057/solr/tobedeleted_shard1_replica1/ [junit4] 2> 8980 INFO (qtp29321600-56) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 8980 INFO (qtp29321600-56) [ ] o.a.s.c.SyncStrategy https://127.0.0.1:33057/solr/tobedeleted_shard1_replica1/ has no replicas [junit4] 2> 8980 INFO (qtp29321600-56) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 9020 INFO (qtp29321600-56) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:33057/solr/tobedeleted_shard1_replica1/ shard1 [junit4] 2> 9119 INFO (zkCallback-22-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tobedeleted/state.json] for collection [tobedeleted] has occurred - updating... (live nodes size: [4]) [junit4] 2> 9122 INFO (qtp29321600-56) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 9126 INFO (qtp29321600-56) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=config&newCollection=true&name=tobedeleted_shard1_replica1&action=CREATE&numShards=1&collection=tobedeleted&shard=shard1&wt=javabin&version=2} status=0 QTime=1404 [junit4] 2> 9167 INFO (qtp20786761-59) [ ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas [junit4] 2> 9231 INFO (zkCallback-22-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tobedeleted/state.json] for collection [tobedeleted] has occurred - updating... (live nodes size: [4]) [junit4] 2> 9511 INFO (OverseerCollectionConfigSetProcessor-98518777170755594-127.0.0.1:33057_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> 10168 INFO (qtp20786761-59) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=config&name=tobedeleted&action=CREATE&numShards=1&wt=javabin&version=2} status=0 QTime=2679 [junit4] 2> 10174 INFO (qtp20786761-64) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=tobedeleted&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 10184 INFO (OverseerThreadFactory-31-thread-2) [ ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true [junit4] 2> 10187 INFO (qtp29321600-58) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.tobedeleted.shard1.replica1 [junit4] 2> 10188 INFO (qtp29321600-58) [ ] o.a.s.c.SolrCore [tobedeleted_shard1_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@804737 [junit4] 2> 10190 INFO (qtp29321600-58) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.tobedeleted.shard1.replica1 [junit4] 2> 10195 INFO (qtp29321600-58) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=tobedeleted_shard1_replica1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=8 [junit4] 2> 10302 INFO (zkCallback-34-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDeleted path:/collections/tobedeleted/state.json] for collection [tobedeleted] has occurred - updating... (live nodes size: [4]) [junit4] 2> 10903 INFO (qtp20786761-64) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=tobedeleted&action=DELETE&wt=javabin&version=2} status=0 QTime=728 [junit4] 2> 10904 INFO (TEST-TestCollectionStateWatchers.testDeletionsTriggerWatches-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testDeletionsTriggerWatches [junit4] 2> 10945 INFO (TEST-TestCollectionStateWatchers.testSimpleCollectionWatch-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testSimpleCollectionWatch [junit4] 2> 10990 INFO (qtp20786761-65) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params async=fc22bba1-4816-49dd-a1a1-44827f30c54d&replicationFactor=1&collection.configName=config&name=testcollection&action=CREATE&numShards=4&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 10992 INFO (qtp20786761-65) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={async=fc22bba1-4816-49dd-a1a1-44827f30c54d&replicationFactor=1&collection.configName=config&name=testcollection&action=CREATE&numShards=4&wt=javabin&version=2} status=0 QTime=1 [junit4] 2> 10997 INFO (qtp20786761-66) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :requeststatus with params requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d&action=REQUESTSTATUS&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 10998 INFO (qtp20786761-66) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=1 [junit4] 2> 11002 INFO (OverseerThreadFactory-31-thread-3) [ ] o.a.s.c.CreateCollectionCmd Create collection testcollection [junit4] 2> 11026 INFO (OverseerCollectionConfigSetProcessor-98518777170755594-127.0.0.1:33057_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> 11283 INFO (qtp20786761-64) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={async=fc22bba1-4816-49dd-a1a1-44827f30c54d2274168390580518&qt=/admin/cores&collection.configName=config&newCollection=true&name=testcollection_shard1_replica1&action=CREATE&numShards=4&collection=testcollection&shard=shard1&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 11283 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.h.a.CoreAdminOperation core create command async=fc22bba1-4816-49dd-a1a1-44827f30c54d2274168390580518&qt=/admin/cores&collection.configName=config&newCollection=true&name=testcollection_shard1_replica1&action=CREATE&numShards=4&collection=testcollection&shard=shard1&wt=javabin&version=2 [junit4] 2> 11283 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 11292 INFO (qtp29321600-77) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={async=fc22bba1-4816-49dd-a1a1-44827f30c54d2274168390910758&qt=/admin/cores&collection.configName=config&newCollection=true&name=testcollection_shard2_replica1&action=CREATE&numShards=4&collection=testcollection&shard=shard2&wt=javabin&version=2} status=0 QTime=6 [junit4] 2> 11294 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.h.a.CoreAdminOperation core create command async=fc22bba1-4816-49dd-a1a1-44827f30c54d2274168390910758&qt=/admin/cores&collection.configName=config&newCollection=true&name=testcollection_shard2_replica1&action=CREATE&numShards=4&collection=testcollection&shard=shard2&wt=javabin&version=2 [junit4] 2> 11338 INFO (qtp27709112-98) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={async=fc22bba1-4816-49dd-a1a1-44827f30c54d2274168391054431&qt=/admin/cores&collection.configName=config&newCollection=true&name=testcollection_shard4_replica1&action=CREATE&numShards=4&collection=testcollection&shard=shard4&wt=javabin&version=2} status=0 QTime=9 [junit4] 2> 11338 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.h.a.CoreAdminOperation core create command async=fc22bba1-4816-49dd-a1a1-44827f30c54d2274168391054431&qt=/admin/cores&collection.configName=config&newCollection=true&name=testcollection_shard4_replica1&action=CREATE&numShards=4&collection=testcollection&shard=shard4&wt=javabin&version=2 [junit4] 2> 11339 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 11346 INFO (qtp3283411-57) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={async=fc22bba1-4816-49dd-a1a1-44827f30c54d2274168393956416&qt=/admin/cores&collection.configName=config&newCollection=true&name=testcollection_shard3_replica1&action=CREATE&numShards=4&collection=testcollection&shard=shard3&wt=javabin&version=2} status=0 QTime=4 [junit4] 2> 11347 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.h.a.CoreAdminOperation core create command async=fc22bba1-4816-49dd-a1a1-44827f30c54d2274168393956416&qt=/admin/cores&collection.configName=config&newCollection=true&name=testcollection_shard3_replica1&action=CREATE&numShards=4&collection=testcollection&shard=shard3&wt=javabin&version=2 [junit4] 2> 11348 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 11360 INFO (qtp20786761-65) [ ] o.a.s.h.a.CoreAdminOperation Checking request status for : fc22bba1-4816-49dd-a1a1-44827f30c54d2274168390580518 [junit4] 2> 11362 INFO (qtp20786761-65) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d2274168390580518&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=2 [junit4] 2> 11461 INFO (zkCallback-29-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 11461 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 11461 INFO (zkCallback-20-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 11461 INFO (zkCallback-22-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 12002 INFO (qtp20786761-59) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :requeststatus with params requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d&action=REQUESTSTATUS&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 12008 INFO (qtp20786761-59) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=5 [junit4] 2> 12336 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.1 [junit4] 2> 12366 INFO (qtp20786761-66) [ ] o.a.s.h.a.CoreAdminOperation Checking request status for : fc22bba1-4816-49dd-a1a1-44827f30c54d2274168390580518 [junit4] 2> 12366 INFO (qtp20786761-66) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d2274168390580518&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 12372 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.1 [junit4] 2> 12387 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.s.IndexSchema [testcollection_shard1_replica1] Schema name=test [junit4] 2> 12390 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.1 [junit4] 2> 12396 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.1 [junit4] 2> 12400 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.s.IndexSchema [testcollection_shard2_replica1] Schema name=test [junit4] 2> 12410 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.s.IndexSchema [testcollection_shard4_replica1] Schema name=test [junit4] 2> 12433 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.s.IndexSchema [testcollection_shard3_replica1] Schema name=test [junit4] 2> 12501 WARN (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.s.IndexSchema Field lowerfilt1and2 is not multivalued and destination for multiple copyFields (2) [junit4] 2> 12501 WARN (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.s.IndexSchema Field text is not multivalued and destination for multiple copyFields (3) [junit4] 2> 12501 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id [junit4] 2> 12501 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.c.CoreContainer Creating SolrCore 'testcollection_shard4_replica1' using configuration from collection testcollection, trusted=true [junit4] 2> 12502 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 12502 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.c.SolrCore [[testcollection_shard4_replica1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node4/testcollection_shard4_replica1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node4/./testcollection_shard4_replica1/data/] [junit4] 2> 12504 WARN (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.s.IndexSchema Field lowerfilt1and2 is not multivalued and destination for multiple copyFields (2) [junit4] 2> 12504 WARN (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.s.IndexSchema Field text is not multivalued and destination for multiple copyFields (3) [junit4] 2> 12505 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id [junit4] 2> 12505 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.c.CoreContainer Creating SolrCore 'testcollection_shard3_replica1' using configuration from collection testcollection, trusted=true [junit4] 2> 12511 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 12512 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.c.SolrCore [[testcollection_shard3_replica1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node3/testcollection_shard3_replica1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node3/./testcollection_shard3_replica1/data/] [junit4] 2> 12513 WARN (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.s.IndexSchema Field lowerfilt1and2 is not multivalued and destination for multiple copyFields (2) [junit4] 2> 12513 WARN (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.s.IndexSchema Field text is not multivalued and destination for multiple copyFields (3) [junit4] 2> 12513 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id [junit4] 2> 12514 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.c.CoreContainer Creating SolrCore 'testcollection_shard1_replica1' using configuration from collection testcollection, trusted=true [junit4] 2> 12514 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 12514 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.c.SolrCore [[testcollection_shard1_replica1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node1/testcollection_shard1_replica1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node1/./testcollection_shard1_replica1/data/] [junit4] 2> 12521 WARN (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.s.IndexSchema Field lowerfilt1and2 is not multivalued and destination for multiple copyFields (2) [junit4] 2> 12521 WARN (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.s.IndexSchema Field text is not multivalued and destination for multiple copyFields (3) [junit4] 2> 12521 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id [junit4] 2> 12521 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.c.CoreContainer Creating SolrCore 'testcollection_shard2_replica1' using configuration from collection testcollection, trusted=true [junit4] 2> 12522 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 12522 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.c.SolrCore [[testcollection_shard2_replica1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node2/testcollection_shard2_replica1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node2/./testcollection_shard2_replica1/data/] [junit4] 2> 12674 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 12674 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 12675 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 12675 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 12676 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@1ca5d2[testcollection_shard3_replica1] main] [junit4] 2> 12682 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 12682 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 12692 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 12693 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 12693 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 12693 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 12695 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 12695 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 12696 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/config [junit4] 2> 12696 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@1155712[testcollection_shard4_replica1] main] [junit4] 2> 12696 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/config [junit4] 2> 12696 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 12696 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1576300442372014080 [junit4] 2> 12697 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@52d6fb[testcollection_shard2_replica1] main] [junit4] 2> 12702 INFO (searcherExecutor-46-thread-1) [ ] o.a.s.c.SolrCore [testcollection_shard3_replica1] Registered new searcher Searcher@1ca5d2[testcollection_shard3_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 12704 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 12704 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 12705 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/config [junit4] 2> 12705 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/config [junit4] 2> 12706 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/config [junit4] 2> 12706 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/config [junit4] 2> 12706 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 12706 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 12706 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 12706 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1576300442382499840 [junit4] 2> 12706 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 12708 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1576300442384596992 [junit4] 2> 12720 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@d4d220[testcollection_shard1_replica1] main] [junit4] 2> 12719 INFO (searcherExecutor-48-thread-1) [ ] o.a.s.c.SolrCore [testcollection_shard2_replica1] Registered new searcher Searcher@52d6fb[testcollection_shard2_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 12726 INFO (searcherExecutor-45-thread-1) [ ] o.a.s.c.SolrCore [testcollection_shard4_replica1] Registered new searcher Searcher@1155712[testcollection_shard4_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 12732 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 12732 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 12732 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:34799/solr/testcollection_shard3_replica1/ [junit4] 2> 12733 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 12733 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.c.SyncStrategy https://127.0.0.1:34799/solr/testcollection_shard3_replica1/ has no replicas [junit4] 2> 12733 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 12735 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/config [junit4] 2> 12736 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/config [junit4] 2> 12736 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 12737 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1576300442415005696 [junit4] 2> 12741 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:34799/solr/testcollection_shard3_replica1/ shard3 [junit4] 2> 12742 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 12742 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 12742 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:44743/solr/testcollection_shard4_replica1/ [junit4] 2> 12745 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 12745 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.c.SyncStrategy https://127.0.0.1:44743/solr/testcollection_shard4_replica1/ has no replicas [junit4] 2> 12745 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 12746 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 12746 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 12746 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:33057/solr/testcollection_shard2_replica1/ [junit4] 2> 12746 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 12746 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.c.SyncStrategy https://127.0.0.1:33057/solr/testcollection_shard2_replica1/ has no replicas [junit4] 2> 12746 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 12752 INFO (searcherExecutor-47-thread-1) [ ] o.a.s.c.SolrCore [testcollection_shard1_replica1] Registered new searcher Searcher@d4d220[testcollection_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 12758 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 12758 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 12758 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:36907/solr/testcollection_shard1_replica1/ [junit4] 2> 12758 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 12758 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.c.SyncStrategy https://127.0.0.1:36907/solr/testcollection_shard1_replica1/ has no replicas [junit4] 2> 12758 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 12780 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:44743/solr/testcollection_shard4_replica1/ shard4 [junit4] 2> 12780 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:33057/solr/testcollection_shard2_replica1/ shard2 [junit4] 2> 12788 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:36907/solr/testcollection_shard1_replica1/ shard1 [junit4] 2> 12920 INFO (zkCallback-29-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 12920 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 12920 INFO (zkCallback-20-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 12920 INFO (zkCallback-22-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 12933 INFO (parallelCoreAdminExecutor-33-thread-1) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 12935 INFO (parallelCoreAdminExecutor-36-thread-1) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 12939 INFO (parallelCoreAdminExecutor-37-thread-1) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 12948 INFO (parallelCoreAdminExecutor-32-thread-1) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 13011 INFO (qtp20786761-60) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :requeststatus with params requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d&action=REQUESTSTATUS&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 13012 INFO (qtp20786761-60) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 13052 INFO (zkCallback-29-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 13052 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 13053 INFO (zkCallback-20-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 13053 INFO (zkCallback-22-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 13369 INFO (qtp20786761-64) [ ] o.a.s.h.a.CoreAdminOperation Checking request status for : fc22bba1-4816-49dd-a1a1-44827f30c54d2274168390580518 [junit4] 2> 13369 INFO (qtp20786761-64) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d2274168390580518&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 13373 INFO (qtp3283411-84) [ ] o.a.s.h.a.CoreAdminOperation Checking request status for : fc22bba1-4816-49dd-a1a1-44827f30c54d2274168393956416 [junit4] 2> 13373 INFO (qtp3283411-84) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d2274168393956416&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 13376 INFO (qtp29321600-76) [ ] o.a.s.h.a.CoreAdminOperation Checking request status for : fc22bba1-4816-49dd-a1a1-44827f30c54d2274168390910758 [junit4] 2> 13376 INFO (qtp29321600-76) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d2274168390910758&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 13380 INFO (qtp27709112-69) [ ] o.a.s.h.a.CoreAdminOperation Checking request status for : fc22bba1-4816-49dd-a1a1-44827f30c54d2274168391054431 [junit4] 2> 13380 INFO (qtp27709112-69) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d2274168391054431&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 13384 INFO (OverseerThreadFactory-31-thread-3) [ ] 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> 14016 INFO (qtp20786761-65) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :requeststatus with params requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d&action=REQUESTSTATUS&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 14018 INFO (qtp20786761-65) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=2 [junit4] 2> 14021 INFO (qtp20786761-66) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :deletestatus with params requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d&action=DELETESTATUS&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 14022 INFO (qtp20786761-66) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={requestid=fc22bba1-4816-49dd-a1a1-44827f30c54d&action=DELETESTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 14024 INFO (TEST-TestCollectionStateWatchers.testSimpleCollectionWatch-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.c.c.TestCollectionStateWatchers State changed: DocCollection(testcollection//collections/testcollection/state.json/3)={ [junit4] 2> "replicationFactor":"1", [junit4] 2> "shards":{ [junit4] 2> "shard1":{ [junit4] 2> "range":"80000000-bfffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{"core_node1":{ [junit4] 2> "core":"testcollection_shard1_replica1", [junit4] 2> "base_url":"https://127.0.0.1:36907/solr", [junit4] 2> "node_name":"127.0.0.1:36907_solr", [junit4] 2> "state":"active", [junit4] 2> "leader":"true"}}}, [junit4] 2> "shard2":{ [junit4] 2> "range":"c0000000-ffffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{"core_node2":{ [junit4] 2> "core":"testcollection_shard2_replica1", [junit4] 2> "base_url":"https://127.0.0.1:33057/solr", [junit4] 2> "node_name":"127.0.0.1:33057_solr", [junit4] 2> "state":"active", [junit4] 2> "leader":"true"}}}, [junit4] 2> "shard3":{ [junit4] 2> "range":"0-3fffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{"core_node4":{ [junit4] 2> "core":"testcollection_shard3_replica1", [junit4] 2> "base_url":"https://127.0.0.1:34799/solr", [junit4] 2> "node_name":"127.0.0.1:34799_solr", [junit4] 2> "state":"active", [junit4] 2> "leader":"true"}}}, [junit4] 2> "shard4":{ [junit4] 2> "range":"40000000-7fffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{"core_node3":{ [junit4] 2> "core":"testcollection_shard4_replica1", [junit4] 2> "base_url":"https://127.0.0.1:44743/solr", [junit4] 2> "node_name":"127.0.0.1:44743_solr", [junit4] 2> "state":"active", [junit4] 2> "leader":"true"}}}}, [junit4] 2> "router":{"name":"compositeId"}, [junit4] 2> "maxShardsPerNode":"1", [junit4] 2> "autoAddReplicas":"false"} [junit4] 2> 14024 INFO (watches-33-thread-1) [ ] o.a.s.c.c.TestCollectionStateWatchers State changed: DocCollection(testcollection//collections/testcollection/state.json/3)={ [junit4] 2> "replicationFactor":"1", [junit4] 2> "shards":{ [junit4] 2> "shard1":{ [junit4] 2> "range":"80000000-bfffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{"core_node1":{ [junit4] 2> "core":"testcollection_shard1_replica1", [junit4] 2> "base_url":"https://127.0.0.1:36907/solr", [junit4] 2> "node_name":"127.0.0.1:36907_solr", [junit4] 2> "state":"active", [junit4] 2> "leader":"true"}}}, [junit4] 2> "shard2":{ [junit4] 2> "range":"c0000000-ffffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{"core_node2":{ [junit4] 2> "core":"testcollection_shard2_replica1", [junit4] 2> "base_url":"https://127.0.0.1:33057/solr", [junit4] 2> "node_name":"127.0.0.1:33057_solr", [junit4] 2> "state":"active", [junit4] 2> "leader":"true"}}}, [junit4] 2> "shard3":{ [junit4] 2> "range":"0-3fffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{"core_node4":{ [junit4] 2> "core":"testcollection_shard3_replica1", [junit4] 2> "base_url":"https://127.0.0.1:34799/solr", [junit4] 2> "node_name":"127.0.0.1:34799_solr", [junit4] 2> "state":"active", [junit4] 2> "leader":"true"}}}, [junit4] 2> "shard4":{ [junit4] 2> "range":"40000000-7fffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{"core_node3":{ [junit4] 2> "core":"testcollection_shard4_replica1", [junit4] 2> "base_url":"https://127.0.0.1:44743/solr", [junit4] 2> "node_name":"127.0.0.1:44743_solr", [junit4] 2> "state":"active", [junit4] 2> "leader":"true"}}}}, [junit4] 2> "router":{"name":"compositeId"}, [junit4] 2> "maxShardsPerNode":"1", [junit4] 2> "autoAddReplicas":"false"} [junit4] 2> 14028 INFO (TEST-TestCollectionStateWatchers.testSimpleCollectionWatch-seed#[EFF932D00BBAF2D6]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@191f58e{SSL,[ssl, http/1.1]}{127.0.0.1:0} [junit4] 2> 14029 INFO (TEST-TestCollectionStateWatchers.testSimpleCollectionWatch-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=16315034 [junit4] 2> 14029 INFO (TEST-TestCollectionStateWatchers.testSimpleCollectionWatch-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.node [junit4] 2> 14029 INFO (TEST-TestCollectionStateWatchers.testSimpleCollectionWatch-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.jvm [junit4] 2> 14029 INFO (TEST-TestCollectionStateWatchers.testSimpleCollectionWatch-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.jetty [junit4] 2> 14034 INFO (coreCloseExecutor-65-thread-1) [ ] o.a.s.c.SolrCore [testcollection_shard4_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@2b7bb7 [junit4] 2> 14036 INFO (coreCloseExecutor-65-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.testcollection.shard4.replica1 [junit4] 2> 14040 INFO (zkCallback-34-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (3) [junit4] 2> 14040 WARN (zkCallback-29-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> 14040 INFO (TEST-TestCollectionStateWatchers.testSimpleCollectionWatch-seed#[EFF932D00BBAF2D6]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@1c9f542{/solr,null,UNAVAILABLE} [junit4] 2> 14040 INFO (zkCallback-22-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (3) [junit4] 2> 14040 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (3) [junit4] 2> 14040 INFO (zkCallback-20-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (3) [junit4] 2> 14132 INFO (zkCallback-20-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [3]) [junit4] 2> 14132 INFO (zkCallback-34-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [3]) [junit4] 2> 14132 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [3]) [junit4] 2> 14132 INFO (zkCallback-34-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [3]) [junit4] 2> 14133 INFO (watches-33-thread-1) [ ] o.a.s.c.c.TestCollectionStateWatchers State changed: DocCollection(testcollection//collections/testcollection/state.json/4)={ [junit4] 2> "replicationFactor":"1", [junit4] 2> "shards":{ [junit4] 2> "shard1":{ [junit4] 2> "range":"80000000-bfffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{"core_node1":{ [junit4] 2> "core":"testcollection_shard1_replica1", [junit4] 2> "base_url":"https://127.0.0.1:36907/solr", [junit4] 2> "node_name":"127.0.0.1:36907_solr", [junit4] 2> "state":"active", [junit4] 2> "leader":"true"}}}, [junit4] 2> "shard2":{ [junit4] 2> "range":"c0000000-ffffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{"core_node2":{ [junit4] 2> "core":"testcollection_shard2_replica1", [junit4] 2> "base_url":"https://127.0.0.1:33057/solr", [junit4] 2> "node_name":"127.0.0.1:33057_solr", [junit4] 2> "state":"active", [junit4] 2> "leader":"true"}}}, [junit4] 2> "shard3":{ [junit4] 2> "range":"0-3fffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{"core_node4":{ [junit4] 2> "core":"testcollection_shard3_replica1", [junit4] 2> "base_url":"https://127.0.0.1:34799/solr", [junit4] 2> "node_name":"127.0.0.1:34799_solr", [junit4] 2> "state":"active", [junit4] 2> "leader":"true"}}}, [junit4] 2> "shard4":{ [junit4] 2> "range":"40000000-7fffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{"core_node3":{ [junit4] 2> "core":"testcollection_shard4_replica1", [junit4] 2> "base_url":"https://127.0.0.1:44743/solr", [junit4] 2> "node_name":"127.0.0.1:44743_solr", [junit4] 2> "state":"down", [junit4] 2> "leader":"true"}}}}, [junit4] 2> "router":{"name":"compositeId"}, [junit4] 2> "maxShardsPerNode":"1", [junit4] 2> "autoAddReplicas":"false"} [junit4] 2> 14132 INFO (zkCallback-22-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [3]) [junit4] 2> 14136 INFO (TEST-TestCollectionStateWatchers.testSimpleCollectionWatch-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testSimpleCollectionWatch [junit4] 2> 14151 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testWatchesWorkForStateFormat1 [junit4] 2> 14156 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 14157 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@1927ef7{/solr,null,AVAILABLE} [junit4] 2> 14159 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@1b1d59b{SSL,[ssl, http/1.1]}{127.0.0.1:41937} [junit4] 2> 14159 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.e.j.s.Server Started @15999ms [junit4] 2> 14159 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=41937} [junit4] 2> 14159 ERROR (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 14159 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.6.1 [junit4] 2> 14159 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 14159 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 14159 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-08-21T01:00:48.293716Z [junit4] 2> 14203 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 14219 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true [junit4] 2> 14225 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:45197/solr [junit4] 2> 14270 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3) [junit4] 2> 14272 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 14273 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41937_solr [junit4] 2> 14274 INFO (zkCallback-20-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 14274 INFO (zkCallback-34-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 14274 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 14274 INFO (zkCallback-41-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 14275 INFO (zkCallback-22-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 14388 INFO (TEST-TestCollectionStateWatchers.testWatchesWorkForStateFormat1-seed#[EFF932D00BBAF2D6]) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node5/. [junit4] 2> 14441 INFO (qtp20786761-60) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params async=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb&replicationFactor=1&collection.configName=config&name=stateformat1&action=CREATE&numShards=1&stateFormat=1&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 14442 INFO (qtp20786761-60) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={async=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb&replicationFactor=1&collection.configName=config&name=stateformat1&action=CREATE&numShards=1&stateFormat=1&wt=javabin&version=2} status=0 QTime=2 [junit4] 2> 14446 INFO (qtp20786761-64) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :requeststatus with params requestid=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb&action=REQUESTSTATUS&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 14447 INFO (qtp20786761-64) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={requestid=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 14451 INFO (OverseerThreadFactory-31-thread-4) [ ] o.a.s.c.CreateCollectionCmd Create collection stateformat1 [junit4] 2> 14452 INFO (OverseerCollectionConfigSetProcessor-98518777170755594-127.0.0.1:33057_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> 14668 INFO (qtp20786761-59) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={async=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb2274171793785010&qt=/admin/cores&collection.configName=config&newCollection=true&name=stateformat1_shard1_replica1&action=CREATE&numShards=1&collection=stateformat1&shard=shard1&wt=javabin&version=2} status=0 QTime=9 [junit4] 2> 14669 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.h.a.CoreAdminOperation core create command async=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb2274171793785010&qt=/admin/cores&collection.configName=config&newCollection=true&name=stateformat1_shard1_replica1&action=CREATE&numShards=1&collection=stateformat1&shard=shard1&wt=javabin&version=2 [junit4] 2> 14681 INFO (qtp20786761-66) [ ] o.a.s.h.a.CoreAdminOperation Checking request status for : f77b2219-c7ce-4960-b58a-6e6aebd9ecdb2274171793785010 [junit4] 2> 14681 INFO (qtp20786761-66) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&requestid=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb2274171793785010&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 15450 INFO (qtp20786761-65) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :requeststatus with params requestid=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb&action=REQUESTSTATUS&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 15451 INFO (qtp20786761-65) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={requestid=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 15680 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.1 [junit4] 2> 15689 INFO (qtp20786761-60) [ ] o.a.s.h.a.CoreAdminOperation Checking request status for : f77b2219-c7ce-4960-b58a-6e6aebd9ecdb2274171793785010 [junit4] 2> 15689 INFO (qtp20786761-60) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&requestid=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb2274171793785010&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 15692 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.s.IndexSchema [stateformat1_shard1_replica1] Schema name=test [junit4] 2> 15759 WARN (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.s.IndexSchema Field lowerfilt1and2 is not multivalued and destination for multiple copyFields (2) [junit4] 2> 15759 WARN (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.s.IndexSchema Field text is not multivalued and destination for multiple copyFields (3) [junit4] 2> 15759 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id [junit4] 2> 15759 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.c.CoreContainer Creating SolrCore 'stateformat1_shard1_replica1' using configuration from collection stateformat1, trusted=true [junit4] 2> 15759 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 15760 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.c.SolrCore [[stateformat1_shard1_replica1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node1/stateformat1_shard1_replica1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001/tempDir-001/node1/./stateformat1_shard1_replica1/data/] [junit4] 2> 15799 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 15799 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 15800 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 15800 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 15801 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@ec134f[stateformat1_shard1_replica1] main] [junit4] 2> 15802 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/config [junit4] 2> 15803 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/config [junit4] 2> 15803 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 15806 INFO (searcherExecutor-73-thread-1) [ ] o.a.s.c.SolrCore [stateformat1_shard1_replica1] Registered new searcher Searcher@ec134f[stateformat1_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 15809 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1576300445636231168 [junit4] 2> 15824 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 15824 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 15824 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:36907/solr/stateformat1_shard1_replica1/ [junit4] 2> 15824 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 15824 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.c.SyncStrategy https://127.0.0.1:36907/solr/stateformat1_shard1_replica1/ has no replicas [junit4] 2> 15824 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 15866 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:36907/solr/stateformat1_shard1_replica1/ shard1 [junit4] 2> 16017 INFO (parallelCoreAdminExecutor-37-thread-2) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 16459 INFO (qtp20786761-64) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :requeststatus with params requestid=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb&action=REQUESTSTATUS&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 16470 INFO (qtp20786761-64) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={requestid=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=11 [junit4] 2> 16692 INFO (qtp20786761-60) [ ] o.a.s.h.a.CoreAdminOperation Checking request status for : f77b2219-c7ce-4960-b58a-6e6aebd9ecdb2274171793785010 [junit4] 2> 16692 INFO (qtp20786761-60) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&requestid=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb2274171793785010&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 16695 INFO (OverseerThreadFactory-31-thread-4) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000005 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 17473 INFO (qtp20786761-66) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :requeststatus with params requestid=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb&action=REQUESTSTATUS&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 17474 INFO (qtp20786761-66) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={requestid=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=1 [junit4] 2> 17478 INFO (qtp20786761-59) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :deletestatus with params requestid=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb&action=DELETESTATUS&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 17478 INFO (qtp20786761-59) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={requestid=f77b2219-c7ce-4960-b58a-6e6aebd9ecdb&action=DELETESTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 17482 INFO (qtp20786761-64) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :migratestateformat with params async=4efd6337-5035-47b9-8bad-0da03a169176&action=MIGRATESTATEFORMAT&collection=stateformat1&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 17483 INFO (qtp20786761-64) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={async=4efd6337-5035-47b9-8bad-0da03a169176&action=MIGRATESTATEFORMAT&collection=stateformat1&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 17484 INFO (OverseerCollectionConfigSetProcessor-98518777170755594-127.0.0.1:33057_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000005 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 17485 INFO (qtp20786761-60) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :requeststatus with params requestid=4efd6337-5035-47b9-8bad-0da03a169176&action=REQUESTSTATUS&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 17486 INFO (qtp20786761-60) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={requestid=4efd6337-5035-47b9-8bad-0da03a169176&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 17587 INFO (zkCallback-34-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeCreated path:/collections/stateformat1/state.json] for collection [stateformat1] has occurred - updating... (live nodes size: [4]) [junit4] 2> 17587 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeCreated path:/collections/stateformat1/state.json] for collection [stateformat1] has occurred - updating... (live nodes size: [4]) [junit4] 2> 17587 INFO (zkCallback-34-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeCreated path:/collections/stateformat1/state.json] for collection [stateformat1] has occurred - updating... (live nodes size: [4]) [junit4] 2> 17688 INFO (OverseerThreadFactory-31-thread-5) [ ] 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> 18489 INFO (qtp20786761-66) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :requeststatus with params requestid=4efd6337-5035-47b9-8bad-0da03a169176&action=REQUESTSTATUS&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 18489 INFO (qtp20786761-66) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={requestid=4efd6337-5035-47b9-8bad-0da03a169176&action=REQUESTSTATUS&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 18492 INFO (qtp20786761-59) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :deletestatus with params requestid=4efd6337-5035-47b9-8bad-0da03a169176 [...truncated too long message...] state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/stateformat1/state.json] for collection [stateformat1] has occurred - updating... (live nodes size: [4]) [junit4] 2> 63503 INFO (zkCallback-51-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 63504 INFO (zkCallback-57-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 63504 INFO (zkCallback-22-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testcollection/state.json] for collection [testcollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 63506 INFO (coreCloseExecutor-166-thread-3) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.falsepredicate.shard4.replica1 [junit4] 2> 63513 INFO (jetty-closer-5-thread-1) [ ] o.a.s.c.Overseer Overseer (id=98518777170755594-127.0.0.1:33057_solr-n_0000000000) closing [junit4] 2> 63513 INFO (OverseerStateUpdate-98518777170755594-127.0.0.1:33057_solr-n_0000000000) [ ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:33057_solr [junit4] 2> 63514 INFO (zkCallback-51-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/falsepredicate/state.json] for collection [falsepredicate] has occurred - updating... (live nodes size: [4]) [junit4] 2> 63514 INFO (zkCallback-41-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/falsepredicate/state.json] for collection [falsepredicate] has occurred - updating... (live nodes size: [4]) [junit4] 2> 63514 WARN (zkCallback-22-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> 63515 INFO (zkCallback-22-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/falsepredicate/state.json] for collection [falsepredicate] has occurred - updating... (live nodes size: [4]) [junit4] 2> 63515 WARN (zkCallback-22-thread-2) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /collections/falsepredicate/state.json] [junit4] 2> 63516 INFO (zkCallback-57-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/falsepredicate/state.json] for collection [falsepredicate] has occurred - updating... (live nodes size: [4]) [junit4] 2> 63516 WARN (zkCallback-57-thread-2) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /collections/falsepredicate/state.json] [junit4] 2> 63516 WARN (zkCallback-57-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> 63516 INFO (jetty-closer-5-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@4a1f0b{/solr,null,UNAVAILABLE} [junit4] 2> 63517 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception [junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x15e024e4cf8000a, likely client has closed socket [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239) [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203) [junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844) [junit4] 2> 63518 INFO (jetty-closer-5-thread-4) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@fc9f70{/solr,null,UNAVAILABLE} [junit4] 2> 63518 INFO (zkCallback-51-thread-3) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (2) [junit4] 2> 63518 INFO (zkCallback-41-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (2) [junit4] 2> 63518 INFO (zkCallback-41-thread-3) [ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:41937_solr [junit4] 2> 63521 INFO (coreCloseExecutor-166-thread-5) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.testcollection.shard1.replica1 [junit4] 2> 63521 INFO (coreCloseExecutor-167-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.falsepredicate.shard1.replica1 [junit4] 2> 63522 INFO (coreCloseExecutor-166-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.delayed.shard1.replica1 [junit4] 2> 63530 INFO (coreCloseExecutor-166-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.stateformat1.shard1.replica1 [junit4] 2> 63530 INFO (coreCloseExecutor-166-thread-4) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.waitforstate.shard1.replica1 [junit4] 2> 63534 WARN (zkCallback-41-thread-3) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 63534 INFO (zkCallback-51-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1) [junit4] 2> 63535 WARN (zkCallback-51-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> 63535 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception [junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x15e024e4cf8001a, likely client has closed socket [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239) [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203) [junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844) [junit4] 2> 63534 INFO (zkCallback-51-thread-3) [ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:40715_solr [junit4] 2> 63535 INFO (jetty-closer-5-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@1927ef7{/solr,null,UNAVAILABLE} [junit4] 2> 63538 INFO (jetty-closer-5-thread-3) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@17c23ec{/solr,null,UNAVAILABLE} [junit4] 2> 63539 ERROR (SUITE-TestCollectionStateWatchers-seed#[EFF932D00BBAF2D6]-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> 63540 INFO (SUITE-TestCollectionStateWatchers-seed#[EFF932D00BBAF2D6]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:45197 45197 [junit4] 2> 68959 INFO (Thread-11) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:45197 45197 [junit4] 2> 68960 WARN (Thread-11) [ ] o.a.s.c.ZkTestServer Watch limit violations: [junit4] 2> Maximum concurrent create/delete watches above limit: [junit4] 2> [junit4] 2> 8 /solr/aliases.json [junit4] 2> 8 /solr/configs/config [junit4] 2> 7 /solr/security.json [junit4] 2> 3 /solr/collections/stateformat1/state.json [junit4] 2> [junit4] 2> Maximum concurrent data watches above limit: [junit4] 2> [junit4] 2> 12 /solr/collections/waitforstate/state.json [junit4] 2> 8 /solr/clusterprops.json [junit4] 2> 8 /solr/clusterstate.json [junit4] 2> 8 /solr/collections/testcollection/state.json [junit4] 2> 7 /solr/collections/falsepredicate/state.json [junit4] 2> 3 /solr/overseer_elect/election/98518777170755594-127.0.0.1:33057_solr-n_0000000000 [junit4] 2> 3 /solr/collections/stateformat1/state.json [junit4] 2> 2 /solr/overseer_elect/election/98518777170755593-127.0.0.1:34799_solr-n_0000000002 [junit4] 2> 2 /solr/collections/currentstate/state.json [junit4] 2> 2 /solr/collections/delayed/state.json [junit4] 2> 2 /solr/collections/tobedeleted/state.json [junit4] 2> [junit4] 2> Maximum concurrent children watches above limit: [junit4] 2> [junit4] 2> 8 /solr/collections [junit4] 2> 5 /solr/live_nodes [junit4] 2> [junit4] 2> 68960 INFO (SUITE-TestCollectionStateWatchers-seed#[EFF932D00BBAF2D6]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore [junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/workspace/Lucene-Solr-6.6-Linux/solr/build/solr-solrj/test/J2/temp/solr.common.cloud.TestCollectionStateWatchers_EFF932D00BBAF2D6-001 [junit4] 2> NOTE: test params are: codec=Asserting(Lucene62): {}, docValues:{}, maxPointsInLeafNode=51, maxMBSortInHeap=6.142355941684421, sim=RandomSimilarity(queryNorm=true,coord=no): {}, locale=pt-ST, timezone=Australia/North [junit4] 2> NOTE: Linux 4.10.0-27-generic i386/Oracle Corporation 9 (32-bit)/cpus=8,threads=1,free=119908488,total=249823232 [junit4] 2> NOTE: All tests run in this JVM: [TestConfigSetAdminRequest, TestBatchUpdate, CompoundEvaluatorTest, TestCollectionStateWatchers] [junit4] Completed [63/130 (1!)] on J2 in 63.64s, 9 tests, 1 failure <<< FAILURES! [...truncated 35771 lines...]
--------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org