https://issues.apache.org/jira/browse/SOLR-6386
: Date: Sat, 16 Aug 2014 17:25:45 +0000 (UTC) : From: Policeman Jenkins Server <[email protected]> : Reply-To: [email protected] : To: [email protected] : Subject: [JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.7.0_65) - Build # 11037 : - Still Failing! : : Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/11037/ : Java: 32bit/jdk1.7.0_65 -server -XX:+UseConcMarkSweepGC : : 2 tests failed. : FAILED: org.apache.solr.TestDistributedSearch.testDistribSearch : : Error Message: : .facet_counts.facet_fields.a_n_tdt.1970-01-01T00:00:00Z!=2010-04-20T11:00:00Z (unordered or missing) : : Stack Trace: : junit.framework.AssertionFailedError: .facet_counts.facet_fields.a_n_tdt.1970-01-01T00:00:00Z!=2010-04-20T11:00:00Z (unordered or missing) : at __randomizedtesting.SeedInfo.seed([5547E29057A024AB:D4A16C8820FF4497]:0) : at junit.framework.Assert.fail(Assert.java:50) : at org.apache.solr.BaseDistributedSearchTestCase.compareSolrResponses(BaseDistributedSearchTestCase.java:842) : at org.apache.solr.BaseDistributedSearchTestCase.compareResponses(BaseDistributedSearchTestCase.java:861) : at org.apache.solr.BaseDistributedSearchTestCase.query(BaseDistributedSearchTestCase.java:562) : at org.apache.solr.BaseDistributedSearchTestCase.query(BaseDistributedSearchTestCase.java:542) : at org.apache.solr.BaseDistributedSearchTestCase.query(BaseDistributedSearchTestCase.java:521) : at org.apache.solr.TestDistributedSearch.doTest(TestDistributedSearch.java:180) : at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:875) : at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) : at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) : at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) : at java.lang.reflect.Method.invoke(Method.java:606) : at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1618) : at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:827) : at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863) : at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:877) : at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53) : at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50) : at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46) : at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55) : at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49) : at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65) : at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48) : at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:365) : at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:798) : at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:458) : at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:836) : at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:738) : at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:772) : at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:783) : at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53) : at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46) : at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42) : at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55) : at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39) : at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39) : at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43) : at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48) : at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65) : at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55) : at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:365) : at java.lang.Thread.run(Thread.java:745) : : : FAILED: org.apache.solr.cloud.OverseerTest.testOverseerFailure : : Error Message: : KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election : : Stack Trace: : org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election : at __randomizedtesting.SeedInfo.seed([5547E29057A024AB:514F6D634505CB8A]:0) : at org.apache.zookeeper.KeeperException.create(KeeperException.java:111) : at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) : at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1472) : at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:290) : at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287) : at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) : at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287) : at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94) : at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:155) : at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:314) : at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:221) : at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:157) : at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:662) : at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) : at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) : at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) : at java.lang.reflect.Method.invoke(Method.java:606) : at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1618) : at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:827) : at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863) : at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:877) : at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53) : at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50) : at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46) : at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55) : at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49) : at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65) : at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48) : at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:365) : at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:798) : at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:458) : at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:836) : at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:738) : at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:772) : at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:783) : at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53) : at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46) : at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42) : at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55) : at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39) : at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39) : at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43) : at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48) : at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65) : at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55) : at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:365) : at java.lang.Thread.run(Thread.java:745) : : : : : Build Log: : [...truncated 11366 lines...] : [junit4] Suite: org.apache.solr.cloud.OverseerTest : [junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./temp/solr.cloud.OverseerTest-5547E29057A024AB-001/init-core-data-001 : [junit4] 2> 1604704 T4268 oas.SolrTestCaseJ4.buildSSLConfig Randomized ssl (false) and clientAuth (false) : [junit4] 2> 1604704 T4268 oas.SolrTestCaseJ4.initCore ####initCore : [junit4] 2> 1604704 T4268 oas.SolrTestCaseJ4.initCore ####initCore end : [junit4] 2> 1604707 T4268 oas.SolrTestCaseJ4.setUp ###Starting testPlaceholders : [junit4] 2> 1604708 T4268 oasc.ZkTestServer.run STARTING ZK TEST SERVER : [junit4] 1> client port:0.0.0.0/0.0.0.0:0 : [junit4] 2> 1604708 T4269 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server : [junit4] 2> 1604816 T4268 oasc.ZkTestServer.run start zk server on port:46180 : [junit4] 2> 1604817 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1604820 T4275 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@cacff9 name:ZooKeeperConnection Watcher:127.0.0.1:46180/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1604820 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1604821 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1604822 T4277 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a5eef5 name:ZooKeeperConnection Watcher:127.0.0.1:46180 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1604822 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1604824 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1604825 T4279 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9022ad name:ZooKeeperConnection Watcher:127.0.0.1:46180 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1604825 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1604825 T4268 oascc.SolrZkClient.makePath makePath: /solr : [junit4] 2> 1604828 T4268 oascc.SolrZkClient.makePath makePath: /live_nodes : [junit4] 2> 1604830 T4268 oascc.SolrZkClient.makePath makePath: /clusterstate.json : [junit4] 2> 1604831 T4268 oascc.SolrZkClient.makePath makePath: /aliases.json : [junit4] 2> 1604832 T4268 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... : [junit4] 2> 1604839 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1604840 T4281 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ada0d1 name:ZooKeeperConnection Watcher:127.0.0.1:46180/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1604840 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1604841 T4268 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... : [junit4] 2> 1604842 T4268 oascc.SolrZkClient.makePath makePath: /live_nodes/node1 : [junit4] 2> 1604851 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1604852 T4285 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e7e1e7 name:ZooKeeperConnection Watcher:127.0.0.1:46180/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1604852 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1604853 T4268 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false : [junit4] 2> 1604854 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect : [junit4] 2> 1604855 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect/election : [junit4] 2> 1604857 T4268 oasc.Overseer.close Overseer (id=null) closing : [junit4] 2> 1604858 T4268 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:46180_solr : [junit4] 2> 1604858 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader : [junit4] 2> 1604860 T4268 oasc.Overseer.start Overseer (id=92288351107088388-127.0.0.1:46180_solr-n_0000000000) starting : [junit4] 2> 1604861 T4268 oascc.SolrZkClient.makePath makePath: /overseer/queue : [junit4] 2> 1604862 T4268 oascc.SolrZkClient.makePath makePath: /overseer/queue-work : [junit4] 2> 1604864 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure : [junit4] 2> 1604866 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running : [junit4] 2> 1604868 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed : [junit4] 2> 1604870 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work : [junit4] 2> 1604873 T4268 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000 : [junit4] 2> 1604873 T4287 oasc.OverseerCollectionProcessor.run Process current queue of collection creations : [junit4] 2> 1604874 T4286 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue : [junit4] 2> 1604876 T4286 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=12 message={ : [junit4] 2> "operation":"state", : [junit4] 2> "state":"recovering", : [junit4] 2> "node_name":"node1", : [junit4] 2> "core":"core1", : [junit4] 2> "core_node_name":"node1", : [junit4] 2> "collection":"collection1", : [junit4] 2> "numShards":"12", : [junit4] 2> "base_url":"http://node1/solr/"} : [junit4] 2> 1604876 T4286 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3, shard4, shard5, shard6, shard7, shard8, shard9, shard10, shard11, shard12] : [junit4] 2> 1604877 T4286 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1 : [junit4] 2> 1604878 T4289 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1604879 T4282 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1604879 T4283 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1605376 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election : [junit4] 2> 1605381 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1 : [junit4] 2> 1605385 T4289 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1605389 T4268 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:46180 46180 : [junit4] 2> 1605947 T4269 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:46180 46180 : [junit4] 2> 1605949 T4268 oas.SolrTestCaseJ4.tearDown ###Ending testPlaceholders : [junit4] 2> 1605949 T4268 oasc.Overseer.close Overseer (id=92288351107088388-127.0.0.1:46180_solr-n_0000000000) closing : [junit4] 2> 1605950 T4286 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:46180_solr : [junit4] 2> 1605951 T4290 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127) : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) : [junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:321) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:293) : [junit4] 2> : [junit4] 2> 1605955 T4268 oas.SolrTestCaseJ4.setUp ###Starting testShardAssignment : [junit4] 2> 1605955 T4268 oasc.ZkTestServer.run STARTING ZK TEST SERVER : [junit4] 1> client port:0.0.0.0/0.0.0.0:0 : [junit4] 2> 1605956 T4291 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server : [junit4] 2> 1606056 T4268 oasc.ZkTestServer.run start zk server on port:51454 : [junit4] 2> 1606057 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1606059 T4297 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5c931c name:ZooKeeperConnection Watcher:127.0.0.1:51454 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1606059 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1606061 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1606062 T4299 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@cca746 name:ZooKeeperConnection Watcher:127.0.0.1:51454 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1606062 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1606063 T4268 oascc.SolrZkClient.makePath makePath: /solr : [junit4] 2> 1606065 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1606066 T4301 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@315e42 name:ZooKeeperConnection Watcher:127.0.0.1:51454/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1606066 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1606067 T4268 oascc.SolrZkClient.makePath makePath: /live_nodes : [junit4] 2> 1606068 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1606069 T4303 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@775b26 name:ZooKeeperConnection Watcher:127.0.0.1:51454/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1606069 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1606069 T4268 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false : [junit4] 2> 1606070 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect : [junit4] 2> 1606072 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect/election : [junit4] 2> 1606073 T4268 oasc.Overseer.close Overseer (id=null) closing : [junit4] 2> 1606074 T4268 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:51454_solr : [junit4] 2> 1606075 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader : [junit4] 2> 1606076 T4268 oasc.Overseer.start Overseer (id=92288351188877315-127.0.0.1:51454_solr-n_0000000000) starting : [junit4] 2> 1606077 T4268 oascc.SolrZkClient.makePath makePath: /overseer/queue : [junit4] 2> 1606079 T4268 oascc.SolrZkClient.makePath makePath: /overseer/queue-work : [junit4] 2> 1606080 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure : [junit4] 2> 1606082 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running : [junit4] 2> 1606084 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed : [junit4] 2> 1606086 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work : [junit4] 2> 1606089 T4268 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000 : [junit4] 2> 1606089 T4305 oasc.OverseerCollectionProcessor.run Process current queue of collection creations : [junit4] 2> 1606090 T4268 oascc.SolrZkClient.makePath makePath: /clusterstate.json : [junit4] 2> 1606090 T4304 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue : [junit4] 2> 1606092 T4268 oascc.SolrZkClient.makePath makePath: /aliases.json : [junit4] 2> 1606093 T4268 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... : [junit4] 2> 1606094 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1606096 T4308 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1e910c3 name:ZooKeeperConnection Watcher:127.0.0.1:51454/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1606096 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1606097 T4268 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... : [junit4] 2> 1606099 T4268 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1 : [junit4] 2> 1606104 T4311 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1606106 T4304 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={ : [junit4] 2> "operation":"state", : [junit4] 2> "state":"active", : [junit4] 2> "node_name":"127.0.0.1", : [junit4] 2> "core":"core1", : [junit4] 2> "core_node_name":"node1", : [junit4] 2> "collection":"collection1", : [junit4] 2> "numShards":"3", : [junit4] 2> "base_url":"http://127.0.0.1/solr/"} : [junit4] 2> 1606106 T4304 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3] : [junit4] 2> 1606107 T4304 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1 : [junit4] 2> 1606109 T4309 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1606109 T4310 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1606603 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election : [junit4] 2> 1606608 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1 : [junit4] 2> 1606611 T4311 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1606614 T4304 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={ : [junit4] 2> "operation":"state", : [junit4] 2> "state":"active", : [junit4] 2> "node_name":"127.0.0.1", : [junit4] 2> "core":"core2", : [junit4] 2> "core_node_name":"node2", : [junit4] 2> "collection":"collection1", : [junit4] 2> "numShards":"3", : [junit4] 2> "base_url":"http://127.0.0.1/solr/"} : [junit4] 2> 1606614 T4304 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3 : [junit4] 2> 1606614 T4304 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3 : [junit4] 2> 1606615 T4311 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1606616 T4309 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1606616 T4310 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1607112 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election : [junit4] 2> 1607117 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3 : [junit4] 2> 1607121 T4311 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1607124 T4304 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={ : [junit4] 2> "operation":"state", : [junit4] 2> "state":"active", : [junit4] 2> "node_name":"127.0.0.1", : [junit4] 2> "core":"core3", : [junit4] 2> "core_node_name":"node3", : [junit4] 2> "collection":"collection1", : [junit4] 2> "numShards":"3", : [junit4] 2> "base_url":"http://127.0.0.1/solr/"} : [junit4] 2> 1607124 T4304 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3 : [junit4] 2> 1607125 T4304 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2 : [junit4] 2> 1607126 T4311 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1607127 T4309 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1607127 T4310 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1607622 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election : [junit4] 2> 1607627 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2 : [junit4] 2> 1607630 T4311 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1607633 T4304 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={ : [junit4] 2> "operation":"state", : [junit4] 2> "state":"active", : [junit4] 2> "node_name":"127.0.0.1", : [junit4] 2> "core":"core4", : [junit4] 2> "core_node_name":"node4", : [junit4] 2> "collection":"collection1", : [junit4] 2> "numShards":"3", : [junit4] 2> "base_url":"http://127.0.0.1/solr/"} : [junit4] 2> 1607633 T4304 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3 : [junit4] 2> 1607633 T4304 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1 : [junit4] 2> 1607635 T4311 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1607636 T4310 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1607636 T4309 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1608131 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election : [junit4] 2> 1608137 T4311 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1608138 T4304 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={ : [junit4] 2> "operation":"state", : [junit4] 2> "state":"active", : [junit4] 2> "node_name":"127.0.0.1", : [junit4] 2> "core":"core5", : [junit4] 2> "core_node_name":"node5", : [junit4] 2> "collection":"collection1", : [junit4] 2> "numShards":"3", : [junit4] 2> "base_url":"http://127.0.0.1/solr/"} : [junit4] 2> 1608138 T4304 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3 : [junit4] 2> 1608138 T4304 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3 : [junit4] 2> 1608241 T4310 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1608241 T4309 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1608637 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election : [junit4] 2> 1608642 T4311 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1608644 T4304 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={ : [junit4] 2> "operation":"state", : [junit4] 2> "state":"active", : [junit4] 2> "node_name":"127.0.0.1", : [junit4] 2> "core":"core6", : [junit4] 2> "core_node_name":"node6", : [junit4] 2> "collection":"collection1", : [junit4] 2> "numShards":"3", : [junit4] 2> "base_url":"http://127.0.0.1/solr/"} : [junit4] 2> 1608644 T4304 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3 : [junit4] 2> 1608644 T4304 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2 : [junit4] 2> 1608746 T4310 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1608746 T4309 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1609142 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election : [junit4] 2> 1609148 T4292 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x147dfc435850004, likely client has closed socket : [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228) : [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208) : [junit4] 2> at java.lang.Thread.run(Thread.java:745) : [junit4] 2> : [junit4] 2> 1609148 T4312 oasc.LeaderElector$ElectionWatcher.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard3/election : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127) : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) : [junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1472) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:290) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287) : [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287) : [junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94) : [junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55) : [junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209) : [junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) : [junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262) : [junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) : [junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) : [junit4] 2> at java.lang.Thread.run(Thread.java:745) : [junit4] 2> : [junit4] 2> 1609148 T4308 oaz.ClientCnxn$EventThread.processEvent ERROR Error while calling watcher java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@1a713ca rejected from java.util.concurrent.ThreadPoolExecutor@466e9[Shutting down, pool size = 2, active threads = 2, queued tasks = 0, completed tasks = 8] : [junit4] 2> at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2048) : [junit4] 2> at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:821) : [junit4] 2> at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1372) : [junit4] 2> at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:110) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.process(SolrZkClient.java:206) : [junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:522) : [junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498) : [junit4] 2> : [junit4] 2> 1610648 T4310 oasc.LeaderElector$ElectionWatcher.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127) : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) : [junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1472) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:290) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287) : [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287) : [junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94) : [junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55) : [junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209) : [junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) : [junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262) : [junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) : [junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) : [junit4] 2> at java.lang.Thread.run(Thread.java:745) : [junit4] 2> : [junit4] 2> 1610650 T4268 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:51454 51454 : [junit4] 2> 1611085 T4291 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:51454 51454 : [junit4] 2> 1611086 T4268 oas.SolrTestCaseJ4.tearDown ###Ending testShardAssignment : [junit4] 2> 1611087 T4268 oasc.Overseer.close Overseer (id=92288351188877315-127.0.0.1:51454_solr-n_0000000000) closing : [junit4] 2> 1611087 T4304 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:51454_solr : [junit4] 2> 1611088 T4313 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127) : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) : [junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:321) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:293) : [junit4] 2> : [junit4] 2> 1611093 T4268 oas.SolrTestCaseJ4.setUp ###Starting testReplay : [junit4] 2> 1611093 T4268 oasc.ZkTestServer.run STARTING ZK TEST SERVER : [junit4] 1> client port:0.0.0.0/0.0.0.0:0 : [junit4] 2> 1611094 T4314 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server : [junit4] 2> 1611194 T4268 oasc.ZkTestServer.run start zk server on port:50873 : [junit4] 2> 1611200 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1611201 T4320 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f4feab name:ZooKeeperConnection Watcher:127.0.0.1:50873/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1611202 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1611206 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1611207 T4322 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c8ac4b name:ZooKeeperConnection Watcher:127.0.0.1:50873 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1611207 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1611209 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1611210 T4324 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16d2b7d name:ZooKeeperConnection Watcher:127.0.0.1:50873 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1611211 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1611211 T4268 oascc.SolrZkClient.makePath makePath: /solr : [junit4] 2> 1611213 T4268 oascc.SolrZkClient.makePath makePath: /live_nodes : [junit4] 2> 1611215 T4268 oascc.SolrZkClient.makePath makePath: /clusterstate.json : [junit4] 2> 1611216 T4268 oascc.SolrZkClient.makePath makePath: /aliases.json : [junit4] 2> 1611218 T4268 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... : [junit4] 2> 1611220 T4268 oascc.SolrZkClient.makePath makePath: /overseer/queue-work : [junit4] 2> 1611223 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1611223 T4326 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1ebe264 name:ZooKeeperConnection Watcher:127.0.0.1:50873/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1611224 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1611225 T4268 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false : [junit4] 2> 1611225 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect : [junit4] 2> 1611227 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect/election : [junit4] 2> 1611228 T4268 oasc.Overseer.close Overseer (id=null) closing : [junit4] 2> 1611230 T4268 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:50873_solr : [junit4] 2> 1611230 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader : [junit4] 2> 1611231 T4268 oasc.Overseer.start Overseer (id=92288351525666819-127.0.0.1:50873_solr-n_0000000000) starting : [junit4] 2> 1611233 T4268 oascc.SolrZkClient.makePath makePath: /overseer/queue : [junit4] 2> 1611236 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure : [junit4] 2> 1611238 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running : [junit4] 2> 1611240 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed : [junit4] 2> 1611243 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work : [junit4] 2> 1611247 T4268 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000 : [junit4] 2> 1611248 T4328 oasc.OverseerCollectionProcessor.run Process current queue of collection creations : [junit4] 2> 1611252 T4327 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue. : [junit4] 2> 1611252 T4327 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={ : [junit4] 2> "operation":"state", : [junit4] 2> "base_url":"http://127.0.0.1/solr";, : [junit4] 2> "node_name":"node1", : [junit4] 2> "shard":"s1", : [junit4] 2> "collection":"collection1", : [junit4] 2> "core":"core1", : [junit4] 2> "roles":"", : [junit4] 2> "state":"recovering"} : [junit4] 2> 1611253 T4330 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0) : [junit4] 2> 1611255 T4327 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={ : [junit4] 2> "operation":"state", : [junit4] 2> "base_url":"http://127.0.0.1/solr";, : [junit4] 2> "node_name":"node1", : [junit4] 2> "shard":"s1", : [junit4] 2> "collection":"collection1", : [junit4] 2> "core":"core2", : [junit4] 2> "roles":"", : [junit4] 2> "state":"recovering"} : [junit4] 2> 1611256 T4330 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0) : [junit4] 2> 1611258 T4327 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue : [junit4] 2> 1611260 T4327 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={ : [junit4] 2> "operation":"state", : [junit4] 2> "base_url":"http://127.0.0.1/solr";, : [junit4] 2> "node_name":"node1", : [junit4] 2> "shard":"s1", : [junit4] 2> "collection":"collection1", : [junit4] 2> "core":"core3", : [junit4] 2> "roles":"", : [junit4] 2> "state":"recovering"} : [junit4] 2> 1611262 T4331 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1611263 T4330 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0) : [junit4] 2> 1611368 T4268 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:50873 50873 : [junit4] 2> 1611818 T4314 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:50873 50873 : [junit4] 2> 1611820 T4268 oas.SolrTestCaseJ4.tearDown ###Ending testReplay : [junit4] 2> 1611820 T4268 oasc.Overseer.close Overseer (id=92288351525666819-127.0.0.1:50873_solr-n_0000000000) closing : [junit4] 2> 1611821 T4327 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:50873_solr : [junit4] 2> 1611823 T4332 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127) : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) : [junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:321) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:293) : [junit4] 2> : [junit4] 2> 1611829 T4268 oas.SolrTestCaseJ4.setUp ###Starting testOverseerFailure : [junit4] 2> 1611829 T4268 oasc.ZkTestServer.run STARTING ZK TEST SERVER : [junit4] 1> client port:0.0.0.0/0.0.0.0:0 : [junit4] 2> 1611830 T4333 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server : [junit4] 2> 1611930 T4268 oasc.ZkTestServer.run start zk server on port:40099 : [junit4] 2> 1611931 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1611933 T4339 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ff693a name:ZooKeeperConnection Watcher:127.0.0.1:40099 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1611933 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1611935 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1611936 T4341 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12fac1c name:ZooKeeperConnection Watcher:127.0.0.1:40099 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1611936 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1611936 T4268 oascc.SolrZkClient.makePath makePath: /solr : [junit4] 2> 1611939 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1611940 T4343 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1df2969 name:ZooKeeperConnection Watcher:127.0.0.1:40099/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1611940 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1611941 T4268 oascc.SolrZkClient.makePath makePath: /live_nodes : [junit4] 2> 1611942 T4268 oascc.SolrZkClient.makePath makePath: /clusterstate.json : [junit4] 2> 1611943 T4268 oascc.SolrZkClient.makePath makePath: /aliases.json : [junit4] 2> 1611944 T4268 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... : [junit4] 2> 1611946 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1611947 T4345 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12eded name:ZooKeeperConnection Watcher:127.0.0.1:40099/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1611947 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1611948 T4268 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... : [junit4] 2> 1611950 T4268 oascc.SolrZkClient.makePath makePath: /live_nodes/node1 : [junit4] 2> 1611953 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1611953 T4349 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@183bb88 name:ZooKeeperConnection Watcher:127.0.0.1:40099/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1611954 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1611954 T4268 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false : [junit4] 2> 1611955 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect : [junit4] 2> 1611956 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect/election : [junit4] 2> 1611957 T4268 oasc.Overseer.close Overseer (id=null) closing : [junit4] 2> 1611959 T4268 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:40099_solr : [junit4] 2> 1611959 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader : [junit4] 2> 1611960 T4268 oasc.Overseer.start Overseer (id=92288351573835780-127.0.0.1:40099_solr-n_0000000000) starting : [junit4] 2> 1611961 T4268 oascc.SolrZkClient.makePath makePath: /overseer/queue : [junit4] 2> 1611963 T4268 oascc.SolrZkClient.makePath makePath: /overseer/queue-work : [junit4] 2> 1611965 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure : [junit4] 2> 1611967 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running : [junit4] 2> 1611969 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed : [junit4] 2> 1611972 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work : [junit4] 2> 1611976 T4268 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000 : [junit4] 2> 1611976 T4351 oasc.OverseerCollectionProcessor.run Process current queue of collection creations : [junit4] 2> 1611977 T4350 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue : [junit4] 2> 1612988 T4353 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1612991 T4350 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={ : [junit4] 2> "operation":"state", : [junit4] 2> "state":"recovering", : [junit4] 2> "node_name":"node1", : [junit4] 2> "core":"core1", : [junit4] 2> "core_node_name":"core_node1", : [junit4] 2> "collection":"collection1", : [junit4] 2> "numShards":"1", : [junit4] 2> "base_url":"http://node1/solr/"} : [junit4] 2> 1612991 T4350 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1] : [junit4] 2> 1612991 T4350 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1 : [junit4] 2> 1612993 T4347 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1612993 T4346 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1613488 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election : [junit4] 2> 1613496 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1 : [junit4] 2> 1613501 T4353 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1613504 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election : [junit4] 2> 1613505 T4350 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={ : [junit4] 2> "operation":"state", : [junit4] 2> "state":"active", : [junit4] 2> "node_name":"node1", : [junit4] 2> "core":"core1", : [junit4] 2> "core_node_name":"core_node1", : [junit4] 2> "collection":"collection1", : [junit4] 2> "numShards":"1", : [junit4] 2> "base_url":"http://node1/solr/"} : [junit4] 2> 1613505 T4350 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered : [junit4] 2> 1613507 T4353 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1613508 T4347 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1613508 T4346 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1613513 T4334 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x147dfc44c770004, likely client has closed socket : [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228) : [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208) : [junit4] 2> at java.lang.Thread.run(Thread.java:745) : [junit4] 2> : [junit4] 2> 1613985 T4351 oasc.OverseerCollectionProcessor.amILeader org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127) : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) : [junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.cloud.OverseerCollectionProcessor.amILeader(OverseerCollectionProcessor.java:516) : [junit4] 2> at org.apache.solr.cloud.OverseerCollectionProcessor.run(OverseerCollectionProcessor.java:271) : [junit4] 2> at java.lang.Thread.run(Thread.java:745) : [junit4] 2> : [junit4] 2> 1613985 T4351 oasc.OverseerCollectionProcessor.amILeader According to ZK I (id=92288351573835780-127.0.0.1:40099_solr-n_0000000000) am no longer a leader. : [junit4] 2> 1614515 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election : [junit4] 2> 1614519 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1614520 T4355 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1dc1ae1 name:ZooKeeperConnection Watcher:127.0.0.1:40099/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1614520 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1614521 T4268 oasc.Overseer.close Overseer (id=92288351573835780-127.0.0.1:40099_solr-n_0000000000) closing : [junit4] 2> 1614521 T4350 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:40099_solr : [junit4] 2> 1614522 T4268 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false : [junit4] 2> 1614523 T4356 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127) : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) : [junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:321) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:293) : [junit4] 2> : [junit4] 2> 1614524 T4268 oasc.Overseer.close Overseer (id=null) closing : [junit4] 2> 1614525 T4268 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:40099_solr : [junit4] 2> 1614525 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader : [junit4] 2> 1614527 T4268 oasc.Overseer.start Overseer (id=92288351573835781-127.0.0.1:40099_solr-n_0000000001) starting : [junit4] 2> 1614532 T4268 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000 : [junit4] 2> 1614532 T4358 oasc.OverseerCollectionProcessor.run Process current queue of collection creations : [junit4] 2> 1614534 T4357 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue : [junit4] 2> 1614535 T4357 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={ : [junit4] 2> "operation":"state", : [junit4] 2> "state":"recovering", : [junit4] 2> "node_name":"node1", : [junit4] 2> "core":"core1", : [junit4] 2> "core_node_name":"core_node1", : [junit4] 2> "collection":"collection1", : [junit4] 2> "numShards":"1", : [junit4] 2> "base_url":"http://node1/solr/"} : [junit4] 2> 1614536 T4357 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered : [junit4] 2> 1614537 T4360 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1614537 T4346 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1614537 T4347 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) : [junit4] 2> 1614590 T4268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election : [junit4] 2> 1614590 T4360 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1614594 T4268 oasc.LeaderElector.checkIfIamLeader WARN Failed setting watch org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election/92288351573835779-node1_core1-n_0000000002 : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:111) : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) : [junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:148) : [junit4] 2> at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:314) : [junit4] 2> at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:221) : [junit4] 2> at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:157) : [junit4] 2> at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:662) : [junit4] 2> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) : [junit4] 2> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) : [junit4] 2> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) : [junit4] 2> at java.lang.reflect.Method.invoke(Method.java:606) : [junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1618) : [junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:827) : [junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863) : [junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:877) : [junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53) : [junit4] 2> at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50) : [junit4] 2> at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46) : [junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55) : [junit4] 2> at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49) : [junit4] 2> at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65) : [junit4] 2> at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48) : [junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : [junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:365) : [junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:798) : [junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:458) : [junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:836) : [junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:738) : [junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:772) : [junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:783) : [junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : [junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53) : [junit4] 2> at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46) : [junit4] 2> at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42) : [junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55) : [junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39) : [junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39) : [junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : [junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : [junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : [junit4] 2> at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43) : [junit4] 2> at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48) : [junit4] 2> at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65) : [junit4] 2> at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55) : [junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) : [junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:365) : [junit4] 2> at java.lang.Thread.run(Thread.java:745) : [junit4] 2> : [junit4] 2> 1614595 T4346 oasc.LeaderElector.checkIfIamLeader WARN Our node is no longer in line to be leader : [junit4] 2> 1614596 T4361 oasc.LeaderElector$ElectionWatcher.process WARN org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:111) : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) : [junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1472) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:290) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287) : [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287) : [junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94) : [junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55) : [junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209) : [junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) : [junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262) : [junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) : [junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) : [junit4] 2> at java.lang.Thread.run(Thread.java:745) : [junit4] 2> : [junit4] 2> 1614599 T4268 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:40099 40099 : [junit4] 2> 1615294 T4333 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:40099 40099 : [junit4] 2> 1615295 T4268 oas.SolrTestCaseJ4.tearDown ###Ending testOverseerFailure : [junit4] 2> 1615295 T4268 oasc.Overseer.close Overseer (id=92288351573835781-127.0.0.1:40099_solr-n_0000000001) closing : [junit4] 2> 1615297 T4357 oasc.SolrException.log ERROR Cleaning up collection in zk was interrupted:collection1:java.lang.InterruptedException: sleep interrupted : [junit4] 2> at java.lang.Thread.sleep(Native Method) : [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryDelay(ZkCmdExecutor.java:119) : [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:87) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:186) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:670) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.removeCore(Overseer.java:1098) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.processMessage(Overseer.java:363) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:246) : [junit4] 2> at java.lang.Thread.run(Thread.java:745) : [junit4] 2> : [junit4] 2> 1615297 T4357 oasc.Overseer$ClusterStateUpdater.run WARN Solr cannot talk to ZK, exiting Overseer main queue loop org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer/queue-work/qn- : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127) : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) : [junit4] 2> at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:783) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:273) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:270) : [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.create(SolrZkClient.java:270) : [junit4] 2> at org.apache.solr.cloud.DistributedQueue.createData(DistributedQueue.java:369) : [junit4] 2> at org.apache.solr.cloud.DistributedQueue.offer(DistributedQueue.java:353) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:259) : [junit4] 2> at java.lang.Thread.run(Thread.java:745) : [junit4] 2> : [junit4] 2> 1615298 T4357 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:40099_solr : [junit4] 2> 1615299 T4362 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127) : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) : [junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:321) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:293) : [junit4] 2> : [junit4] 2> NOTE: reproduce with: ant test -Dtestcase=OverseerTest -Dtests.method=testOverseerFailure -Dtests.seed=5547E29057A024AB -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_UY -Dtests.timezone=America/Santa_Isabel -Dtests.file.encoding=ISO-8859-1 : [junit4] ERROR 3.48s J0 | OverseerTest.testOverseerFailure <<< : [junit4] > Throwable #1: org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election : [junit4] > at __randomizedtesting.SeedInfo.seed([5547E29057A024AB:514F6D634505CB8A]:0) : [junit4] > at org.apache.zookeeper.KeeperException.create(KeeperException.java:111) : [junit4] > at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) : [junit4] > at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1472) : [junit4] > at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:290) : [junit4] > at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287) : [junit4] > at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) : [junit4] > at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287) : [junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94) : [junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:155) : [junit4] > at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:314) : [junit4] > at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:221) : [junit4] > at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:157) : [junit4] > at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:662) : [junit4] > at java.lang.Thread.run(Thread.java:745) : [junit4] 2> 1615312 T4268 oas.SolrTestCaseJ4.setUp ###Starting testStateChange : [junit4] 2> 1615313 T4268 oasc.ZkTestServer.run STARTING ZK TEST SERVER : [junit4] 1> client port:0.0.0.0/0.0.0.0:0 : [junit4] 2> 1615314 T4363 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server : [junit4] 2> 1615414 T4268 oasc.ZkTestServer.run start zk server on port:57017 : [junit4] 2> 1615415 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1615417 T4369 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@14ae008 name:ZooKeeperConnection Watcher:127.0.0.1:57017/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1615417 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1615420 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1615421 T4371 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@172325d name:ZooKeeperConnection Watcher:127.0.0.1:57017 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1615421 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1615423 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1615424 T4373 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1218652 name:ZooKeeperConnection Watcher:127.0.0.1:57017 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1615424 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1615425 T4268 oascc.SolrZkClient.makePath makePath: /solr : [junit4] 2> 1615427 T4268 oascc.SolrZkClient.makePath makePath: /live_nodes : [junit4] 2> 1615429 T4268 oascc.SolrZkClient.makePath makePath: /clusterstate.json : [junit4] 2> 1615431 T4268 oascc.SolrZkClient.makePath makePath: /aliases.json : [junit4] 2> 1615433 T4268 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... : [junit4] 2> 1615435 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1615436 T4375 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13f476c name:ZooKeeperConnection Watcher:127.0.0.1:57017/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1615436 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1615436 T4268 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false : [junit4] 2> 1615437 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect : [junit4] 2> 1615439 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect/election : [junit4] 2> 1615441 T4268 oasc.Overseer.close Overseer (id=null) closing : [junit4] 2> 1615443 T4268 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:57017_solr : [junit4] 2> 1615443 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader : [junit4] 2> 1615445 T4268 oasc.Overseer.start Overseer (id=92288351802163203-127.0.0.1:57017_solr-n_0000000000) starting : [junit4] 2> 1615448 T4268 oascc.SolrZkClient.makePath makePath: /overseer/queue : [junit4] 2> 1615451 T4268 oascc.SolrZkClient.makePath makePath: /overseer/queue-work : [junit4] 2> 1615452 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure : [junit4] 2> 1615454 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running : [junit4] 2> 1615456 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed : [junit4] 2> 1615458 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work : [junit4] 2> 1615460 T4268 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000 : [junit4] 2> 1615461 T4377 oasc.OverseerCollectionProcessor.run Process current queue of collection creations : [junit4] 2> 1615462 T4376 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue : [junit4] 2> 1615464 T4376 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={ : [junit4] 2> "operation":"state", : [junit4] 2> "base_url":"http://127.0.0.1/solr";, : [junit4] 2> "node_name":"node1", : [junit4] 2> "collection":"collection1", : [junit4] 2> "core":"core1", : [junit4] 2> "roles":"", : [junit4] 2> "state":"recovering"} : [junit4] 2> 1615464 T4376 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1 : [junit4] 2> 1615466 T4379 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1615466 T4380 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0) : [junit4] 2> 1615515 T4379 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged : [junit4] 2> 1615516 T4376 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={ : [junit4] 2> "operation":"state", : [junit4] 2> "base_url":"http://127.0.0.1/solr";, : [junit4] 2> "node_name":"node1", : [junit4] 2> "collection":"collection1", : [junit4] 2> "core":"core1", : [junit4] 2> "roles":"", : [junit4] 2> "state":"active"} : [junit4] 2> 1615517 T4376 oasc.Overseer$ClusterStateUpdater.updateState node=core_node1 is already registered : [junit4] 2> 1615517 T4376 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered : [junit4] 2> 1615619 T4380 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0) : [junit4] 2> 1615667 T4268 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:57017 57017 : [junit4] 2> 1616218 T4363 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:57017 57017 : [junit4] 2> 1616219 T4268 oas.SolrTestCaseJ4.tearDown ###Ending testStateChange : [junit4] 2> 1616219 T4268 oasc.Overseer.close Overseer (id=92288351802163203-127.0.0.1:57017_solr-n_0000000000) closing : [junit4] 2> 1616220 T4376 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:57017_solr : [junit4] 2> 1616225 T4381 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127) : [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) : [junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) : [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:321) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89) : [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:293) : [junit4] 2> : [junit4] 2> 1616229 T4268 oas.SolrTestCaseJ4.setUp ###Starting testShardAssignmentBigger : [junit4] 2> 1616230 T4268 oasc.ZkTestServer.run STARTING ZK TEST SERVER : [junit4] 1> client port:0.0.0.0/0.0.0.0:0 : [junit4] 2> 1616231 T4382 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server : [junit4] 2> 1616331 T4268 oasc.ZkTestServer.run start zk server on port:56278 : [junit4] 2> 1616332 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1616333 T4388 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3284a1 name:ZooKeeperConnection Watcher:127.0.0.1:56278 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1616334 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1616336 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1616337 T4390 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1533f20 name:ZooKeeperConnection Watcher:127.0.0.1:56278 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1616337 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1616337 T4268 oascc.SolrZkClient.makePath makePath: /solr : [junit4] 2> 1616340 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1616341 T4392 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@68d232 name:ZooKeeperConnection Watcher:127.0.0.1:56278/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1616341 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1616341 T4268 oascc.SolrZkClient.makePath makePath: /live_nodes : [junit4] 2> 1616343 T4268 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper : [junit4] 2> 1616344 T4394 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a1e22d name:ZooKeeperConnection Watcher:127.0.0.1:56278/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None : [junit4] 2> 1616344 T4268 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper : [junit4] 2> 1616344 T4268 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false : [junit4] 2> 1616345 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect : [junit4] 2> 1616346 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect/election : [junit4] 2> 1616348 T4268 oasc.Overseer.close Overseer (id=null) closing : [junit4] 2> 1616349 T4268 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:56278_solr : [junit4] 2> 1616349 T4268 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader : [junit4] 2> 1616350 T4268 oasc.Overseer.start Overseer (id=92288351862259715-127.0.0.1:56278_solr-n_0000000000) starting : [junit4] 2> 1616351 T4268 oascc.SolrZkClient.makePath makePath: /overseer/queue : [junit4] 2> 1616353 T4268 oascc.SolrZkClient.makePath makePath: /overseer/queue-work : [junit4] 2> 1616355 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure : [junit4] 2> 1616356 T4268 oascc.SolrZkClient.makePath makePath: /overseer/collection-map- : : [...truncated too long message...] : : ,cumulative_errors=0,transaction_logs_total_size=17895,transaction_logs_total_number=2} : [junit4] 2> 1876365 T4734 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState : [junit4] 2> 1876365 T4734 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter : [junit4] 2> 1876365 T4734 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser : [junit4] 2> 1876367 T4734 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request. : [junit4] 2> 1876367 T4734 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked : [junit4] 2> 1876367 T4734 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./temp/solr.TestDistributedSearch-5547E29057A024AB-001/tempDir-001/shard0/data [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./temp/solr.TestDistributedSearch-5547E29057A024AB-001/tempDir-001/shard0/data;done=false>>] : [junit4] 2> 1876368 T4734 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./temp/solr.TestDistributedSearch-5547E29057A024AB-001/tempDir-001/shard0/data : [junit4] 2> 1876368 T4734 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./temp/solr.TestDistributedSearch-5547E29057A024AB-001/tempDir-001/shard0/data/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./temp/solr.TestDistributedSearch-5547E29057A024AB-001/tempDir-001/shard0/data/index;done=false>>] : [junit4] 2> 1876368 T4734 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./temp/solr.TestDistributedSearch-5547E29057A024AB-001/tempDir-001/shard0/data/index : [junit4] 2> 1876369 T4734 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null} : [junit4] 2> 1881341 T4734 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch : [junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestDistributedSearch -Dtests.method=testDistribSearch -Dtests.seed=5547E29057A024AB -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=de_CH -Dtests.timezone=Asia/Saigon -Dtests.file.encoding=ISO-8859-1 : [junit4] FAILURE 14.6s J1 | TestDistributedSearch.testDistribSearch <<< : [junit4] > Throwable #1: junit.framework.AssertionFailedError: .facet_counts.facet_fields.a_n_tdt.1970-01-01T00:00:00Z!=2010-04-20T11:00:00Z (unordered or missing) : [junit4] > at __randomizedtesting.SeedInfo.seed([5547E29057A024AB:D4A16C8820FF4497]:0) : [junit4] > at junit.framework.Assert.fail(Assert.java:50) : [junit4] > at org.apache.solr.BaseDistributedSearchTestCase.compareSolrResponses(BaseDistributedSearchTestCase.java:842) : [junit4] > at org.apache.solr.BaseDistributedSearchTestCase.compareResponses(BaseDistributedSearchTestCase.java:861) : [junit4] > at org.apache.solr.BaseDistributedSearchTestCase.query(BaseDistributedSearchTestCase.java:562) : [junit4] > at org.apache.solr.BaseDistributedSearchTestCase.query(BaseDistributedSearchTestCase.java:542) : [junit4] > at org.apache.solr.BaseDistributedSearchTestCase.query(BaseDistributedSearchTestCase.java:521) : [junit4] > at org.apache.solr.TestDistributedSearch.doTest(TestDistributedSearch.java:180) : [junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:875) : [junit4] > at java.lang.Thread.run(Thread.java:745) : [junit4] 2> 1881364 T4734 oas.SolrTestCaseJ4.deleteCore ###deleteCore : [junit4] 2> NOTE: leaving temporary files on disk at: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./temp/solr.TestDistributedSearch-5547E29057A024AB-001 : [junit4] 2> NOTE: test params are: codec=Lucene410: {b_n_tdt=PostingsFormat(name=Direct), n_tl1=Pulsing41(freqCutoff=16 minBlockSize=9 maxBlockSize=66), a_i1=PostingsFormat(name=Direct), range_facet_l=PostingsFormat(name=Direct), multiDefault=Pulsing41(freqCutoff=16 minBlockSize=9 maxBlockSize=66), a_t=PostingsFormat(name=Direct), intDefault=PostingsFormat(name=Direct), other_tl1=PostingsFormat(name=Direct), n_tf1=PostingsFormat(name=Direct), id=PostingsFormat(name=Lucene41WithOrds), SubjectTerms_mfacet=PostingsFormat(name=Direct), n_tdt1=PostingsFormat(name=Direct), n_td1=Pulsing41(freqCutoff=16 minBlockSize=9 maxBlockSize=66), n_d1=PostingsFormat(name=Direct), lowerfilt=Pulsing41(freqCutoff=16 minBlockSize=9 maxBlockSize=66), n_ti1=PostingsFormat(name=Lucene41WithOrds), text=PostingsFormat(name=Memory doPackFST= false), timestamp=PostingsFormat(name=Direct), n_l1=PostingsFormat(name=Direct), foo_d=PostingsFormat(name=Lucene41WithOrds), a_n_tdt=PostingsFormat(name=Lucene41Wit hOrds), lowerfilt1and2=Pulsing41(freqCutoff=16 minBlockSize=9 maxBlockSize=66), oddField_s=PostingsFormat(name=Memory doPackFST= false), n_dt1=Pulsing41(freqCutoff=16 minBlockSize=9 maxBlockSize=66), _version_=PostingsFormat(name=Direct), rnd_b=PostingsFormat(name=Lucene41WithOrds), foo_b=PostingsFormat(name=Memory doPackFST= false), foo_f=PostingsFormat(name=Memory doPackFST= false), n_f1=Pulsing41(freqCutoff=16 minBlockSize=9 maxBlockSize=66)}, docValues:{timestamp=DocValuesFormat(name=Memory)}, sim=DefaultSimilarity, locale=de_CH, timezone=Asia/Saigon : [junit4] 2> NOTE: Linux 3.13.0-32-generic i386/Oracle Corporation 1.7.0_65 (32-bit)/cpus=8,threads=1,free=399639880,total=518979584 : [junit4] 2> NOTE: All tests run in this JVM: [SortByFunctionTest, BinaryUpdateRequestHandlerTest, CollectionsAPIDistributedZkTest, ConvertedLegacyTest, FieldAnalysisRequestHandlerTest, CursorPagingTest, OpenCloseCoreStressTest, HdfsBasicDistributedZkTest, OverseerRolesTest, LegacyHTMLStripCharFilterTest, AutoCommitTest, HdfsWriteToMultipleCollectionsTest, TestCollationField, TestFunctionQuery, TestBinaryField, TestSimpleQParserPlugin, UniqFieldsUpdateProcessorFactoryTest, DocValuesTest, PrimUtilsTest, URLClassifyProcessorTest, TestStressLucene, CoreAdminRequestStatusTest, DistributedFacetPivotLongTailTest, TestSweetSpotSimilarityFactory, HdfsCollectionsAPIDistributedZkTest, CurrencyFieldXmlFileTest, TestMissingGroups, TestFieldSortValues, OutputWriterTest, TestCloudInspectUtil, TestSchemaVersionResource, DebugComponentTest, RequestHandlersTest, TestGroupingSearch, TestCustomSort, ScriptEngineTest, TestDocBasedVersionConstraints, TestStandardQParsers, TermVectorComponentDistrib utedTest, DateFieldTest, TestSearcherReuse, ChaosMonkeySafeLeaderTest, DirectSolrConnectionTest, CircularListTest, DirectUpdateHandlerOptimizeTest, TestLazyCores, TestAddFieldRealTimeGet, AnalysisErrorHandlingTest, BasicDistributedZk2Test, LeaderElectionIntegrationTest, TestImplicitCoreProperties, ExpressionTest, AddSchemaFieldsUpdateProcessorFactoryTest, TestReversedWildcardFilterFactory, TestCollationFieldDocValues, SolrInfoMBeanTest, DistributedQueryElevationComponentTest, TestNonNRTOpen, TestManagedResource, RAMDirectoryFactoryTest, TestSolrQueryParserDefaultOperatorResource, TestJoin, TestLeaderElectionZkExpiry, MigrateRouteKeyTest, TestClassNameShortening, CoreMergeIndexesAdminHandlerTest, SolrRequestParserTest, TestIndexingPerformance, DistributedDebugComponentTest, TestFiltering, UpdateRequestProcessorFactoryTest, CursorMarkTest, MultiTermTest, TestCharFilters, UUIDFieldTest, SolrIndexConfigTest, TestSolrQueryParserResource, DistribDocExpirationUpdateProcessorTest, TestInitQ Parser, TestQueryTypes, TestIntervalFaceting, DistributedQueryComponentCustomSortTest, HardAutoCommitTest, SynonymTokenizerTest, SolrXmlInZkTest, SearchHandlerTest, TestSchemaSimilarityResource, SolrPluginUtilsTest, TestUpdate, TestRandomFaceting, TestExceedMaxTermLength, QueryParsingTest, TestSolrXml, TestZkChroot, TestHighlightDedupGrouping, TestSolrXmlPersistence, DistributedTermsComponentTest, SolrCoreTest, FileBasedSpellCheckerTest, AbstractAnalyticsStatsTest, AnalysisAfterCoreReloadTest, PolyFieldTest, TermVectorComponentTest, QueryElevationComponentTest, CacheHeaderTest, BasicDistributedZkTest, BasicZkTest, FullSolrCloudDistribCmdsTest, ZkSolrClientTest, TestRandomDVFaceting, ShardRoutingCustomTest, TestDistributedSearch] : [junit4] Completed on J1 in 14.63s, 1 test, 1 failure <<< FAILURES! : : [...truncated 641 lines...] : BUILD FAILED : /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:474: The following error occurred while executing this line: : /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:454: The following error occurred while executing this line: : /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:45: The following error occurred while executing this line: : /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/extra-targets.xml:37: The following error occurred while executing this line: : /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:189: The following error occurred while executing this line: : /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:496: The following error occurred while executing this line: : /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1350: The following error occurred while executing this line: : /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:965: There were test failures: 430 suites, 1782 tests, 1 error, 1 failure, 40 ignored (19 assumptions) : : Total time: 93 minutes 17 seconds : Build step 'Invoke Ant' marked build as failure : [description-setter] Description set: Java: 32bit/jdk1.7.0_65 -server -XX:+UseConcMarkSweepGC : Archiving artifacts : Recording test results : Email was triggered for: Failure - Any : Sending email for trigger: Failure - Any : : : -Hoss http://www.lucidworks.com/
--------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
