You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2014/04/17 06:43:46 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/jdk1.7.0_60-ea-b14) - Build
# 9984 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/9984/
Java: 32bit/jdk1.7.0_60-ea-b14 -server -XX:+UseConcMarkSweepGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.OverseerTest.testOverseerFailure
Error Message:
Could not register as the leader because creating the ephemeral registration node in ZooKeeper failed
Stack Trace:
org.apache.solr.common.SolrException: Could not register as the leader because creating the ephemeral registration node in ZooKeeper failed
at __randomizedtesting.SeedInfo.seed([9E7068A413DE20C:DEF897953980D2D]:0)
at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:136)
at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:142)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:110)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:134)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:134)
at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:267)
at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:155)
at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:661)
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.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
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:360)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:793)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:453)
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 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:360)
at java.lang.Thread.run(Thread.java:744)
Caused by: org.apache.solr.common.SolrException: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:40)
at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:123)
... 47 more
Caused by: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
at org.apache.zookeeper.KeeperException.create(KeeperException.java:119)
at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:783)
at org.apache.solr.common.cloud.SolrZkClient$10.execute(SolrZkClient.java:432)
at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:429)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:386)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:373)
at org.apache.solr.cloud.ShardLeaderElectionContextBase$1.execute(ElectionContext.java:128)
at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:34)
... 48 more
Build Log:
[...truncated 11158 lines...]
[junit4] Suite: org.apache.solr.cloud.OverseerTest
[junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solr.cloud.OverseerTest-9E7068A413DE20C-001/init-core-data-001
[junit4] 2> 541226 T2629 oas.SolrTestCaseJ4.buildSSLConfig Randomized ssl (false) and clientAuth (false)
[junit4] 2> 541226 T2629 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> 541226 T2629 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 541229 T2629 oas.SolrTestCaseJ4.setUp ###Starting testPlaceholders
[junit4] 2> 541230 T2629 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 541230 T2630 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 541330 T2629 oasc.ZkTestServer.run start zk server on port:60914
[junit4] 2> 541331 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 548033 T2633 oazsp.FileTxnLog.commit WARN fsync-ing the write ahead log in SyncThread:0 took 6699ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide
[junit4] 2> 548035 T2636 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1569f0e name:ZooKeeperConnection Watcher:127.0.0.1:60914/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 548035 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 548036 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 548037 T2638 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@28dafc name:ZooKeeperConnection Watcher:127.0.0.1:60914 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 548037 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 548040 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 548041 T2640 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@80f6a name:ZooKeeperConnection Watcher:127.0.0.1:60914 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 548041 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 548041 T2629 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 548045 T2629 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 548048 T2629 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 548049 T2629 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 548050 T2629 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 548053 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 548054 T2642 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1966bf8 name:ZooKeeperConnection Watcher:127.0.0.1:60914/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 548054 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 548055 T2629 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 548057 T2629 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 548058 T2642 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 548058 T2636 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 548059 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 548060 T2644 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@83f595 name:ZooKeeperConnection Watcher:127.0.0.1:60914/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 548060 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 548061 T2629 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 548070 T2629 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 548073 T2629 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:60914_solr
[junit4] 2> 548073 T2629 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 548075 T2629 oasc.Overseer.start Overseer (id=91600243527057412-127.0.0.1:60914_solr-n_0000000000) starting
[junit4] 2> 548083 T2629 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 548085 T2629 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 548087 T2629 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 548089 T2629 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 548091 T2629 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 548094 T2629 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 548097 T2646 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 548098 T2645 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 548098 T2646 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes at 127.0.0.1:60914_solr
[junit4] 2> 548099 T2644 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 548102 T2645 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 548102 T2645 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> 548102 T2645 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3, shard4, shard5, shard6, shard7, shard8, shard9, shard10, shard11, shard12]
[junit4] 2> 548103 T2645 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 548106 T2644 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 548113 T2636 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> 548113 T2642 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> 548599 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4] 2> 548609 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4] 2> 548613 T2644 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 548613 T2629 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 548616 T2642 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 548616 T2636 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 548618 T2629 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:60914 60914
[junit4] 2> 550114 T2645 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/qn-0000000001
[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$7.execute(SolrZkClient.java:277)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:274)
[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:274)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.peek(DistributedQueue.java:472)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.peek(DistributedQueue.java:428)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:216)
[junit4] 2> at java.lang.Thread.run(Thread.java:744)
[junit4] 2>
[junit4] 2> 553727 T2645 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:60914_solr
[junit4] 2> 553728 T2630 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:60914 60914
[junit4] 2> 553729 T2647 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$7.execute(SolrZkClient.java:277)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:274)
[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:274)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:302)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:85)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:291)
[junit4] 2>
[junit4] 2> 553731 T2629 oas.SolrTestCaseJ4.tearDown ###Ending testPlaceholders
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 553738 T2629 oas.SolrTestCaseJ4.setUp ###Starting testOverseerFailure
[junit4] 2> 553739 T2629 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 553739 T2648 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 553839 T2629 oasc.ZkTestServer.run start zk server on port:58902
[junit4] 2> 553841 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 553846 T2654 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@657e45 name:ZooKeeperConnection Watcher:127.0.0.1:58902 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 553846 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 553849 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 553851 T2656 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3b3ddc name:ZooKeeperConnection Watcher:127.0.0.1:58902 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 553851 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 553852 T2629 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 553857 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 553858 T2658 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1cdfa18 name:ZooKeeperConnection Watcher:127.0.0.1:58902/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 553859 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 553860 T2629 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 553863 T2629 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 553867 T2629 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 553869 T2629 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 553874 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 553880 T2660 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@14862d name:ZooKeeperConnection Watcher:127.0.0.1:58902/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 553881 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 553883 T2629 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 553887 T2629 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 553891 T2658 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 553891 T2660 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 553892 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 553894 T2662 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@178ee7 name:ZooKeeperConnection Watcher:127.0.0.1:58902/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 553895 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 553897 T2629 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 553900 T2629 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 553904 T2629 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:58902_solr
[junit4] 2> 553905 T2629 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 553906 T2629 oasc.Overseer.start Overseer (id=91600244346912772-127.0.0.1:58902_solr-n_0000000000) starting
[junit4] 2> 553908 T2629 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 553910 T2629 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 553912 T2629 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 553914 T2629 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 553916 T2629 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 553918 T2629 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 553921 T2664 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 553922 T2664 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes at 127.0.0.1:58902_solr
[junit4] 2> 553922 T2663 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 554926 T2662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 554929 T2663 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 554929 T2663 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> 554929 T2663 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 554929 T2663 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 554932 T2662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 554933 T2658 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> 554933 T2660 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> 555426 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 555441 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 555444 T2662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 555445 T2629 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 555446 T2663 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 555449 T2662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 555449 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 555451 T2663 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> 555451 T2663 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 555454 T2662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 555556 T2660 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> 555556 T2658 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> 556610 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 556636 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 556638 T2666 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@394e69 name:ZooKeeperConnection Watcher:127.0.0.1:58902/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 556638 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 556640 T2663 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:58902_solr
[junit4] 2> 556641 T2667 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$7.execute(SolrZkClient.java:277)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:274)
[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:274)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:302)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:85)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:291)
[junit4] 2>
[junit4] 2> 556642 T2629 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:58902_solr
[junit4] 2> 556643 T2629 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 556644 T2629 oasc.Overseer.start Overseer (id=91600244346912773-127.0.0.1:58902_solr-n_0000000001) starting
[junit4] 2> 556652 T2669 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 556652 T2668 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 556652 T2669 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes at 127.0.0.1:58902_solr
[junit4] 2> 556654 T2668 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 556654 T2668 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> 556654 T2668 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 556656 T2666 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 556656 T2658 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> 556657 T2660 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> 556709 T2666 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 556709 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 556711 T2668 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 556716 T2629 oasc.LeaderElector.checkIfIamLeader WARN Failed setting watch org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election/91600244346912771-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$7.execute(SolrZkClient.java:277)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:274)
[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:274)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:127)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:267)
[junit4] 2> at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:155)
[junit4] 2> at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:661)
[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.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
[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:360)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:793)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:453)
[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 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:360)
[junit4] 2> at java.lang.Thread.run(Thread.java:744)
[junit4] 2>
[junit4] 2> 556719 T2660 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 556719 T2629 oasc.LeaderElector.checkIfIamLeader WARN Failed setting watch org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election/91600244346912771-node1_core1-n_0000000001
[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$7.execute(SolrZkClient.java:277)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:274)
[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:274)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:127)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:134)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:267)
[junit4] 2> at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:155)
[junit4] 2> at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:661)
[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.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
[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:360)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:793)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:453)
[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 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:360)
[junit4] 2> at java.lang.Thread.run(Thread.java:744)
[junit4] 2>
[junit4] 2> 556719 T2668 oasc.SolrException.log ERROR Problem cleaning up collection in zk:collection1:org.apache.zookeeper.KeeperException$NotEmptyException: KeeperErrorCode = Directory not empty for /collections/collection1/leader_elect/shard1/election
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:125)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:177)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:174)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:174)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:631)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:626)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:626)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:626)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.removeCore(Overseer.java:1069)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.processMessage(Overseer.java:342)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:241)
[junit4] 2> at java.lang.Thread.run(Thread.java:744)
[junit4] 2>
[junit4] 2> 556723 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 556727 T2666 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 556729 T2666 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 556730 T2660 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 556730 T2668 oasc.Overseer$ClusterStateUpdater.setShardLeader ERROR Could not mark shard leader for non existing collection:collection1
[junit4] 2> 556732 T2666 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 556734 T2666 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 556734 T2668 oasc.Overseer$ClusterStateUpdater.setShardLeader ERROR Could not mark shard leader for non existing collection:collection1
[junit4] 2> 556736 T2666 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 556838 T2658 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> 556838 T2660 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> 557728 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 558731 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 559736 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 560739 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 561742 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 562745 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 563748 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 564750 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 565755 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 566780 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 567806 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 568826 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 569846 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 570866 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 571887 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 571926 T2660 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 571926 T2658 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 571986 T2629 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:58902 58902
[junit4] 2> 577048 T2648 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:58902 58902
[junit4] 2> 577048 T2629 oas.SolrTestCaseJ4.tearDown ###Ending testOverseerFailure
[junit4] 2> 577049 T2668 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:58902_solr
[junit4] 2> 577050 T2670 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$7.execute(SolrZkClient.java:277)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:274)
[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:274)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:302)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:85)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:291)
[junit4] 2>
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=OverseerTest -Dtests.method=testOverseerFailure -Dtests.seed=9E7068A413DE20C -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=cs -Dtests.timezone=PRC -Dtests.file.encoding=UTF-8
[junit4] ERROR 23.3s J0 | OverseerTest.testOverseerFailure <<<
[junit4] > Throwable #1: org.apache.solr.common.SolrException: Could not register as the leader because creating the ephemeral registration node in ZooKeeper failed
[junit4] > at __randomizedtesting.SeedInfo.seed([9E7068A413DE20C:DEF897953980D2D]:0)
[junit4] > at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:136)
[junit4] > at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:142)
[junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:110)
[junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:134)
[junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:134)
[junit4] > at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:267)
[junit4] > at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:155)
[junit4] > at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:661)
[junit4] > at java.lang.Thread.run(Thread.java:744)
[junit4] > Caused by: org.apache.solr.common.SolrException: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
[junit4] > at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:40)
[junit4] > at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:123)
[junit4] > ... 47 more
[junit4] > Caused by: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
[junit4] > at org.apache.zookeeper.KeeperException.create(KeeperException.java:119)
[junit4] > at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] > at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:783)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient$10.execute(SolrZkClient.java:432)
[junit4] > at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:429)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:386)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:373)
[junit4] > at org.apache.solr.cloud.ShardLeaderElectionContextBase$1.execute(ElectionContext.java:128)
[junit4] > at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:34)
[junit4] > ... 48 more
[junit4] 2> 577063 T2629 oas.SolrTestCaseJ4.setUp ###Starting testBadQueueItem
[junit4] 2> 577064 T2629 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 577065 T2671 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 577165 T2629 oasc.ZkTestServer.run start zk server on port:58654
[junit4] 2> 577166 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 589053 T2674 oazsp.FileTxnLog.commit WARN fsync-ing the write ahead log in SyncThread:0 took 11886ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide
[junit4] 2> 589055 T2672 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x1456df034bf0000, 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:744)
[junit4] 2>
[junit4] 2> 589240 T2677 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@514c18 name:ZooKeeperConnection Watcher:127.0.0.1:58654 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 589240 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 589243 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 589244 T2679 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@192078c name:ZooKeeperConnection Watcher:127.0.0.1:58654 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 589244 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 589244 T2629 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 589247 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 589248 T2681 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@48efa9 name:ZooKeeperConnection Watcher:127.0.0.1:58654/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 589248 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 589249 T2629 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 589250 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 589251 T2683 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4cd692 name:ZooKeeperConnection Watcher:127.0.0.1:58654/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 589252 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 589252 T2629 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 589255 T2629 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 589263 T2629 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:58654_solr
[junit4] 2> 589264 T2629 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 589265 T2629 oasc.Overseer.start Overseer (id=91600245875474436-127.0.0.1:58654_solr-n_0000000000) starting
[junit4] 2> 589267 T2629 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 589270 T2629 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 589272 T2629 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 589275 T2629 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 589278 T2629 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 589281 T2629 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 589292 T2685 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 589292 T2629 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 589292 T2684 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 589293 T2685 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes at 127.0.0.1:58654_solr
[junit4] 2> 589295 T2629 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 589297 T2629 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 589299 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 589300 T2687 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@113a4a2 name:ZooKeeperConnection Watcher:127.0.0.1:58654/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 589300 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 589301 T2629 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 589303 T2629 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1
[junit4] 2> 589305 T2687 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 589305 T2681 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 589306 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 589307 T2684 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 589307 T2684 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> 589308 T2684 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3]
[junit4] 2> 589308 T2684 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 589310 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 589374 T2687 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> 589374 T2681 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> 589806 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4] 2> 589813 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4] 2> 589817 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 589818 T2684 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 589819 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 589821 T2684 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> 589821 T2684 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 589821 T2684 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 589825 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 589927 T2681 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> 589927 T2687 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> 590319 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 590338 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 590341 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 590342 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 590342 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 590343 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 590343 T2684 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 590346 T2684 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> 590346 T2684 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 590347 T2684 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 590348 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 590450 T2687 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> 590450 T2681 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> 590843 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 590851 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4] 2> 590855 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 590855 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 590855 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 590856 T2684 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 590858 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 590960 T2681 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> 590960 T2687 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> 591007 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 591007 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 591007 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 591008 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 591009 T2684 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 591009 T2684 oasc.Overseer$ClusterStateUpdater.checkKeyExistence ERROR Skipping invalid Overseer message because it has no collection specified: {
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"127.0.0.1",
[junit4] 2> "core":"core0",
[junit4] 2> "core_node_name":"node0",
[junit4] 2> "collection":"",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 591012 T2684 oasc.Overseer$ClusterStateUpdater.checkKeyExistence ERROR Skipping invalid Overseer message because it has no collection specified: {
[junit4] 2> "operation":"deletecore",
[junit4] 2> "node_name":"127.0.0.1",
[junit4] 2> "core":"core0",
[junit4] 2> "core_node_name":"node0",
[junit4] 2> "collection":""}
[junit4] 2> 591014 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 591015 T2684 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":"collection2",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 591015 T2684 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection2 with shards [shard1, shard2, shard3]
[junit4] 2> 591015 T2684 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 591096 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 591198 T2681 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> 591198 T2687 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> 591510 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection2/leader_elect/shard3/election
[junit4] 2> 591516 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection2/leaders/shard3
[junit4] 2> 591526 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 591527 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 591527 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 591528 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 591529 T2684 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 591539 T2684 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":"collection2",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 591539 T2684 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 591539 T2684 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 591541 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 591643 T2681 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> 591643 T2687 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> 592028 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection2/leader_elect/shard1/election
[junit4] 2> 592036 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection2/leaders/shard1
[junit4] 2> 592039 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 592040 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 592040 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 592042 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 592042 T2684 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 592045 T2684 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":"collection2",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 592045 T2684 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 592045 T2684 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 592047 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 592150 T2687 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> 592150 T2681 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> 592542 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection2/leader_elect/shard2/election
[junit4] 2> 592548 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection2/leaders/shard2
[junit4] 2> 592552 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 592553 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 592553 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 592553 T2684 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 592556 T2683 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 592657 T2681 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> 592657 T2687 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> 592706 T2687 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 592707 T2672 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x1456df034bf0004, 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:744)
[junit4] 2>
[junit4] 2> 592708 T2629 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:58654 58654
[junit4] 2> 592817 T2671 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:58654 58654
[junit4] 2> 592819 T2629 oas.SolrTestCaseJ4.tearDown ###Ending testBadQueueItem
[junit4] 2> 592819 T2684 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:58654_solr
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 592821 T2688 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$7.execute(SolrZkClient.java:277)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:274)
[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:274)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:302)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:85)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:291)
[junit4] 2>
[junit4] 2> 592835 T2629 oas.SolrTestCaseJ4.setUp ###Starting testShardLeaderChange
[junit4] 2> 592836 T2629 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 592837 T2689 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 592937 T2629 oasc.ZkTestServer.run start zk server on port:34219
[junit4] 2> 592938 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 592946 T2695 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ca8b1 name:ZooKeeperConnection Watcher:127.0.0.1:34219/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 592946 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 592947 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 592949 T2697 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12ea729 name:ZooKeeperConnection Watcher:127.0.0.1:34219 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 592949 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 592952 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 592954 T2699 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2d9296 name:ZooKeeperConnection Watcher:127.0.0.1:34219 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 592954 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 592955 T2629 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 592960 T2629 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 592964 T2700 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 592974 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 592975 T2703 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16d2e56 name:ZooKeeperConnection Watcher:127.0.0.1:34219/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 592976 T2700 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 592977 T2704 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16d85d4 name:ZooKeeperConnection Watcher:127.0.0.1:34219/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 592977 T2700 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 592977 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 592979 T2629 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 592979 T2700 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 592983 T2700 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:34219_solr
[junit4] 2> 592983 T2629 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 592983 T2700 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 592986 T2629 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 592987 T2700 oasc.Overseer.start Overseer (id=91600246909173763-127.0.0.1:34219_solr-n_0000000000) starting
[junit4] 2> 592990 T2700 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 592990 T2629 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 592993 T2704 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 592996 T2700 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 593001 T2700 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 593004 T2700 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 593006 T2700 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 593009 T2700 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 593014 T2706 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 593014 T2700 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 593014 T2705 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 593015 T2706 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes at 127.0.0.1:34219_solr
[junit4] 2> 593017 T2700 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 593019 T2708 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7d9683 name:ZooKeeperConnection Watcher:127.0.0.1:34219/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 593020 T2700 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 593021 T2705 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=91600246909173763-127.0.0.1:34219_solr-n_0000000000) am no longer a leader.
[junit4] 2> 593021 T2705 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:34219_solr
[junit4] 2> 593031 T2709 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$7.execute(SolrZkClient.java:277)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:274)
[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:274)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:302)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:85)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:291)
[junit4] 2>
[junit4] 2> 593031 T2706 oasc.OverseerCollectionProcessor.run ERROR Unable to prioritize overseer 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.exists(SolrZkClient.java:223)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionProcessor.prioritizeOverseerNodes(OverseerCollectionProcessor.java:299)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionProcessor.run(OverseerCollectionProcessor.java:212)
[junit4] 2> at java.lang.Thread.run(Thread.java:744)
[junit4] 2>
[junit4] 2> 593040 T2700 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:34219_solr
[junit4] 2> 593040 T2700 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 593054 T2700 oasc.Overseer.start Overseer (id=91600246909173765-127.0.0.1:34219_solr-n_0000000001) starting
[junit4] 2> 593076 T2711 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 593077 T2711 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes at 127.0.0.1:34219_solr
[junit4] 2> 593079 T2710 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 593080 T2710 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 593082 T2710 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 593082 T2710 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 593082 T2710 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 593085 T2708 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 593086 T2704 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> 593498 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 593508 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 593514 T2708 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 593517 T2710 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 593517 T2708 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 593517 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 593521 T2710 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 593521 T2710 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 593523 T2708 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 593525 T2629 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 593528 T2713 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1ff40ea name:ZooKeeperConnection Watcher:127.0.0.1:34219/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 593528 T2629 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 593530 T2629 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 593533 T2629 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 593535 T2704 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 593535 T2713 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 593537 T2708 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 593538 T2629 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 593539 T2710 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 593539 T2710 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 593541 T2708 oasc.DistributedQue
[...truncated too long message...]
ZooKeeper.getChildren(ZooKeeper.java:1472)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:260)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:257)
[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:257)
[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:303)
[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> 619835 T2963 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 619834 T2935 oasc.LeaderElector$ElectionWatcher.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard1/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$6.execute(SolrZkClient.java:260)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:257)
[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:257)
[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:303)
[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> 619846 T2629 oas.SolrTestCaseJ4.tearDown ###Ending testShardAssignmentBigger
[junit4] 2> 619844 T2931 oasc.LeaderElector$ElectionWatcher.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard1/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$6.execute(SolrZkClient.java:260)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:257)
[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:257)
[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:303)
[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> 619849 T2924 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:34954_solr
[junit4] 2> 619848 T2935 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 619850 T2931 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 619851 T2629 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> 619850 T3127 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$7.execute(SolrZkClient.java:277)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:274)
[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:274)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:302)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:85)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:291)
[junit4] 2>
[junit4] 2> 619852 T2629 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 622853 T2629 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solr.cloud.OverseerTest-9E7068A413DE20C-001
[junit4] 2> NOTE: test params are: codec=Lucene40, sim=DefaultSimilarity, locale=cs, timezone=PRC
[junit4] 2> NOTE: Linux 3.8.0-38-generic i386/Oracle Corporation 1.7.0_60-ea (32-bit)/cpus=8,threads=1,free=72808928,total=250056704
[junit4] 2> NOTE: All tests run in this JVM: [TestSerializedLuceneMatchVersion, CachingDirectoryFactoryTest, DeleteReplicaTest, TestRemoteStreaming, DocExpirationUpdateProcessorFactoryTest, DocValuesTest, ZkControllerTest, TestComplexPhraseQParserPlugin, TestPseudoReturnFields, MBeansHandlerTest, SliceStateTest, TermVectorComponentTest, TestDocBasedVersionConstraints, TestReversedWildcardFilterFactory, TestSurroundQueryParser, SpellPossibilityIteratorTest, TestStressVersions, SoftAutoCommitTest, OverseerRolesTest, SystemInfoHandlerTest, SchemaVersionSpecificBehaviorTest, ShardRoutingTest, RegexBoostProcessorTest, TestQueryUtils, TestDocumentBuilder, TestFieldTypeCollectionResource, WordBreakSolrSpellCheckerTest, TestCollapseQParserPlugin, SuggestComponentTest, TestSolrQueryParserDefaultOperatorResource, SolrCoreTest, SampleTest, SearchHandlerTest, SyncSliceTest, TestSchemaVersionResource, IndexSchemaTest, TestReloadAndDeleteDocs, FastVectorHighlighterTest, TestSolrXMLSerializer, LoggingHandlerTest, TestOverriddenPrefixQueryForCustomFieldType, TestBadConfig, HdfsBasicDistributedZk2Test, TestTrie, BlockDirectoryTest, TestFreeTextSuggestions, TestValueSourceCache, DocValuesMissingTest, BJQParserTest, PeerSyncTest, TestSimpleQParserPlugin, UpdateRequestProcessorFactoryTest, TestPostingsSolrHighlighter, CoreAdminHandlerTest, AddBlockUpdateTest, SuggesterTest, TestLRUCache, TestFunctionQuery, URLClassifyProcessorTest, TestCursorMarkWithoutUniqueKey, TestImplicitCoreProperties, ResourceLoaderTest, UUIDFieldTest, TestShortCircuitedRequests, TestPerFieldSimilarity, BasicDistributedZkTest, DistributedSpellCheckComponentTest, TestExpandComponent, LegacyHTMLStripCharFilterTest, DistributedQueryComponentOptimizationTest, LukeRequestHandlerTest, AnalysisAfterCoreReloadTest, CSVRequestHandlerTest, TestInfoStreamLogging, TestElisionMultitermQuery, TestPHPSerializedResponseWriter, TestConfig, DistributedTermsComponentTest, QueryElevationComponentTest, SynonymTokenizerTest, TestNonDefinedSimilarityFactory, QueryParsingTest, DistributedDebugComponentTest, TestConfigSets, StatelessScriptUpdateProcessorFactoryTest, TestExtendedDismaxParser, MoreLikeThisHandlerTest, BadComponentTest, JsonLoaderTest, ShowFileRequestHandlerTest, TestInitQParser, TestMergePolicyConfig, TestNRTOpen, TestLMJelinekMercerSimilarityFactory, UnloadDistributedZkTest, OverseerTest]
[junit4] Completed on J0 in 81.67s, 9 tests, 1 error <<< FAILURES!
[...truncated 702 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:467: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:447: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:45: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/extra-targets.xml:37: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:189: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:496: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1286: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:910: There were test failures: 387 suites, 1619 tests, 1 error, 38 ignored (17 assumptions)
Total time: 59 minutes 34 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_60-ea-b14 -server -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure