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-Tests-4.x-Java7 - Build # 1820 - Failure
Date Thu, 19 Dec 2013 02:31:23 GMT
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java7/1820/

2 tests failed.
REGRESSION:  org.apache.solr.cloud.ChaosMonkeyNothingIsSafeTest.testDistribSearch

Error Message:
There were expected update fails expected:<0> but was:<1>

Stack Trace:
java.lang.AssertionError: There were expected update fails expected:<0> but was:<1>
	at __randomizedtesting.SeedInfo.seed([9E383FAE8CE20A23:1FDEB1B6FBBD6A1F]:0)
	at org.junit.Assert.fail(Assert.java:93)
	at org.junit.Assert.failNotEquals(Assert.java:647)
	at org.junit.Assert.assertEquals(Assert.java:128)
	at org.junit.Assert.assertEquals(Assert.java:472)
	at org.apache.solr.cloud.ChaosMonkeyNothingIsSafeTest.doTest(ChaosMonkeyNothingIsSafeTest.java:202)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:849)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at java.lang.Thread.run(Thread.java:724)


REGRESSION:  org.apache.solr.cloud.OverseerTest.testOverseerFailure

Error Message:
KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1

Stack Trace:
org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
	at __randomizedtesting.SeedInfo.seed([9E383FAE8CE20A23:9A30B05D9E47E502]:0)
	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:424)
	at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
	at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:421)
	at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:378)
	at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:365)
	at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:102)
	at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:165)
	at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:109)
	at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:157)
	at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:277)
	at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:153)
	at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:584)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at java.lang.Thread.run(Thread.java:724)




Build Log:
[...truncated 10060 lines...]
   [junit4] Suite: org.apache.solr.cloud.OverseerTest
   [junit4]   2> 405792 T1665 oas.SolrTestCaseJ4.initCore ####initCore
   [junit4]   2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./solrtest-OverseerTest-1387418097130
   [junit4]   2> 405793 T1665 oas.SolrTestCaseJ4.initCore ####initCore end
   [junit4]   2> 405798 T1665 oas.SolrTestCaseJ4.setUp ###Starting testReplay
   [junit4]   2> 405798 T1665 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   2> 405799 T1666 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 405900 T1665 oasc.ZkTestServer.run start zk server on port:33066
   [junit4]   2> 405901 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 405906 T1672 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6ee120c3 name:ZooKeeperConnection Watcher:127.0.0.1:33066/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 405906 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 405907 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 405909 T1674 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4f66fd33 name:ZooKeeperConnection Watcher:127.0.0.1:33066 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 405909 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 405929 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 405931 T1676 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@31d2725c name:ZooKeeperConnection Watcher:127.0.0.1:33066 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 405932 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 405932 T1665 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 405944 T1665 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 405949 T1665 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 405951 T1665 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 405958 T1665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 405963 T1665 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
   [junit4]   2> 405974 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 405976 T1678 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2e064b57 name:ZooKeeperConnection Watcher:127.0.0.1:33066/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 405976 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 405978 T1665 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 406052 T1665 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 406072 T1665 oasc.Overseer.start Overseer (id=90925832414363651-127.0.0.1:33066_solr-n_0000000000) starting
   [junit4]   2> 406101 T1665 oascc.SolrZkClient.makePath makePath: /overseer/queue
   [junit4]   2> 406155 T1665 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
   [junit4]   2> 406158 T1680 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 406169 T1679 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 406170 T1679 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue.
   [junit4]   2> 406170 T1679 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> 406188 T1672 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> 406192 T1679 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> 406252 T1672 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> 406255 T1679 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 406257 T1679 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 406258 T1679 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> 406295 T1678 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 406356 T1672 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> 406425 T1665 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:33066 33066
   [junit4]   2> 406667 T1665 oas.SolrTestCaseJ4.tearDown ###Ending testReplay
   [junit4]   1> client port:0.0.0.0/0.0.0.0:0
   [junit4]   2> 406674 T1665 oas.SolrTestCaseJ4.setUp ###Starting testPlaceholders
   [junit4]   2> 406675 T1665 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   2> 406676 T1681 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 406777 T1665 oasc.ZkTestServer.run start zk server on port:33071
   [junit4]   2> 406778 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 406785 T1687 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4446b3d9 name:ZooKeeperConnection Watcher:127.0.0.1:33071/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 406785 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 406786 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 406788 T1689 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c98bf3d name:ZooKeeperConnection Watcher:127.0.0.1:33071 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 406789 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 406841 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 406843 T1691 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d2b1ad5 name:ZooKeeperConnection Watcher:127.0.0.1:33071 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 406843 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 406844 T1665 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 406854 T1665 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 406857 T1665 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 406860 T1665 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 406862 T1665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 406865 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 406867 T1693 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6ef36079 name:ZooKeeperConnection Watcher:127.0.0.1:33071/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 406868 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 406869 T1665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 406872 T1665 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
   [junit4]   2> 406875 T1687 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 406875 T1693 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 406876 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 406877 T1695 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19e264b name:ZooKeeperConnection Watcher:127.0.0.1:33071/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 406878 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 406879 T1665 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 406885 T1665 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 406887 T1665 oasc.Overseer.start Overseer (id=90925832471969796-127.0.0.1:33071_solr-n_0000000000) starting
   [junit4]   2> 406890 T1665 oascc.SolrZkClient.makePath makePath: /overseer/queue
   [junit4]   2> 406893 T1665 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
   [junit4]   2> 406897 T1665 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
   [junit4]   2> 406900 T1697 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 406901 T1696 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 406903 T1696 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 406904 T1696 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> 406905 T1696 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3, shard4, shard5, shard6, shard7, shard8, shard9, shard10, shard11, shard12]
   [junit4]   2> 406905 T1696 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard10
   [junit4]   2> 406908 T1695 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 406909 T1693 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> 406909 T1687 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> 407403 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard10/election
   [junit4]   2> 407435 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard10
   [junit4]   2> 407442 T1695 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 407442 T1665 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 407444 T1696 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 407447 T1687 oascc.ZkStateReader$3.process Updating live nodes... (0)
   [junit4]   2> 407447 T1693 oascc.ZkStateReader$3.process Updating live nodes... (0)
   [junit4]   2> 407450 T1665 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:33071 33071
   [junit4]   2> 408521 T1665 oas.SolrTestCaseJ4.tearDown ###Ending testPlaceholders
   [junit4]   1> client port:0.0.0.0/0.0.0.0:0
   [junit4]   2> 408527 T1665 oas.SolrTestCaseJ4.setUp ###Starting testShardAssignment
   [junit4]   2> 408528 T1665 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   2> 408529 T1698 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 408630 T1665 oasc.ZkTestServer.run start zk server on port:33077
   [junit4]   2> 408631 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 408635 T1704 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5511c5a6 name:ZooKeeperConnection Watcher:127.0.0.1:33077 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 408635 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 408669 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 408671 T1706 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@396cec41 name:ZooKeeperConnection Watcher:127.0.0.1:33077 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 408671 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 408672 T1665 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 408676 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 408678 T1708 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@67d993fc name:ZooKeeperConnection Watcher:127.0.0.1:33077/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 408678 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 408678 T1665 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 408681 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 408683 T1710 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7542cca3 name:ZooKeeperConnection Watcher:127.0.0.1:33077/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 408683 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 408684 T1665 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 408690 T1665 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 408693 T1665 oasc.Overseer.start Overseer (id=90925832593473539-127.0.0.1:33077_solr-n_0000000000) starting
   [junit4]   2> 408695 T1665 oascc.SolrZkClient.makePath makePath: /overseer/queue
   [junit4]   2> 408699 T1665 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
   [junit4]   2> 408703 T1665 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
   [junit4]   2> 408706 T1712 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 408706 T1665 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 408707 T1711 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 408709 T1665 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 408711 T1665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 408714 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 408716 T1714 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2521bcf2 name:ZooKeeperConnection Watcher:127.0.0.1:33077/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 408716 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 408718 T1665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 408720 T1665 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1
   [junit4]   2> 408723 T1708 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 408723 T1714 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 408726 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 408728 T1711 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 408728 T1711 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> 408729 T1711 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3]
   [junit4]   2> 408729 T1711 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
   [junit4]   2> 408733 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 408734 T1714 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> 408734 T1708 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> 409227 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
   [junit4]   2> 409248 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
   [junit4]   2> 409255 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 409258 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 409258 T1711 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 409263 T1711 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> 409263 T1711 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
   [junit4]   2> 409263 T1711 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
   [junit4]   2> 409266 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 409369 T1708 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> 409369 T1714 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> 409759 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
   [junit4]   2> 409776 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
   [junit4]   2> 409782 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 409783 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 409783 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 409785 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 409785 T1711 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 409790 T1711 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> 409790 T1711 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
   [junit4]   2> 409790 T1711 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 409793 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 409896 T1714 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> 409896 T1708 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> 410286 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 410304 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 410317 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 410318 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 410318 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 410320 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 410320 T1711 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 410325 T1711 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"active",
   [junit4]   2> 	  "node_name":"127.0.0.1",
   [junit4]   2> 	  "core":"core4",
   [junit4]   2> 	  "core_node_name":"node4",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"3",
   [junit4]   2> 	  "base_url":"http://127.0.0.1/solr/"}
   [junit4]   2> 410325 T1711 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
   [junit4]   2> 410325 T1711 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
   [junit4]   2> 410328 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 410431 T1708 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> 410432 T1714 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> 410821 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
   [junit4]   2> 410839 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 410840 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 410840 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 410841 T1711 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 410842 T1711 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"active",
   [junit4]   2> 	  "node_name":"127.0.0.1",
   [junit4]   2> 	  "core":"core5",
   [junit4]   2> 	  "core_node_name":"node5",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"3",
   [junit4]   2> 	  "base_url":"http://127.0.0.1/solr/"}
   [junit4]   2> 410843 T1711 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
   [junit4]   2> 410843 T1711 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
   [junit4]   2> 410846 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 410950 T1714 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> 410950 T1708 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> 411340 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
   [junit4]   2> 411426 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 411426 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 411427 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 411428 T1711 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 411429 T1711 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"active",
   [junit4]   2> 	  "node_name":"127.0.0.1",
   [junit4]   2> 	  "core":"core6",
   [junit4]   2> 	  "core_node_name":"node6",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"3",
   [junit4]   2> 	  "base_url":"http://127.0.0.1/solr/"}
   [junit4]   2> 411429 T1711 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
   [junit4]   2> 411429 T1711 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 411433 T1710 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 411540 T1708 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> 411540 T1714 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> 411927 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 411950 T1714 oascc.ZkStateReader$3.process Updating live nodes... (0)
   [junit4]   2> 411959 T1665 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:33077 33077
   [junit4]   2> 412194 T1665 oas.SolrTestCaseJ4.tearDown ###Ending testShardAssignment
   [junit4]   1> client port:0.0.0.0/0.0.0.0:0
   [junit4]   2> 412202 T1665 oas.SolrTestCaseJ4.setUp ###Starting testShardLeaderChange
   [junit4]   2> 412202 T1665 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   2> 412203 T1715 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 412304 T1665 oasc.ZkTestServer.run start zk server on port:33083
   [junit4]   2> 412305 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 412309 T1721 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3f71d892 name:ZooKeeperConnection Watcher:127.0.0.1:33083/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 412309 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 412310 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 412312 T1723 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@33758f41 name:ZooKeeperConnection Watcher:127.0.0.1:33083 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 412312 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 412375 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 412377 T1725 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@74888272 name:ZooKeeperConnection Watcher:127.0.0.1:33083 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 412377 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 412378 T1665 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 412381 T1665 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 412385 T1726 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 412385 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 412387 T1729 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7c3a0e14 name:ZooKeeperConnection Watcher:127.0.0.1:33083/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 412387 T1726 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 412388 T1730 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@477282c3 name:ZooKeeperConnection Watcher:127.0.0.1:33083/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 412388 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 412388 T1726 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 412389 T1665 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 412392 T1665 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 412395 T1726 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 412395 T1665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 412398 T1726 oasc.Overseer.start Overseer (id=90925832834646019-127.0.0.1:33083_solr-n_0000000000) starting
   [junit4]   2> 412398 T1665 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
   [junit4]   2> 412400 T1726 oascc.SolrZkClient.makePath makePath: /overseer/queue
   [junit4]   2> 412401 T1730 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 412414 T1726 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
   [junit4]   2> 412418 T1726 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
   [junit4]   2> 412428 T1732 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 412428 T1726 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
   [junit4]   2> 412430 T1726 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 412432 T1734 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@67a1ad06 name:ZooKeeperConnection Watcher:127.0.0.1:33083/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 412433 T1726 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 412441 T1726 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 412444 T1726 oasc.Overseer.start Overseer (id=90925832834646021-127.0.0.1:33083_solr-n_0000000001) starting
   [junit4]   2> 412449 T1736 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 412450 T1735 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 412452 T1735 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 412453 T1735 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state1",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 412453 T1735 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
   [junit4]   2> 412453 T1735 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 412456 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 412457 T1730 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> 412906 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 412934 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 412950 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 412961 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 412961 T1735 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 412961 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 412966 T1735 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state2",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 412966 T1735 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 412969 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 412969 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 412971 T1738 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2fa99c9a name:ZooKeeperConnection Watcher:127.0.0.1:33083/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 412971 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 412972 T1665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 412975 T1665 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
   [junit4]   2> 412978 T1730 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 412979 T1738 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 412981 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 412981 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 412982 T1735 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state1",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 412983 T1735 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 412986 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 412988 T1665 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 413089 T1738 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 413089 T1730 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 413190 T1665 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 413194 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 413195 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 413195 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 413196 T1735 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 413197 T1735 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state2",
   [junit4]   2> 	  "node_name":"node2",
   [junit4]   2> 	  "core":"core4",
   [junit4]   2> 	  "core_node_name":"node2",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node2/solr/"}
   [junit4]   2> 413197 T1735 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
   [junit4]   2> 413198 T1735 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 413207 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 413311 T1730 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 413311 T1738 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 413451 T1714 oasc.LeaderElector$1.process WARN  org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard3/election
   [junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
   [junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
   [junit4]   2> 	at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:252)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:249)
   [junit4]   2> 	at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:249)
   [junit4]   2> 	at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:93)
   [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:138)
   [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> 413452 T1714 oasc.LeaderElector$1.process WARN  org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election
   [junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
   [junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
   [junit4]   2> 	at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:252)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:249)
   [junit4]   2> 	at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:249)
   [junit4]   2> 	at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:93)
   [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:138)
   [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> 413452 T1714 oasc.LeaderElector$1.process WARN  org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
   [junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
   [junit4]   2> 	at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:252)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:249)
   [junit4]   2> 	at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:249)
   [junit4]   2> 	at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:93)
   [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:138)
   [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> 413695 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 413723 T1738 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 413723 T1730 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 413724 T1665 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 413734 T1738 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 413746 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 413746 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 413746 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 413748 T1735 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 413751 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 413855 T1738 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> 413930 T1732 oasc.OverseerCollectionProcessor.amILeader  org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
   [junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
   [junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
   [junit4]   2> 	at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1151)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:269)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:266)
   [junit4]   2> 	at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:266)
   [junit4]   2> 	at org.apache.solr.cloud.OverseerCollectionProcessor.amILeader(OverseerCollectionProcessor.java:204)
   [junit4]   2> 	at org.apache.solr.cloud.OverseerCollectionProcessor.run(OverseerCollectionProcessor.java:163)
   [junit4]   2> 	at java.lang.Thread.run(Thread.java:724)
   [junit4]   2> 
   [junit4]   2> 413930 T1731 oasc.Overseer$ClusterStateUpdater.run WARN Solr cannot talk to ZK, exiting Overseer work queue loop org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer/queue-work
   [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:252)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:249)
   [junit4]   2> 	at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:249)
   [junit4]   2> 	at org.apache.solr.cloud.DistributedQueue.orderedChildren(DistributedQueue.java:89)
   [junit4]   2> 	at org.apache.solr.cloud.DistributedQueue.element(DistributedQueue.java:131)
   [junit4]   2> 	at org.apache.solr.cloud.DistributedQueue.peek(DistributedQueue.java:325)
   [junit4]   2> 	at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:105)
   [junit4]   2> 	at java.lang.Thread.run(Thread.java:724)
   [junit4]   2> 
   [junit4]   2> 413930 T1732 oasc.OverseerCollectionProcessor.amILeader According to ZK I (id=90925832834646019-127.0.0.1:33083_solr-n_0000000000) am no longer a leader.
   [junit4]   2> 413936 T1665 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 413938 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 413940 T1740 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2036dd62 name:ZooKeeperConnection Watcher:127.0.0.1:33083/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 413940 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 413942 T1665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 413945 T1665 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
   [junit4]   2> 413948 T1738 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 413948 T1740 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 413957 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 413957 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 413958 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 413958 T1734 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 413960 T1735 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 413961 T1735 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state1",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 413962 T1735 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 413966 T1726 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
   [junit4]   2> 413972 T1726 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 413974 T1742 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4e476310 name:ZooKeeperConnection Watcher:127.0.0.1:33083/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 413974 T1740 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 413975 T1726 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 413974 T1738 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 413977 T1740 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 413978 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 413979 T1726 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 413982 T1726 oasc.Overseer.start Overseer (id=90925832834646024-127.0.0.1:33083_solr-n_0000000002) starting
   [junit4]   2> 413986 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 413988 T1744 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@573ee865 name:ZooKeeperConnection Watcher:127.0.0.1:33083/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 413988 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 413988 T1746 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 413990 T1665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 413990 T1745 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 413991 T1745 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue.
   [junit4]   2> 413992 T1745 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state1",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 413992 T1745 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 413993 T1665 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
   [junit4]   2> 413993 T1744 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> 413994 T1740 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> 413996 T1740 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 413996 T1744 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 413996 T1745 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 413999 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 413999 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 413999 T1745 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414000 T1745 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state1",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 414000 T1745 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 414005 T1740 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 414005 T1744 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 414006 T1665 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414009 T1745 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414010 T1745 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state2",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 414010 T1745 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 414013 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414017 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414018 T1745 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state1",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 414019 T1745 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 414022 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414124 T1740 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 414124 T1744 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 414209 T1665 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414213 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414213 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 414213 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414214 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414215 T1745 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414216 T1745 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state2",
   [junit4]   2> 	  "node_name":"node2",
   [junit4]   2> 	  "core":"core4",
   [junit4]   2> 	  "core_node_name":"node2",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node2/solr/"}
   [junit4]   2> 414216 T1745 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 414232 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414234 T1744 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 414234 T1740 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 414236 T1665 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414237 T1744 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 414242 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414246 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414349 T1744 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> 414439 T1665 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414441 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 414443 T1748 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8b21056 name:ZooKeeperConnection Watcher:127.0.0.1:33083/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 414444 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 414446 T1665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 414449 T1665 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
   [junit4]   2> 414452 T1744 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 414452 T1748 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 414462 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414462 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 414462 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414463 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414464 T1745 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414465 T1745 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state1",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 414465 T1745 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 414477 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414478 T1748 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 414479 T1744 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 414481 T1748 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 414482 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414482 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 414483 T1745 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state2",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 414483 T1745 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 414494 T1726 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
   [junit4]   2> 414496 T1742 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414497 T1726 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 414499 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 414500 T1750 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@65405c9c name:ZooKeeperConnection Watcher:127.0.0.1:33083/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 414500 T1726 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 414508 T1752 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3d65ca0e name:ZooKeeperConnection Watcher:127.0.0.1:33083/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 414508 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 414509 T1665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 414510 T1726 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 414518 T1665 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
   [junit4]   2> 414518 T1726 oasc.Overseer.start Overseer (id=90925832834646027-127.0.0.1:33083_solr-n_0000000003) starting
   [junit4]   2> 414530 T1748 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 414530 T1752 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 414532 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 414533 T1754 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 414535 T1753 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414536 T1753 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue.
   [junit4]   2> 414537 T1753 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state1",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 414538 T1753 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 414539 T1748 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 414539 T1665 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414539 T1752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 414542 T1753 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state2",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 414543 T1753 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 414544 T1748 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 414544 T1752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 414546 T1753 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 414548 T1753 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414552 T1750 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414553 T1748 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 414553 T1752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 414557 T1753 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414558 T1753 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state1",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 414558 T1753 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 414561 T1750 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414665 T1752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 414665 T1748 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 414741 T1665 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414745 T1750 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414745 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 414745 T1750 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414746 T1750 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414748 T1753 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414748 T1753 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state2",
   [junit4]   2> 	  "node_name":"node2",
   [junit4]   2> 	  "core":"core4",
   [junit4]   2> 	  "core_node_name":"node2",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node2/solr/"}
   [junit4]   2> 414749 T1753 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 414765 T1750 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414767 T1748 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 414767 T1752 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 414769 T1665 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414775 T1752 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 414780 T1750 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414784 T1750 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414888 T1752 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> 414976 T1665 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 414978 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 414980 T1756 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5af64d52 name:ZooKeeperConnection Watcher:127.0.0.1:33083/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 414981 T1665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 414983 T1665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 414986 T1665 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
   [junit4]   2> 414989 T1752 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 414989 T1756 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 414998 T1750 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414998 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 414998 T1750 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 414999 T1750 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 415000 T1753 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 415000 T1753 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state1",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 415001 T1753 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 415004 T1750 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 415006 T1756 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 415006 T1752 oascc.ZkStateReader$3.process Updating live nodes... (1)
   [junit4]   2> 415008 T1756 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 415009 T1750 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 415009 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 415011 T1753 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"state2",
   [junit4]   2> 	  "node_name":"node1",
   [junit4]   2> 	  "core":"core1",
   [junit4]   2> 	  "core_node_name":"node1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "base_url":"http://node1/solr/"}
   [junit4]   2> 415011 T1753 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
   [junit4]   2> 415015 T1750 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 415017 T1665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 415019 T1758 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@44f8e47a name:ZooKeeperConnection Watcher:127.0.0.1:33083/sol

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

>     DATA: ...supressed...
   [junit4]   1>     /solr/configs/conf1/currency.xml (0)
   [junit4]   1>     DATA: ...supressed...
   [junit4]   1>     /solr/configs/conf1/open-exchange-rates.json (0)
   [junit4]   1>     DATA:
   [junit4]   1>         {
   [junit4]   1>           "disclaimer": "This data is not real, it was synthetically created to match currency.xml.  It is modeled after the data format available from openexchangerates.org.  See https://openexchangerates.org/documentation for details",
   [junit4]   1>           "license": "http://www.apache.org/licenses/LICENSE-2.0",
   [junit4]   1>           "timestamp": 1332070464,
   [junit4]   1>         
   [junit4]   1>         
   [junit4]   1>           "IMPORTANT NOTE": "In order for tests to work, this data must be kept in sync with ./currency.xml",
   [junit4]   1>         
   [junit4]   1>         
   [junit4]   1>           "base": "USD",
   [junit4]   1>           "rates": {
   [junit4]   1>             "USD": 1,
   [junit4]   1>             "JPY": 81.29,
   [junit4]   1>             "EUR": 2.5,
   [junit4]   1>             "GBP": 0.5,
   [junit4]   1>             "MXN": 2.0
   [junit4]   1>           }
   [junit4]   1>         }
   [junit4]   1>         
   [junit4]   1>     /solr/configs/conf1/solrconfig.xml (0)
   [junit4]   1>     DATA: ...supressed...
   [junit4]   1>     /solr/configs/conf1/mapping-ISOLatin1Accent.txt (0)
   [junit4]   1>     DATA: ...supressed...
   [junit4]   1>     /solr/configs/conf1/synonyms.txt (0)
   [junit4]   1>     DATA: ...supressed...
   [junit4]   1>     /solr/configs/conf1/schema.xml (0)
   [junit4]   1>     DATA: ...supressed...
   [junit4]   1>     /solr/configs/conf1/stopwords.txt (0)
   [junit4]   1>     DATA: ...supressed...
   [junit4]   1>   /solr/overseer (3)
   [junit4]   1>   DATA:
   [junit4]   1>       
   [junit4]   1>    /solr/overseer/queue-work (0)
   [junit4]   1>    /solr/overseer/collection-queue-work (0)
   [junit4]   1>    /solr/overseer/queue (0)
   [junit4]   1>   /solr/aliases.json (0)
   [junit4]   1>  /zookeeper (1)
   [junit4]   1>  DATA:
   [junit4]   1>      
   [junit4]   1> 
   [junit4]   2> 787563 T624 C277 P49937 oasc.SyncStrategy.sync WARN Closed, skipping sync up.
   [junit4]   2> 787563 T624 oasc.ShardLeaderElectionContext.rejoinLeaderElection Not rejoining election because CoreContainer is shutdown
   [junit4]   2> 787564 T624 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@2eac686a
   [junit4]   2> 787567 T624 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=2,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=47,cumulative_deletesById=25,cumulative_deletesByQuery=1,cumulative_errors=0,transaction_logs_total_size=0,transaction_logs_total_number=1}
   [junit4]   2> 787568 T624 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
   [junit4]   2> 787568 T624 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
   [junit4]   2> 787568 T624 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
   [junit4]   2> 787570 T624 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
   [junit4]   2> 787571 T624 oasc.CachingDirectoryFactory.close Closing StandardDirectoryFactory - 2 directories currently being tracked
   [junit4]   2> 787571 T624 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyNothingIsSafeTest-1387418306570/jetty7/index [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyNothingIsSafeTest-1387418306570/jetty7/index;done=false>>]
   [junit4]   2> 787571 T624 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyNothingIsSafeTest-1387418306570/jetty7/index
   [junit4]   2> 787572 T624 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyNothingIsSafeTest-1387418306570/jetty7 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyNothingIsSafeTest-1387418306570/jetty7;done=false>>]
   [junit4]   2> 787572 T624 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyNothingIsSafeTest-1387418306570/jetty7
   [junit4]   2> 787572 T624 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
   [junit4]   2> 787573 T624 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 787573 T624 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
   [junit4]   2> 787573 T624 oasc.LeaderElector$1.process WARN  org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/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:252)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:249)
   [junit4]   2> 	at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
   [junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:249)
   [junit4]   2> 	at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:93)
   [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:138)
   [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> NOTE: reproduce with: ant test  -Dtestcase=ChaosMonkeyNothingIsSafeTest -Dtests.method=testDistribSearch -Dtests.seed=9E383FAE8CE20A23 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_US -Dtests.timezone=Asia/Samarkand -Dtests.file.encoding=UTF-8
   [junit4] FAILURE  173s J1 | ChaosMonkeyNothingIsSafeTest.testDistribSearch <<<
   [junit4]    > Throwable #1: java.lang.AssertionError: There were expected update fails expected:<0> but was:<1>
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([9E383FAE8CE20A23:1FDEB1B6FBBD6A1F]:0)
   [junit4]    > 	at org.apache.solr.cloud.ChaosMonkeyNothingIsSafeTest.doTest(ChaosMonkeyNothingIsSafeTest.java:202)
   [junit4]    > 	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:849)
   [junit4]    > 	at java.lang.Thread.run(Thread.java:724)
   [junit4]   2> 787603 T479 oas.SolrTestCaseJ4.deleteCore ###deleteCore
   [junit4]   2> 172670 T478 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
   [junit4]   2> 787633 T606 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
   [junit4]   2> NOTE: test params are: codec=Asserting, sim=DefaultSimilarity, locale=es_US, timezone=Asia/Samarkand
   [junit4]   2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=16,threads=1,free=244594576,total=460324864
   [junit4]   2> NOTE: All tests run in this JVM: [TestRemoteStreaming, TestCollationKeyRangeQueries, BasicZkTest, DistributedQueryElevationComponentTest, ShardSplitTest, TestDynamicFieldCollectionResource, TestPHPSerializedResponseWriter, TestManagedSchema, SpellCheckCollatorTest, InfoHandlerTest, ChaosMonkeyNothingIsSafeTest]
   [junit4] Completed on J1 in 172.97s, 1 test, 1 failure <<< FAILURES!

[...truncated 823 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:459: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:439: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/extra-targets.xml:37: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build.xml:189: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/common-build.xml:491: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:1307: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:940: There were test failures: 347 suites, 1517 tests, 1 error, 1 failure, 34 ignored (6 assumptions)

Total time: 71 minutes 56 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