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/03/07 12:37:32 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.7.0_51) - Build #
9704 - Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/9704/
Java: 32bit/jdk1.7.0_51 -client -XX:+UseParallelGC
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([EC6FA60BD0AF2C0F:E86729F8C20AC32E]:0)
at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:135)
at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:164)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:108)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:156)
at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:289)
at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:155)
at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:666)
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:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
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:70)
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:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
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 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:70)
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:358)
at java.lang.Thread.run(Thread.java:744)
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:431)
at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:428)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:385)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:372)
at org.apache.solr.cloud.ShardLeaderElectionContextBase$1.execute(ElectionContext.java:127)
at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:31)
at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:122)
... 46 more
Build Log:
[...truncated 10654 lines...]
[junit4] Suite: org.apache.solr.cloud.OverseerTest
[junit4] 2> 700083 T2589 oas.SolrTestCaseJ4.buildSSLConfig Randomized ssl (true) and clientAuth (true)
[junit4] 2> 700083 T2589 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-OverseerTest-1394191440697
[junit4] 2> 700084 T2589 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 700086 T2589 oas.SolrTestCaseJ4.setUp ###Starting testOverseerFailure
[junit4] 2> 700087 T2589 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 700087 T2590 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 700187 T2589 oasc.ZkTestServer.run start zk server on port:34566
[junit4] 2> 700188 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 700240 T2596 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bc26a9 name:ZooKeeperConnection Watcher:127.0.0.1:34566 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 700240 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 700243 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 700244 T2598 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d18425 name:ZooKeeperConnection Watcher:127.0.0.1:34566 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 700244 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 700245 T2589 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 700248 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 700248 T2600 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@616781 name:ZooKeeperConnection Watcher:127.0.0.1:34566/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 700249 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 700249 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 700250 T2589 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 700252 T2589 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 700253 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 700255 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 700256 T2602 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a3ca4d name:ZooKeeperConnection Watcher:127.0.0.1:34566/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 700256 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 700257 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 700258 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 700260 T2602 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 700260 T2600 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 700260 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 700261 T2604 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bd524d name:ZooKeeperConnection Watcher:127.0.0.1:34566/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 700261 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 700262 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 700263 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 700266 T2589 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:34566_solr
[junit4] 2> 700266 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 700267 T2589 oasc.Overseer.start Overseer (id=91369730257846276-127.0.0.1:34566_solr-n_0000000000) starting
[junit4] 2> 700270 T2589 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 700273 T2589 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 700276 T2589 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 700277 T2606 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 700278 T2606 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
[junit4] 2> 700278 T2605 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 701279 T2604 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 701281 T2605 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 701281 T2605 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> 701281 T2605 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 701282 T2605 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 701283 T2604 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 701284 T2600 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> 701284 T2602 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> 701780 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 701789 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 701793 T2604 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 701794 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 701795 T2605 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 701797 T2604 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 701797 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 701798 T2605 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> 701798 T2605 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 701801 T2604 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 701903 T2600 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> 701903 T2602 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> 702957 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 702962 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 702962 T2608 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@486919 name:ZooKeeperConnection Watcher:127.0.0.1:34566/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 702963 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 702965 T2589 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:34566_solr
[junit4] 2> 702966 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 702967 T2589 oasc.Overseer.start Overseer (id=91369730257846277-127.0.0.1:34566_solr-n_0000000001) starting
[junit4] 2> 702971 T2610 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 702971 T2610 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
[junit4] 2> 702971 T2609 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 702973 T2609 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 702974 T2609 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> 702974 T2609 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 702976 T2608 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 702977 T2600 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> 702977 T2602 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> 703031 T2608 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 703031 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 703032 T2609 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 703037 T2602 oasc.LeaderElector.checkIfIamLeader WARN Our node is no longer in line to be leader
[junit4] 2> 703037 T2589 oasc.LeaderElector.checkIfIamLeader WARN Failed setting watch org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election/91369730257846275-node1_core1-n_0000000000
[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:1151)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:276)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:273)
[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:273)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:125)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:289)
[junit4] 2> at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:155)
[junit4] 2> at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:666)
[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:1559)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
[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:70)
[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:358)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
[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 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:70)
[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:358)
[junit4] 2> at java.lang.Thread.run(Thread.java:744)
[junit4] 2>
[junit4] 2> 703038 T2602 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 703038 T2609 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:176)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:173)
[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:173)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:635)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:630)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:630)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:630)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.removeCore(Overseer.java:976)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.processMessage(Overseer.java:253)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:202)
[junit4] 2> at java.lang.Thread.run(Thread.java:744)
[junit4] 2>
[junit4] 2> 703039 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 703041 T2608 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 703043 T2608 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 703043 T2609 oasc.Overseer$ClusterStateUpdater.setShardLeader ERROR Could not mark shard leader for non existing collection:collection1
[junit4] 2> 703045 T2608 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 703147 T2600 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> 703147 T2602 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> 704042 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 705046 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 706049 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 707052 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 708056 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 709059 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 710062 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 711064 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 712067 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 713078 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 714083 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 715087 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 716090 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 717094 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 718097 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 718105 T2600 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 718109 T2589 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:34566 34566
[junit4] 2> 718345 T2589 oas.SolrTestCaseJ4.tearDown ###Ending testOverseerFailure
[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=EC6FA60BD0AF2C0F -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ko_KR -Dtests.timezone=Mideast/Riyadh89 -Dtests.file.encoding=ISO-8859-1
[junit4] ERROR 18.3s J1 | 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([EC6FA60BD0AF2C0F:E86729F8C20AC32E]:0)
[junit4] > at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:135)
[junit4] > at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:164)
[junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:108)
[junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:156)
[junit4] > at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:289)
[junit4] > at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:155)
[junit4] > at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:666)
[junit4] > at java.lang.Thread.run(Thread.java:744)
[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:431)
[junit4] > at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:428)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:385)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:372)
[junit4] > at org.apache.solr.cloud.ShardLeaderElectionContextBase$1.execute(ElectionContext.java:127)
[junit4] > at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:31)
[junit4] > at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:122)
[junit4] > ... 46 more
[junit4] 2> 718364 T2589 oas.SolrTestCaseJ4.setUp ###Starting testBadQueueItem
[junit4] 2> 718364 T2589 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 718365 T2611 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 718465 T2589 oasc.ZkTestServer.run start zk server on port:41659
[junit4] 2> 718466 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 718468 T2617 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bd336b name:ZooKeeperConnection Watcher:127.0.0.1:41659 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 718469 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 718486 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 718487 T2619 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ecde5a name:ZooKeeperConnection Watcher:127.0.0.1:41659 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 718487 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 718487 T2589 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 718489 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 718490 T2621 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f488fb name:ZooKeeperConnection Watcher:127.0.0.1:41659/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 718491 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 718491 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 718492 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 718493 T2623 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@138ead8 name:ZooKeeperConnection Watcher:127.0.0.1:41659/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 718493 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 718494 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 718495 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 718498 T2589 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:41659_solr
[junit4] 2> 718498 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 718500 T2589 oasc.Overseer.start Overseer (id=91369731455844355-127.0.0.1:41659_solr-n_0000000000) starting
[junit4] 2> 718501 T2589 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 718503 T2589 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 718505 T2589 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 718507 T2625 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 718507 T2589 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 718507 T2625 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
[junit4] 2> 718507 T2624 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 718509 T2589 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 718512 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 718516 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 718517 T2627 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@829004 name:ZooKeeperConnection Watcher:127.0.0.1:41659/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 718517 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 718519 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 718521 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1
[junit4] 2> 718523 T2621 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 718523 T2627 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 718524 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 718525 T2624 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 718525 T2624 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> 718526 T2624 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3]
[junit4] 2> 718526 T2624 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 718527 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 718528 T2621 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> 718528 T2627 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> 719024 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4] 2> 719033 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4] 2> 719037 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 719039 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 719039 T2624 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 719042 T2624 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> 719042 T2624 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 719042 T2624 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 719044 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 719147 T2621 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> 719148 T2627 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> 719539 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 719545 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4] 2> 719548 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 719549 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 719549 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 719551 T2624 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 719552 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 719555 T2624 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> 719556 T2624 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 719556 T2624 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 719558 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 719603 T2602 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 719660 T2627 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> 719660 T2621 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> 720052 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 720058 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 720062 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720062 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720063 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720063 T2624 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 720066 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720169 T2621 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> 720169 T2627 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> 720214 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720215 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720215 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720216 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720217 T2624 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 720217 T2624 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> 720220 T2624 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> 720222 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720223 T2624 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> 720223 T2624 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection2 with shards [shard1, shard2, shard3]
[junit4] 2> 720223 T2624 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 720225 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720327 T2621 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> 720327 T2627 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> 720718 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection2/leader_elect/shard3/election
[junit4] 2> 720734 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection2/leaders/shard3
[junit4] 2> 720747 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720747 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720748 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720750 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720750 T2624 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 720754 T2624 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> 720755 T2624 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 720755 T2624 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 720764 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 720866 T2627 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> 720866 T2621 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> 721250 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection2/leader_elect/shard2/election
[junit4] 2> 721260 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection2/leaders/shard2
[junit4] 2> 721278 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 721279 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 721279 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 721281 T2624 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 721281 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 721288 T2624 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> 721288 T2624 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 721289 T2624 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 721291 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 721394 T2627 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> 721394 T2621 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> 721782 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection2/leader_elect/shard1/election
[junit4] 2> 721794 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection2/leaders/shard1
[junit4] 2> 721803 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 721803 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 721804 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 721810 T2624 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 721817 T2623 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 721920 T2627 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> 721920 T2621 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> 721956 T2627 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 721960 T2589 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:41659 41659
[junit4] 2> 727060 T2589 oas.SolrTestCaseJ4.tearDown ###Ending testBadQueueItem
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 727068 T2589 oas.SolrTestCaseJ4.setUp ###Starting testShardAssignment
[junit4] 2> 727068 T2589 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 727079 T2628 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 727179 T2589 oasc.ZkTestServer.run start zk server on port:49826
[junit4] 2> 727190 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 727203 T2634 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3dcc54 name:ZooKeeperConnection Watcher:127.0.0.1:49826 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 727204 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 727240 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 727241 T2636 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b8955 name:ZooKeeperConnection Watcher:127.0.0.1:49826 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 727242 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 727242 T2589 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 727244 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 727245 T2638 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@753b5c name:ZooKeeperConnection Watcher:127.0.0.1:49826/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 727245 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 727246 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 727247 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 727248 T2640 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c43006 name:ZooKeeperConnection Watcher:127.0.0.1:49826/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 727248 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 727251 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 727254 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 727258 T2589 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:49826_solr
[junit4] 2> 727258 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 727260 T2589 oasc.Overseer.start Overseer (id=91369732027908099-127.0.0.1:49826_solr-n_0000000000) starting
[junit4] 2> 727261 T2589 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 727263 T2589 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 727266 T2589 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 727268 T2642 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 727268 T2589 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 727269 T2642 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
[junit4] 2> 727269 T2641 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 727271 T2589 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 727272 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 727274 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 727274 T2644 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19e138c name:ZooKeeperConnection Watcher:127.0.0.1:49826/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 727275 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 727276 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 727277 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1
[junit4] 2> 727279 T2638 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 727279 T2644 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 727280 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 727281 T2641 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 727281 T2641 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> 727282 T2641 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3]
[junit4] 2> 727282 T2641 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 727283 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 727284 T2638 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> 727284 T2644 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> 727780 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4] 2> 727787 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4] 2> 727793 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 727794 T2641 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 727795 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 727797 T2641 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> 727797 T2641 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 727798 T2641 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 727800 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 727902 T2638 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> 727903 T2644 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> 728295 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 728300 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4] 2> 728304 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 728304 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 728304 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 728305 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 728305 T2641 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 728308 T2641 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> 728308 T2641 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 728308 T2641 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 728310 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 728413 T2638 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> 728413 T2644 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> 728805 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 728817 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 728822 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 728823 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 728823 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 728826 T2641 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 728828 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 728829 T2641 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"127.0.0.1",
[junit4] 2> "core":"core4",
[junit4] 2> "core_node_name":"node4",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 728830 T2641 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 728830 T2641 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 728832 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 729080 T2644 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> 729080 T2638 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> 729325 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4] 2> 729333 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 729333 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 729333 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 729334 T2641 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 729335 T2641 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"127.0.0.1",
[junit4] 2> "core":"core5",
[junit4] 2> "core_node_name":"node5",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 729335 T2641 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 729336 T2641 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 729338 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 729439 T2638 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> 729440 T2644 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> 729833 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 729912 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 729912 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 729913 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 729914 T2641 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 729914 T2641 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"127.0.0.1",
[junit4] 2> "core":"core6",
[junit4] 2> "core_node_name":"node6",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 729915 T2641 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 729915 T2641 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 729934 T2640 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 730037 T2644 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> 730037 T2638 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> 730412 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 730420 T2644 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 730422 T2589 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:49826 49826
[junit4] 2> 730465 T2589 oas.SolrTestCaseJ4.tearDown ###Ending testShardAssignment
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 730469 T2589 oas.SolrTestCaseJ4.setUp ###Starting testPlaceholders
[junit4] 2> 730469 T2589 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 730470 T2645 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 730570 T2589 oasc.ZkTestServer.run start zk server on port:60161
[junit4] 2> 730571 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 730573 T2651 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@455abb name:ZooKeeperConnection Watcher:127.0.0.1:60161/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 730573 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 730574 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 730574 T2653 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5aa23 name:ZooKeeperConnection Watcher:127.0.0.1:60161 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 730575 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 730594 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 730595 T2655 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@102ac06 name:ZooKeeperConnection Watcher:127.0.0.1:60161 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 730596 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 730596 T2589 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 730598 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 730602 T2589 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 730606 T2589 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 730608 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 730613 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 730615 T2657 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12aafb0 name:ZooKeeperConnection Watcher:127.0.0.1:60161/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 730615 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 730617 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 730621 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 730625 T2651 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 730625 T2657 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 730626 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 730627 T2659 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11ab9bf name:ZooKeeperConnection Watcher:127.0.0.1:60161/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 730628 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 730629 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 730632 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 730635 T2589 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:60161_solr
[junit4] 2> 730635 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 730637 T2589 oasc.Overseer.start Overseer (id=91369732249288708-127.0.0.1:60161_solr-n_0000000000) starting
[junit4] 2> 730638 T2589 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 730640 T2589 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 730643 T2589 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 730645 T2661 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 730645 T2660 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 730646 T2661 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
[junit4] 2> 730647 T2659 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 730648 T2660 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 730648 T2660 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> 730649 T2660 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3, shard4, shard5, shard6, shard7, shard8, shard9, shard10, shard11, shard12]
[junit4] 2> 730649 T2660 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard6
[junit4] 2> 730652 T2659 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 730653 T2657 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> 730653 T2651 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> 731147 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard6/election
[junit4] 2> 731158 T2589 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard6
[junit4] 2> 731165 T2659 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 731166 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 731168 T2660 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 731171 T2651 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 731171 T2657 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 731173 T2589 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:60161 60161
[junit4] 2> 731257 T2589 oas.SolrTestCaseJ4.tearDown ###Ending testPlaceholders
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 731264 T2589 oas.SolrTestCaseJ4.setUp ###Starting testShardAssignmentBigger
[junit4] 2> 731265 T2589 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 731265 T2662 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 731365 T2589 oasc.ZkTestServer.run start zk server on port:55955
[junit4] 2> 731366 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 731502 T2668 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@437a5 name:ZooKeeperConnection Watcher:127.0.0.1:55955 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 731502 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 731525 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 731526 T2670 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1fe9d61 name:ZooKeeperConnection Watcher:127.0.0.1:55955 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 731527 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 731527 T2589 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 731529 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 731530 T2672 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12b71ce name:ZooKeeperConnection Watcher:127.0.0.1:55955/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 731530 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 731531 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 731532 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 731533 T2674 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1de5ff4 name:ZooKeeperConnection Watcher:127.0.0.1:55955/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 731534 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 731534 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 731536 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 731539 T2589 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:55955_solr
[junit4] 2> 731539 T2589 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 731541 T2589 oasc.Overseer.start Overseer (id=91369732301324291-127.0.0.1:55955_solr-n_0000000000) starting
[junit4] 2> 731542 T2589 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 731544 T2589 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 731547 T2589 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 731549 T2676 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 731550 T2589 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 731550 T2676 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
[junit4] 2> 731550 T2675 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 731553 T2589 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 731554 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 731556 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 731557 T2678 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@553609 name:ZooKeeperConnection Watcher:127.0.0.1:55955/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 731557 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 731558 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 731559 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes/node0
[junit4] 2> 731561 T2672 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 731561 T2678 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 731561 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 731562 T2680 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@180f6f1 name:ZooKeeperConnection Watcher:127.0.0.1:55955/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 731563 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 731564 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 731565 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 731568 T2672 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 731568 T2678 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 731568 T2680 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 731568 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 731569 T2682 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6bed86 name:ZooKeeperConnection Watcher:127.0.0.1:55955/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 731570 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 731571 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 731573 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 731575 T2672 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 731575 T2678 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 731575 T2682 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 731575 T2680 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 731575 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 731577 T2684 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c0e708 name:ZooKeeperConnection Watcher:127.0.0.1:55955/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 731577 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 731578 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 731579 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes/node3
[junit4] 2> 731582 T2678 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 731582 T2680 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 731582 T2672 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 731582 T2682 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 731582 T2684 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 731582 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 731583 T2686 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7bdca9 name:ZooKeeperConnection Watcher:127.0.0.1:55955/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 731584 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 731584 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 731586 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes/node4
[junit4] 2> 731588 T2680 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 731589 T2686 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 731589 T2672 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 731589 T2682 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 731589 T2684 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 731589 T2678 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 731589 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 731590 T2688 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e3a27e name:ZooKeeperConnection Watcher:127.0.0.1:55955/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 731591 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 731592 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 731593 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes/node5
[junit4] 2> 731596 T2686 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4] 2> 731596 T2682 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4] 2> 731596 T2684 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4] 2> 731596 T2672 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4] 2> 731597 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 731599 T2690 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f401ce name:ZooKeeperConnection Watcher:127.0.0.1:55955/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 731599 T2678 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4] 2> 731599 T2680 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4] 2> 731599 T2688 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4] 2> 731599 T2589 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 731600 T2589 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 731602 T2589 oascc.SolrZkClient.makePath makePath: /live_nodes/node6
[junit4] 2> 731605 T2682 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4] 2> 731605 T2686 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4] 2> 731605 T2672 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4] 2> 731605 T2688 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4] 2> 731605 T2678 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4] 2> 731605 T2680 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4] 2> 731605 T2684 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4] 2> 731606 T2589 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 731606 T2690 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4] 2> 731607 T2692 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.Connecti
[...truncated too long message...]
entCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 752342 T3114 oasc.LeaderElector$1.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:1468)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:259)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:256)
[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:256)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:92)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:137)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 747984 T3106 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 752341 T2589 oas.SolrTestCaseJ4.tearDown ###Ending testShardLeaderChange
[junit4] 2> 752341 T3098 oasc.LeaderElector$1.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:1468)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:259)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:256)
[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:256)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:92)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:137)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 752343 T3106 oasc.LeaderElector$1.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:1468)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:259)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:256)
[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:256)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:92)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:137)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 752344 T3106 oasc.LeaderElector$1.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:1468)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:259)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:256)
[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:256)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:92)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:137)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 752345 T2589 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> 752345 T2589 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 755345 T2589 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: test params are: codec=Lucene46: {}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=ko_KR, timezone=Mideast/Riyadh89
[junit4] 2> NOTE: Linux 3.8.0-36-generic i386/Oracle Corporation 1.7.0_51 (32-bit)/cpus=8,threads=1,free=199507816,total=295960576
[junit4] 2> NOTE: All tests run in this JVM: [TestJmxIntegration, BasicDistributedZk2Test, SolrCmdDistributorTest, HdfsDirectoryTest, FileUtilsTest, SolrTestCaseJ4Test, NotRequiredUniqueKeyTest, TestCollapseQParserPlugin, TestSweetSpotSimilarityFactory, ChaosMonkeyNothingIsSafeTest, TestXIncludeConfig, AddBlockUpdateTest, TestDefaultSimilarityFactory, DirectSolrSpellCheckerTest, BadCopyFieldTest, SuggesterWFSTTest, AliasIntegrationTest, PrimUtilsTest, TestDistributedSearch, AlternateDirectoryTest, TestWordDelimiterFilterFactory, TestStandardQParsers, NumericFieldsTest, TestRangeQuery, SolrXmlInZkTest, SpellCheckCollatorTest, SortByFunctionTest, HdfsCollectionsAPIDistributedZkTest, DisMaxRequestHandlerTest, TestDFRSimilarityFactory, TestIBSimilarityFactory, OpenCloseCoreStressTest, TestSchemaResource, TestNumberUtils, DirectSolrConnectionTest, TestSolrXml, RequestHandlersTest, TestIndexSearcher, TestCopyFieldCollectionResource, TestSchemaNameResource, TestClassNameShortening, IndexSchemaRuntimeFieldTest, ZkNodePropsTest, OutputWriterTest, TestBinaryResponseWriter, SuggesterTSTTest, JSONWriterTest, TestCollationField, ChaosMonkeySafeLeaderTest, ZkSolrClientTest, CursorMarkTest, TestDistribDocBasedVersion, TestFuzzyAnalyzedSuggestions, TestReload, TestAnalyzedSuggestions, TestCloudManagedSchema, TestIndexingPerformance, UniqFieldsUpdateProcessorFactoryTest, TestFieldTypeResource, BlockDirectoryTest, CurrencyFieldOpenExchangeTest, SolrIndexConfigTest, TestSchemaVersionResource, LeaderElectionIntegrationTest, DistributedQueryComponentCustomSortTest, HighlighterConfigTest, SolrRequestParserTest, TestInitQParser, DistanceFunctionTest, PluginInfoTest, SimplePostToolTest, IndexBasedSpellCheckerTest, FieldAnalysisRequestHandlerTest, TestLazyCores, AnalysisErrorHandlingTest, BadIndexSchemaTest, TestStressLucene, MultiTermTest, SpellingQueryConverterTest, TestRTGBase, TestFileDictionaryLookup, TestCSVLoader, TestOverriddenPrefixQueryForCustomFieldType, SolrCoreCheckLockOnStartupTest, TestHighlightDedupGrouping, BlockCacheTest, TestPartialUpdateDeduplication, HighlighterTest, TestCSVResponseWriter, TestCodecSupport, TestUtils, XmlUpdateRequestHandlerTest, OverseerTest]
[junit4] Completed on J1 in 55.29s, 9 tests, 1 error <<< FAILURES!
[...truncated 598 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:465: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:445: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/extra-targets.xml:37: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:189: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:490: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1274: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:907: There were test failures: 378 suites, 1618 tests, 1 error, 49 ignored (20 assumptions)
Total time: 50 minutes 16 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_51 -client -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure