lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Apache Jenkins Server <jenk...@builds.apache.org>
Subject [JENKINS] Lucene-Solr-NightlyTests-4.x - Build # 540 - Failure
Date Mon, 17 Mar 2014 23:32:48 GMT
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-4.x/540/

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([40419D9356C66DC9:44491260446382E8]: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:1617)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:826)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:862)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:876)
	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:359)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:783)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:443)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:835)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:737)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:771)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:782)
	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:359)
	at java.lang.Thread.run(Thread.java:724)
Caused by: org.apache.solr.common.SolrException: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
	at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:40)
	at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:122)
	... 45 more
Caused by: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:119)
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
	at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:783)
	at org.apache.solr.common.cloud.SolrZkClient$10.execute(SolrZkClient.java: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:34)
	... 46 more




Build Log:
[...truncated 10806 lines...]
   [junit4] Suite: org.apache.solr.cloud.OverseerTest
   [junit4]   2> 2173974 T3078 oas.SolrTestCaseJ4.buildSSLConfig Randomized ssl (true) and clientAuth (false)
   [junit4]   2> 2173974 T3078 oas.SolrTestCaseJ4.initCore ####initCore
   [junit4]   2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solrtest-OverseerTest-1395097455127
   [junit4]   2> 2173977 T3078 oas.SolrTestCaseJ4.initCore ####initCore end
   [junit4]   2> 2173983 T3078 oas.SolrTestCaseJ4.setUp ###Starting testStateChange
   [junit4]   2> 2173984 T3078 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   2> 2173985 T3079 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 2174085 T3078 oasc.ZkTestServer.run start zk server on port:17226
   [junit4]   2> 2174089 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2174098 T3085 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@49414ab name:ZooKeeperConnection Watcher:127.0.0.1:17226/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2174099 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2174101 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2174113 T3087 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@27a54c5a name:ZooKeeperConnection Watcher:127.0.0.1:17226 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2174114 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2174120 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2174123 T3089 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@669fd92c name:ZooKeeperConnection Watcher:127.0.0.1:17226 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2174127 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2174127 T3078 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 2174136 T3078 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 2174148 T3078 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 2174157 T3078 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 2174162 T3078 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 2174171 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2174175 T3091 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2edbd6ca name:ZooKeeperConnection Watcher:127.0.0.1:17226/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2174175 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2174178 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect
   [junit4]   2> 2174187 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 2174204 T3078 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:17226_solr
   [junit4]   2> 2174205 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 2174216 T3078 oasc.Overseer.start Overseer (id=91429106821169155-127.0.0.1:17226_solr-n_0000000000) starting
   [junit4]   2> 2174219 T3078 oascc.SolrZkClient.makePath makePath: /overseer/queue
   [junit4]   2> 2174234 T3078 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
   [junit4]   2> 2174245 T3078 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
   [junit4]   2> 2174250 T3093 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 2174252 T3093 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
   [junit4]   2> 2174253 T3092 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 2174257 T3092 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2174258 T3078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2174259 T3092 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "base_url":"http://127.0.0.1/solr",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "roles":"",
   [junit4]   2> 	  "state":"recovering"}
   [junit4]   2> 2174260 T3092 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 2174264 T3091 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2174266 T3085 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
   [junit4]   2> 2174310 T3078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2174313 T3091 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2174314 T3092 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2174315 T3092 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "base_url":"http://127.0.0.1/solr",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "roles":"",
   [junit4]   2> 	  "state":"active"}
   [junit4]   2> 2174315 T3092 oasc.Overseer$ClusterStateUpdater.updateState node=core_node1 is already registered
   [junit4]   2> 2174315 T3092 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 2174318 T3091 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2174423 T3085 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
   [junit4]   2> 2174471 T3078 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:17226 17226
   [junit4]   2> 2174731 T3078 oas.SolrTestCaseJ4.tearDown ###Ending testStateChange
   [junit4]   1> client port:0.0.0.0/0.0.0.0:0
   [junit4]   2> 2174741 T3078 oas.SolrTestCaseJ4.setUp ###Starting testDoubleAssignment
   [junit4]   2> 2174741 T3078 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   2> 2174742 T3095 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 2174843 T3078 oasc.ZkTestServer.run start zk server on port:17232
   [junit4]   2> 2174844 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2174851 T3101 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@30ed74ad name:ZooKeeperConnection Watcher:127.0.0.1:17232/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2174851 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2174852 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2174855 T3103 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d6636b3 name:ZooKeeperConnection Watcher:127.0.0.1:17232 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2174856 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2174896 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2174899 T3105 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@458f9d7a name:ZooKeeperConnection Watcher:127.0.0.1:17232 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2174899 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2174899 T3078 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 2174904 T3078 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 2174908 T3078 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 2174912 T3078 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 2174915 T3078 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 2174920 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2174922 T3107 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2136e1dd name:ZooKeeperConnection Watcher:127.0.0.1:17232/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2174923 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2174926 T3078 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 2174931 T3078 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
   [junit4]   2> 2174936 T3101 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 2174936 T3107 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 2174937 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2174939 T3109 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5bcb3421 name:ZooKeeperConnection Watcher:127.0.0.1:17232/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2174940 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2174944 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect
   [junit4]   2> 2174947 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 2174955 T3078 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:17232_solr
   [junit4]   2> 2174955 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 2174959 T3078 oasc.Overseer.start Overseer (id=91429106870124548-127.0.0.1:17232_solr-n_0000000000) starting
   [junit4]   2> 2174962 T3078 oascc.SolrZkClient.makePath makePath: /overseer/queue
   [junit4]   2> 2174968 T3078 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
   [junit4]   2> 2174974 T3078 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
   [junit4]   2> 2174977 T3111 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 2174978 T3111 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
   [junit4]   2> 2174979 T3110 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 2174982 T3110 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2174983 T3110 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> 2174983 T3110 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
   [junit4]   2> 2174983 T3110 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 2174988 T3109 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2174989 T3101 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> 2174989 T3107 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> 2175481 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 2175533 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2175567 T3109 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2175568 T3078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2175568 T3110 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2175573 T3107 oascc.ZkStateReader$3.process Updating live nodes... (0)
   [junit4]   2> 2175573 T3101 oascc.ZkStateReader$3.process Updating live nodes... (0)
   [junit4]   2> 2175585 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2175593 T3109 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2175595 T3113 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@276f1691 name:ZooKeeperConnection Watcher:127.0.0.1:17232/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2175595 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2175596 T3078 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 2175598 T3078 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
   [junit4]   2> 2175608 T3101 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 2175609 T3113 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 2175618 T3109 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2175618 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 2175619 T3110 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> 2175620 T3110 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 2175622 T3109 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2175625 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2175629 T3109 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2175632 T3109 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2175744 T3113 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> 2175744 T3101 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> 2175744 T3078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2175763 T3113 oascc.ZkStateReader$3.process Updating live nodes... (0)
   [junit4]   2> 2175763 T3101 oascc.ZkStateReader$3.process Updating live nodes... (0)
   [junit4]   2> 2175775 T3078 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:17232 17232
   [junit4]   2> 2175863 T3078 oas.SolrTestCaseJ4.tearDown ###Ending testDoubleAssignment
   [junit4]   1> client port:0.0.0.0/0.0.0.0:0
   [junit4]   2> 2175868 T3078 oas.SolrTestCaseJ4.setUp ###Starting testReplay
   [junit4]   2> 2175869 T3078 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   2> 2175869 T3114 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 2175970 T3078 oasc.ZkTestServer.run start zk server on port:17247
   [junit4]   2> 2175971 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2175974 T3120 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2fd7ad01 name:ZooKeeperConnection Watcher:127.0.0.1:17247/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2175974 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2175975 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2175977 T3122 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@183652ed name:ZooKeeperConnection Watcher:127.0.0.1:17247 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2175977 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2176046 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2176059 T3124 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9b83e3f name:ZooKeeperConnection Watcher:127.0.0.1:17247 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2176060 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2176060 T3078 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 2176077 T3078 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 2176081 T3078 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 2176092 T3078 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 2176099 T3078 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 2176102 T3078 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
   [junit4]   2> 2176115 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2176123 T3126 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2211d254 name:ZooKeeperConnection Watcher:127.0.0.1:17247/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2176123 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2176124 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect
   [junit4]   2> 2176126 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 2176143 T3078 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:17247_solr
   [junit4]   2> 2176143 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 2176147 T3078 oasc.Overseer.start Overseer (id=91429106943787011-127.0.0.1:17247_solr-n_0000000000) starting
   [junit4]   2> 2176149 T3078 oascc.SolrZkClient.makePath makePath: /overseer/queue
   [junit4]   2> 2176167 T3078 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
   [junit4]   2> 2176170 T3128 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 2176171 T3128 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
   [junit4]   2> 2176179 T3127 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2176179 T3127 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue.
   [junit4]   2> 2176180 T3127 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "base_url":"http://127.0.0.1/solr",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "shard":"s1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "roles":"",
   [junit4]   2> 	  "state":"recovering"}
   [junit4]   2> 2176182 T3120 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
   [junit4]   2> 2176184 T3127 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "base_url":"http://127.0.0.1/solr",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "shard":"s1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "core":"core2",
   [junit4]   2> 	  "roles":"",
   [junit4]   2> 	  "state":"recovering"}
   [junit4]   2> 2176193 T3120 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
   [junit4]   2> 2176195 T3127 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 2176196 T3127 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2176197 T3127 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "base_url":"http://127.0.0.1/solr",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "shard":"s1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "core":"core3",
   [junit4]   2> 	  "roles":"",
   [junit4]   2> 	  "state":"recovering"}
   [junit4]   2> 2176205 T3126 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2176206 T3120 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
   [junit4]   2> 2176281 T3115 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x144d249d1840003, likely client has closed socket
   [junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
   [junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
   [junit4]   2> 	at java.lang.Thread.run(Thread.java:724)
   [junit4]   2> 
   [junit4]   2> 2176284 T3078 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:17247 17247
   [junit4]   2> 2176413 T3078 oas.SolrTestCaseJ4.tearDown ###Ending testReplay
   [junit4]   1> client port:0.0.0.0/0.0.0.0:0
   [junit4]   2> 2176418 T3078 oas.SolrTestCaseJ4.setUp ###Starting testBadQueueItem
   [junit4]   2> 2176418 T3078 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   2> 2176419 T3129 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 2176520 T3078 oasc.ZkTestServer.run start zk server on port:17252
   [junit4]   2> 2176521 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2176525 T3135 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@41c268cf name:ZooKeeperConnection Watcher:127.0.0.1:17252 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2176525 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2176604 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2176613 T3137 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@66cb1cea name:ZooKeeperConnection Watcher:127.0.0.1:17252 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2176613 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2176614 T3078 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 2176624 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2176634 T3139 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4387e6f5 name:ZooKeeperConnection Watcher:127.0.0.1:17252/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2176634 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2176635 T3078 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 2176643 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2176652 T3141 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@68f2cce name:ZooKeeperConnection Watcher:127.0.0.1:17252/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2176653 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2176654 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect
   [junit4]   2> 2176661 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 2176672 T3078 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:17252_solr
   [junit4]   2> 2176672 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 2176675 T3078 oasc.Overseer.start Overseer (id=91429106979962883-127.0.0.1:17252_solr-n_0000000000) starting
   [junit4]   2> 2176686 T3078 oascc.SolrZkClient.makePath makePath: /overseer/queue
   [junit4]   2> 2176689 T3078 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
   [junit4]   2> 2176692 T3078 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
   [junit4]   2> 2176694 T3143 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 2176694 T3078 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 2176694 T3143 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
   [junit4]   2> 2176694 T3142 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 2176696 T3078 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 2176697 T3078 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 2176699 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2176701 T3145 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@62c524b8 name:ZooKeeperConnection Watcher:127.0.0.1:17252/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2176701 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2176702 T3078 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 2176704 T3078 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1
   [junit4]   2> 2176706 T3139 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 2176706 T3145 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 2176708 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2176709 T3142 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2176710 T3142 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> 2176710 T3142 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3]
   [junit4]   2> 2176710 T3142 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
   [junit4]   2> 2176712 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2176713 T3145 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> 2176713 T3139 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> 2177209 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
   [junit4]   2> 2177217 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
   [junit4]   2> 2177222 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2177239 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2177239 T3142 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2177259 T3142 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> 2177259 T3142 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
   [junit4]   2> 2177259 T3142 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
   [junit4]   2> 2177272 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2177432 T3139 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> 2177432 T3145 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> 2177740 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
   [junit4]   2> 2177766 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
   [junit4]   2> 2177771 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2177771 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2177772 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2177773 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2177773 T3142 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2177778 T3142 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> 2177778 T3142 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
   [junit4]   2> 2177778 T3142 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 2177790 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2177893 T3139 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> 2177893 T3145 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> 2178274 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 2178304 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2178320 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2178320 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2178320 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2178323 T3142 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2178329 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2178433 T3145 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> 2178433 T3139 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> 2178478 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2178478 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2178478 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2178489 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2178489 T3142 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2178492 T3142 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> 2178507 T3142 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> 2178517 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2178519 T3142 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> 2178519 T3142 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection2 with shards [shard1, shard2, shard3]
   [junit4]   2> 2178519 T3142 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
   [junit4]   2> 2178524 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2178628 T3139 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> 2178628 T3145 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> 2179004 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection2/leader_elect/shard2/election
   [junit4]   2> 2179187 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection2/leaders/shard2
   [junit4]   2> 2179203 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2179204 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2179204 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2179214 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2179214 T3142 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2179221 T3142 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> 2179222 T3142 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
   [junit4]   2> 2179222 T3142 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
   [junit4]   2> 2179231 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2179335 T3139 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> 2179335 T3145 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> 2179715 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection2/leader_elect/shard3/election
   [junit4]   2> 2179747 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection2/leaders/shard3
   [junit4]   2> 2179754 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2179755 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2179755 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2179775 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2179775 T3142 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2179783 T3142 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> 2179784 T3142 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
   [junit4]   2> 2179784 T3142 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 2179788 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2179896 T3145 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> 2179896 T3139 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> 2180272 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection2/leader_elect/shard1/election
   [junit4]   2> 2180278 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection2/leaders/shard1
   [junit4]   2> 2180282 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2180283 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2180283 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2180284 T3142 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2180286 T3141 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2180389 T3145 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> 2180389 T3139 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> 2180438 T3145 oascc.ZkStateReader$3.process Updating live nodes... (0)
   [junit4]   2> 2180440 T3078 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:17252 17252
   [junit4]   2> 2180642 T3078 oas.SolrTestCaseJ4.tearDown ###Ending testBadQueueItem
   [junit4]   1> client port:0.0.0.0/0.0.0.0:0
   [junit4]   2> 2180648 T3078 oas.SolrTestCaseJ4.setUp ###Starting testPlaceholders
   [junit4]   2> 2180648 T3078 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   2> 2180649 T3146 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 2180750 T3078 oasc.ZkTestServer.run start zk server on port:17276
   [junit4]   2> 2180751 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2180755 T3152 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@311b70a name:ZooKeeperConnection Watcher:127.0.0.1:17276/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2180755 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2180755 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2180757 T3154 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1e769cfa name:ZooKeeperConnection Watcher:127.0.0.1:17276 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2180757 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2180887 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2180897 T3156 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7f861004 name:ZooKeeperConnection Watcher:127.0.0.1:17276 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2180897 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2180898 T3078 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 2180900 T3078 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 2180908 T3078 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 2180910 T3078 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 2180912 T3078 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 2180914 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2180921 T3158 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@422dd2a3 name:ZooKeeperConnection Watcher:127.0.0.1:17276/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2180921 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2180922 T3078 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 2180924 T3078 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
   [junit4]   2> 2180926 T3152 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 2180926 T3158 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 2180927 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2180928 T3160 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2413b875 name:ZooKeeperConnection Watcher:127.0.0.1:17276/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2180928 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2180929 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect
   [junit4]   2> 2180931 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 2180941 T3078 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:17276_solr
   [junit4]   2> 2180941 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 2180949 T3078 oasc.Overseer.start Overseer (id=91429107257180164-127.0.0.1:17276_solr-n_0000000000) starting
   [junit4]   2> 2180951 T3078 oascc.SolrZkClient.makePath makePath: /overseer/queue
   [junit4]   2> 2180953 T3078 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
   [junit4]   2> 2180956 T3078 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
   [junit4]   2> 2180958 T3162 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 2180958 T3162 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
   [junit4]   2> 2180958 T3161 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 2180960 T3161 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2180960 T3161 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> 2180961 T3161 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3, shard4, shard5, shard6, shard7, shard8, shard9, shard10, shard11, shard12]
   [junit4]   2> 2180961 T3161 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
   [junit4]   2> 2180962 T3160 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2180963 T3158 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> 2180963 T3152 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> 2181460 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
   [junit4]   2> 2181482 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
   [junit4]   2> 2181486 T3160 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2181487 T3078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2181488 T3161 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2181490 T3158 oascc.ZkStateReader$3.process Updating live nodes... (0)
   [junit4]   2> 2181491 T3152 oascc.ZkStateReader$3.process Updating live nodes... (0)
   [junit4]   2> 2181492 T3078 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:17276 17276
   [junit4]   2> 2182589 T3078 oas.SolrTestCaseJ4.tearDown ###Ending testPlaceholders
   [junit4]   1> client port:0.0.0.0/0.0.0.0:0
   [junit4]   2> 2182596 T3078 oas.SolrTestCaseJ4.setUp ###Starting testOverseerFailure
   [junit4]   2> 2182596 T3078 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   2> 2182597 T3163 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 2182698 T3078 oasc.ZkTestServer.run start zk server on port:17292
   [junit4]   2> 2182699 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2182713 T3169 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@59fefba5 name:ZooKeeperConnection Watcher:127.0.0.1:17292 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2182714 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2182800 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2182810 T3171 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2e27ca5d name:ZooKeeperConnection Watcher:127.0.0.1:17292 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2182810 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2182811 T3078 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 2182830 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2182835 T3173 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ad974a4 name:ZooKeeperConnection Watcher:127.0.0.1:17292/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2182835 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2182836 T3078 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 2182844 T3078 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 2182854 T3078 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 2182857 T3078 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 2182862 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2182865 T3175 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9b749d9 name:ZooKeeperConnection Watcher:127.0.0.1:17292/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2182865 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2182867 T3078 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 2182871 T3078 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
   [junit4]   2> 2182875 T3175 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 2182875 T3173 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 2182876 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2182878 T3177 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@69557e67 name:ZooKeeperConnection Watcher:127.0.0.1:17292/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2182879 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2182880 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect
   [junit4]   2> 2182883 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 2182897 T3078 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:17292_solr
   [junit4]   2> 2182898 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 2182903 T3078 oasc.Overseer.start Overseer (id=91429107385040900-127.0.0.1:17292_solr-n_0000000000) starting
   [junit4]   2> 2182906 T3078 oascc.SolrZkClient.makePath makePath: /overseer/queue
   [junit4]   2> 2182917 T3078 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
   [junit4]   2> 2182923 T3078 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
   [junit4]   2> 2182927 T3179 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 2182929 T3179 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
   [junit4]   2> 2182930 T3178 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 2183932 T3177 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2183935 T3178 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2183936 T3178 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> 2183937 T3178 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
   [junit4]   2> 2183937 T3178 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 2183949 T3177 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2183951 T3175 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> 2183951 T3173 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> 2184433 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 2184466 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2184500 T3177 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2184503 T3178 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2184505 T3078 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2184517 T3177 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2184525 T3177 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2184526 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 2184528 T3178 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> 2184528 T3178 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 2184539 T3177 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2184654 T3175 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> 2184655 T3173 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> 2185716 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 2185729 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2185736 T3181 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@558de79b name:ZooKeeperConnection Watcher:127.0.0.1:17292/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2185736 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2185745 T3078 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:17292_solr
   [junit4]   2> 2185745 T3078 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 2185757 T3078 oasc.Overseer.start Overseer (id=91429107385040901-127.0.0.1:17292_solr-n_0000000001) starting
   [junit4]   2> 2185771 T3183 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 2185772 T3183 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
   [junit4]   2> 2185772 T3182 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 2185774 T3182 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2185774 T3182 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> 2185775 T3182 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 2185784 T3181 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2185784 T3175 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> 2185785 T3173 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> 2185838 T3181 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2185838 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 2185839 T3182 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 2185844 T3078 oasc.LeaderElector.checkIfIamLeader WARN Failed setting watch org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election/91429107385040899-node1_core1-n_0000000002
   [junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:111)
   [junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
   [junit4]   2> 	at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java: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:1617)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:826)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:862)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:876)
   [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:359)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:783)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:443)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:835)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:737)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:771)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:782)
   [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:359)
   [junit4]   2> 	at java.lang.Thread.run(Thread.java:724)
   [junit4]   2> 
   [junit4]   2> 2185846 T3182 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:724)
   [junit4]   2> 	
   [junit4]   2> 2185846 T3175 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2185847 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2185848 T3181 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2185852 T3181 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2185853 T3175 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2185853 T3182 oasc.Overseer$ClusterStateUpdater.setShardLeader ERROR Could not mark shard leader for non existing collection:collection1
   [junit4]   2> 2185855 T3181 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2185858 T3181 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2185858 T3182 oasc.Overseer$ClusterStateUpdater.setShardLeader ERROR Could not mark shard leader for non existing collection:collection1
   [junit4]   2> 2185870 T3181 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 2185973 T3173 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> 2185973 T3175 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> 2186851 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2187855 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2188861 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2189873 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2190879 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2191883 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2192886 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2193892 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2194896 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2195900 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2196904 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2197910 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2198914 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2199918 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2200935 T3078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 2200943 T3175 oascc.ZkStateReader$3.process Updating live nodes... (0)
   [junit4]   2> 2200956 T3173 oascc.ZkStateReader$3.process Updating live nodes... (0)
   [junit4]   2> 2200961 T3078 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:17292 17292
   [junit4]   2> 2202179 T3078 oas.SolrTestCaseJ4.tearDown ###Ending testOverseerFailure
   [junit4]   1> client port:0.0.0.0/0.0.0.0:0
   [junit4]   2> NOTE: download the large Jenkins line-docs file by running 'ant get-jenkins-line-docs' in the lucene directory.
   [junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=OverseerTest -Dtests.method=testOverseerFailure -Dtests.seed=40419D9356C66DC9 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/hudson/lucene-data/enwiki.random.lines.txt -Dtests.locale=es_GT -Dtests.timezone=Indian/Comoro -Dtests.file.encoding=UTF-8
   [junit4] ERROR   19.6s J0 | OverseerTest.testOverseerFailure <<<
   [junit4]    > Throwable #1: org.apache.solr.common.SolrException: Could not register as the leader because creating the ephemeral registration node in ZooKeeper failed
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([40419D9356C66DC9:44491260446382E8]: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:724)
   [junit4]    > Caused by: org.apache.solr.common.SolrException: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
   [junit4]    > 	at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:40)
   [junit4]    > 	at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:122)
   [junit4]    > 	... 45 more
   [junit4]    > Caused by: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
   [junit4]    > 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:119)
   [junit4]    > 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
   [junit4]    > 	at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:783)
   [junit4]    > 	at org.apache.solr.common.cloud.SolrZkClient$10.execute(SolrZkClient.java: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:34)
   [junit4]    > 	... 46 more
   [junit4]   2> 2202215 T3078 oas.SolrTestCaseJ4.setUp ###Starting testShardLeaderChange
   [junit4]   2> 2202215 T3078 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   2> 2202216 T3184 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 2202317 T3078 oasc.ZkTestServer.run start zk server on port:17369
   [junit4]   2> 2202318 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2202327 T3190 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5e4a24cf name:ZooKeeperConnection Watcher:127.0.0.1:17369/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2202328 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2202329 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2202332 T3192 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2a9e0ea6 name:ZooKeeperConnection Watcher:127.0.0.1:17369 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2202333 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2202561 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2202564 T3194 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d2f8fed name:ZooKeeperConnection Watcher:127.0.0.1:17369 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2202565 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2202565 T3078 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 2202569 T3078 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 2202583 T3195 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2202584 T3078 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 2202587 T3198 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7fa99c02 name:ZooKeeperConnection Watcher:127.0.0.1:17369/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2202587 T3195 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2202667 T3199 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@584188c8 name:ZooKeeperConnection Watcher:127.0.0.1:17369/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 2202667 T3195 oascc.SolrZkClient.makePath makePath: /overseer_elect
   [junit4]   2> 2202667 T3078 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 2202669 T3078 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 2202671 T3195 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 2202692 T3078 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 2202737 T3078 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 2202739 T3195 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:17369_solr
   [junit4]   2> 2202739 T3195 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 2202741 T3078 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
   [junit4]   2> 2202742 T3195 oasc.Overseer.start Overseer (id=91429108671053827-127.0.0.1:17369_solr-n_0000000000) starting
   [junit4]   2> 2202752 T3199 oascc.ZkStateReader$3.process Updating live nodes..

[...truncated too long message...]

 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
   [junit4]   2> 2225903 T3551 oasc.LeaderElector$1.process WARN  org.apache.solr.common.SolrException: org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer/queue
   [junit4]   2> 	at org.apache.solr.cloud.DistributedQueue.<init>(DistributedQueue.java:63)
   [junit4]   2> 	at org.apache.solr.cloud.Overseer.getInQueue(Overseer.java:1130)
   [junit4]   2> 	at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:146)
   [junit4]   2> 	at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:164)
   [junit4]   2> 	at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:108)
   [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> Caused by: org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer/queue
   [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.exists(ZooKeeper.java:1041)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$4.execute(SolrZkClient.java:225)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$4.execute(SolrZkClient.java:222)
   [junit4]   2> 	at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.exists(SolrZkClient.java:222)
   [junit4]   2> 	at org.apache.solr.common.cloud.ZkCmdExecutor.ensureExists(ZkCmdExecutor.java:100)
   [junit4]   2> 	at org.apache.solr.common.cloud.ZkCmdExecutor.ensureExists(ZkCmdExecutor.java:94)
   [junit4]   2> 	at org.apache.solr.cloud.DistributedQueue.<init>(DistributedQueue.java:61)
   [junit4]   2> 	... 8 more
   [junit4]   2> 
   [junit4]   2> 2225904 T3551 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
   [junit4]   2> 2225905 T3553 oasc.LeaderElector$1.process WARN  org.apache.solr.common.SolrException: Could not register as the leader because creating the ephemeral registration node in ZooKeeper failed
   [junit4]   2> 	at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:135)
   [junit4]   2> 	at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:164)
   [junit4]   2> 	at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:108)
   [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> Caused by: org.apache.solr.common.SolrException: org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leaders/shard12
   [junit4]   2> 	at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:40)
   [junit4]   2> 	at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:122)
   [junit4]   2> 	... 6 more
   [junit4]   2> Caused by: org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leaders/shard12
   [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.exists(ZooKeeper.java:1041)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$3.execute(SolrZkClient.java:208)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$3.execute(SolrZkClient.java:205)
   [junit4]   2> 	at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.exists(SolrZkClient.java:205)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:455)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:385)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:372)
   [junit4]   2> 	at org.apache.solr.cloud.ShardLeaderElectionContextBase$1.execute(ElectionContext.java:127)
   [junit4]   2> 	at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:34)
   [junit4]   2> 	... 7 more
   [junit4]   2> 
   [junit4]   2> 2225906 T3553 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
   [junit4]   2> 2225906 T3553 oasc.LeaderElector$1.process WARN  org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard11/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> 2227474 T3078 oas.SolrTestCaseJ4.deleteCore ###deleteCore
   [junit4]   2> NOTE: test params are: codec=Lucene46: {}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=es_GT, timezone=Indian/Comoro
   [junit4]   2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=16,threads=1,free=49745824,total=300613632
   [junit4]   2> NOTE: All tests run in this JVM: [LegacyHTMLStripCharFilterTest, TestSolrXmlPersistence, TestInfoStreamLogging, TestDocumentBuilder, TestConfig, QueryElevationComponentTest, ShardRoutingTest, FileBasedSpellCheckerTest, PreAnalyzedUpdateProcessorTest, TestComplexPhraseQParserPlugin, TestJoin, CircularListTest, DateMathParserTest, UpdateRequestProcessorFactoryTest, SimpleFacetsTest, ClusterStateUpdateTest, TestCollationKeyRangeQueries, EchoParamsTest, EnumFieldTest, TestDocSet, SliceStateTest, TestSchemaVersionResource, CursorPagingTest, SolrInfoMBeanTest, TermVectorComponentTest, TestGroupingSearch, TestLRUCache, ParsingFieldUpdateProcessorsTest, TestFileDictionaryLookup, MBeansHandlerTest, TestCharFilters, SuggesterFSTTest, CoreAdminHandlerTest, TestSimpleQParserPlugin, TestSort, TestRemoteStreaming, HdfsChaosMonkeySafeLeaderTest, TestRealTimeGet, SyncSliceTest, BinaryUpdateRequestHandlerTest, HdfsBasicDistributedZkTest, MoreLikeThisHandlerTest, DeleteShardTest, SchemaVersionSpecificBehaviorTest, SpellPossibilityIteratorTest, TestValueSourceCache, TestLMDirichletSimilarityFactory, TestLuceneMatchVersion, TestExpandComponent, TestTrie, TestInitQParser, TestJmxMonitoredMap, TestCloudManagedSchemaAddField, CustomCollectionTest, TermsComponentTest, BasicDistributedZkTest, TestCoreContainer, DocumentBuilderTest, UpdateParamsTest, TestPseudoReturnFields, LoggingHandlerTest, PeerSyncTest, TestBadConfig, TestMergePolicyConfig, TestSolrDeletionPolicy1, OverseerTest]
   [junit4] Completed on J0 in 53.55s, 9 tests, 1 error <<< FAILURES!

[...truncated 654 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:474: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:447: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:45: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/extra-targets.xml:37: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build.xml:189: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/common-build.xml:490: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:1276: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:908: There were test failures: 371 suites, 1590 tests, 1 error, 35 ignored (7 assumptions)

Total time: 130 minutes 40 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message