lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Policeman Jenkins Server <jenk...@thetaphi.de>
Subject [JENKINS] Lucene-Solr-trunk-Windows (64bit/jdk1.7.0_21) - Build # 2834 - Still Failing!
Date Sat, 18 May 2013 16:56:12 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Windows/2834/
Java: 64bit/jdk1.7.0_21 -XX:+UseCompressedOops -XX:+UseParallelGC

1 tests failed.
REGRESSION:  org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testDistribSearch

Error Message:
There are still nodes recoverying - waited for 230 seconds

Stack Trace:
java.lang.AssertionError: There are still nodes recoverying - waited for 230 seconds
	at __randomizedtesting.SeedInfo.seed([7DA14641F86B0A99:FC47C8598F346AA5]:0)
	at org.junit.Assert.fail(Assert.java:93)
	at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:173)
	at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:131)
	at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:126)
	at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollectionsAPI(CollectionsAPIDistributedZkTest.java:512)
	at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.doTest(CollectionsAPIDistributedZkTest.java:146)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
	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:601)
	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:722)




Build Log:
[...truncated 9550 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.CollectionsAPIDistributedZkTest
[junit4:junit4]   2> 1454146 T4190 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 1454151 T4190 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\solrtest-CollectionsAPIDistributedZkTest-1368894995842
[junit4:junit4]   2> 1454153 T4190 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 1454154 T4191 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 1454254 T4190 oasc.ZkTestServer.run start zk server on port:60418
[junit4:junit4]   2> 1454255 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1454268 T4197 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7d4aa62 name:ZooKeeperConnection Watcher:127.0.0.1:60418 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1454269 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1454270 T4190 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 1454277 T4192 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eb87ffd8d0000, likely client has closed socket
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 
[junit4:junit4]   2> 1454278 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1454282 T4199 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4114cc1a name:ZooKeeperConnection Watcher:127.0.0.1:60418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1454282 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1454282 T4190 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 1454287 T4190 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 1454293 T4190 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 1454297 T4190 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 1454302 T4190 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 1454303 T4190 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 1454312 T4190 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 1454313 T4190 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 1454319 T4190 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 1454320 T4190 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 1454325 T4190 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 1454326 T4190 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 1454330 T4190 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 1454331 T4190 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 1454336 T4190 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 1454336 T4190 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 1454341 T4190 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 1454342 T4190 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 1454347 T4190 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 1454348 T4190 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 1454353 T4190 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 1454353 T4190 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 1454361 T4192 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eb87ffd8d0001, likely client has closed socket
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 
[junit4:junit4]   2> 1454812 T4190 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1454819 T4190 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:60425
[junit4:junit4]   2> 1454820 T4190 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1454821 T4190 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1454821 T4190 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050
[junit4:junit4]   2> 1454821 T4190 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\solr.xml
[junit4:junit4]   2> 1454822 T4190 oasc.CoreContainer.<init> New CoreContainer 542349926
[junit4:junit4]   2> 1454822 T4190 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\'
[junit4:junit4]   2> 1454823 T4190 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\'
[junit4:junit4]   2> 1454914 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050
[junit4:junit4]   2> 1454917 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\collection1
[junit4:junit4]   2> 1454918 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\collection1\conf
[junit4:junit4]   2> 1455144 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\collection1\conf\xslt
[junit4:junit4]   2> 1455152 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\collection1\lib
[junit4:junit4]   2> 1455155 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\collection1\lib\classes
[junit4:junit4]   2> 1455162 T4190 oasc.SolrCoreDiscoverer.addCore Discovered properties file C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\conf\core.properties, adding to cores
[junit4:junit4]   2> 1455178 T4190 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4]   2> 1455179 T4190 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1455179 T4190 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4]   2> 1455179 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1455180 T4190 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1455181 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1455181 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1455182 T4190 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1455182 T4190 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1455182 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4]   2> 1455190 T4190 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1455191 T4190 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60418/solr
[junit4:junit4]   2> 1455191 T4190 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1455193 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1455207 T4210 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@81b5252 name:ZooKeeperConnection Watcher:127.0.0.1:60418 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1455208 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1455212 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1455212 T4192 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eb87ffd8d0002, likely client has closed socket
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 
[junit4:junit4]   2> 1455218 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1455222 T4212 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@204b81f6 name:ZooKeeperConnection Watcher:127.0.0.1:60418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1455222 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1455225 T4190 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 1455233 T4190 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 1455239 T4190 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 1455242 T4190 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60425_
[junit4:junit4]   2> 1455245 T4190 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60425_
[junit4:junit4]   2> 1455249 T4190 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 1455259 T4190 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 1455266 T4190 oasc.Overseer.start Overseer (id=89711902448222211-127.0.0.1:60425_-n_0000000000) starting
[junit4:junit4]   2> 1455271 T4190 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 1455284 T4214 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 1455285 T4190 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 1455288 T4190 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 1455292 T4190 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1455295 T4213 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 1455299 T4190 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 1455299 T4190 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1455299 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1455304 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 1455306 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1455310 T4217 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7877705e name:ZooKeeperConnection Watcher:127.0.0.1:60418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1455311 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1455312 T4190 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1455315 T4190 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 1455792 T4190 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1455796 T4190 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:60437
[junit4:junit4]   2> 1455798 T4190 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1455798 T4190 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1455799 T4190 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005
[junit4:junit4]   2> 1455799 T4190 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\solr.xml
[junit4:junit4]   2> 1455799 T4190 oasc.CoreContainer.<init> New CoreContainer 2012367928
[junit4:junit4]   2> 1455800 T4190 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\'
[junit4:junit4]   2> 1455800 T4190 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\'
[junit4:junit4]   2> 1455900 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005
[junit4:junit4]   2> 1455903 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\collection1
[junit4:junit4]   2> 1455905 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\collection1\conf
[junit4:junit4]   2> 1456167 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\collection1\conf\xslt
[junit4:junit4]   2> 1456175 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\collection1\lib
[junit4:junit4]   2> 1456179 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\collection1\lib\classes
[junit4:junit4]   2> 1456185 T4190 oasc.SolrCoreDiscoverer.addCore Discovered properties file C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\conf\core.properties, adding to cores
[junit4:junit4]   2> 1456204 T4190 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4]   2> 1456204 T4190 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1456205 T4190 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4]   2> 1456205 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1456207 T4190 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1456208 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1456208 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1456208 T4190 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1456209 T4190 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1456209 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4]   2> 1456216 T4190 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1456217 T4190 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60418/solr
[junit4:junit4]   2> 1456217 T4190 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1456219 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1456236 T4228 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3f827a9 name:ZooKeeperConnection Watcher:127.0.0.1:60418 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1456237 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1456241 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1456241 T4192 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eb87ffd8d0005, likely client has closed socket
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 
[junit4:junit4]   2> 1456247 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1456252 T4230 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@449c95d5 name:ZooKeeperConnection Watcher:127.0.0.1:60418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1456253 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1456262 T4190 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1457368 T4190 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60437_
[junit4:junit4]   2> 1457371 T4190 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60437_
[junit4:junit4]   2> 1457376 T4217 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 1457377 T4230 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 1457377 T4212 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 1457386 T4190 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 1457386 T4190 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1457386 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1457897 T4190 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1457902 T4190 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:60446
[junit4:junit4]   2> 1457903 T4190 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1457904 T4190 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1457904 T4190 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080
[junit4:junit4]   2> 1457904 T4190 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\solr.xml
[junit4:junit4]   2> 1457904 T4190 oasc.CoreContainer.<init> New CoreContainer 1372288854
[junit4:junit4]   2> 1457906 T4190 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\'
[junit4:junit4]   2> 1457906 T4190 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\'
[junit4:junit4]   2> 1458007 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080
[junit4:junit4]   2> 1458010 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\collection1
[junit4:junit4]   2> 1458012 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\collection1\conf
[junit4:junit4]   2> 1458270 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\collection1\conf\xslt
[junit4:junit4]   2> 1458280 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\collection1\lib
[junit4:junit4]   2> 1458283 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\collection1\lib\classes
[junit4:junit4]   2> 1458290 T4190 oasc.SolrCoreDiscoverer.addCore Discovered properties file C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\conf\core.properties, adding to cores
[junit4:junit4]   2> 1458312 T4190 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4]   2> 1458312 T4190 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1458313 T4190 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4]   2> 1458313 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1458313 T4190 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1458314 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1458314 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1458314 T4190 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1458315 T4190 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1458315 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4]   2> 1458341 T4190 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1458341 T4190 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60418/solr
[junit4:junit4]   2> 1458342 T4190 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1458344 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1458366 T4242 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8efde9d name:ZooKeeperConnection Watcher:127.0.0.1:60418 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1458368 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1458372 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1458372 T4192 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eb87ffd8d0007, likely client has closed socket
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 
[junit4:junit4]   2> 1458379 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1458384 T4244 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2821180 name:ZooKeeperConnection Watcher:127.0.0.1:60418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1458385 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1458395 T4190 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1459500 T4190 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60446_
[junit4:junit4]   2> 1459504 T4190 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60446_
[junit4:junit4]   2> 1459510 T4230 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 1459510 T4244 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 1459511 T4212 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 1459513 T4217 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 1459525 T4190 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 1459525 T4190 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1459526 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1460024 T4190 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1460030 T4190 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:60455
[junit4:junit4]   2> 1460031 T4190 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1460031 T4190 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1460032 T4190 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224
[junit4:junit4]   2> 1460032 T4190 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\solr.xml
[junit4:junit4]   2> 1460032 T4190 oasc.CoreContainer.<init> New CoreContainer 449242523
[junit4:junit4]   2> 1460033 T4190 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\'
[junit4:junit4]   2> 1460033 T4190 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\'
[junit4:junit4]   2> 1460153 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224
[junit4:junit4]   2> 1460155 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\collection1
[junit4:junit4]   2> 1460156 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\collection1\conf
[junit4:junit4]   2> 1460381 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\collection1\conf\xslt
[junit4:junit4]   2> 1460389 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\collection1\lib
[junit4:junit4]   2> 1460393 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\collection1\lib\classes
[junit4:junit4]   2> 1460399 T4190 oasc.SolrCoreDiscoverer.addCore Discovered properties file C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\conf\core.properties, adding to cores
[junit4:junit4]   2> 1460418 T4190 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4]   2> 1460420 T4190 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1460421 T4190 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4]   2> 1460421 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1460422 T4190 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1460422 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1460423 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1460424 T4190 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1460424 T4190 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1460425 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4]   2> 1460438 T4190 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1460439 T4190 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60418/solr
[junit4:junit4]   2> 1460439 T4190 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1460441 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1460464 T4256 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@62b4964c name:ZooKeeperConnection Watcher:127.0.0.1:60418 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1460465 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1460470 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1460471 T4192 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eb87ffd8d0009, likely client has closed socket
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 
[junit4:junit4]   2> 1460482 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1460487 T4258 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3144a233 name:ZooKeeperConnection Watcher:127.0.0.1:60418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1460487 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1460500 T4190 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1461608 T4190 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60455_
[junit4:junit4]   2> 1461619 T4190 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60455_
[junit4:junit4]   2> 1461660 T4258 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1461660 T4230 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1461660 T4244 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1461661 T4212 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1461661 T4217 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 1461676 T4190 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 1461677 T4190 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1461678 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1462412 T4190 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 1462418 T4190 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:60464
[junit4:junit4]   2> 1462420 T4190 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1462422 T4190 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1462423 T4190 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373
[junit4:junit4]   2> 1462423 T4190 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\solr.xml
[junit4:junit4]   2> 1462424 T4190 oasc.CoreContainer.<init> New CoreContainer 568834315
[junit4:junit4]   2> 1462425 T4190 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\'
[junit4:junit4]   2> 1462425 T4190 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\'
[junit4:junit4]   2> 1462577 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373
[junit4:junit4]   2> 1462580 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\collection1
[junit4:junit4]   2> 1462582 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\collection1\conf
[junit4:junit4]   2> 1462815 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\collection1\conf\xslt
[junit4:junit4]   2> 1462817 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\collection1\lib
[junit4:junit4]   2> 1462817 T4190 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\collection1\lib\classes
[junit4:junit4]   2> 1462825 T4190 oasc.SolrCoreDiscoverer.addCore Discovered properties file C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\conf\core.properties, adding to cores
[junit4:junit4]   2> 1462854 T4190 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4]   2> 1462854 T4190 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1462855 T4190 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4]   2> 1462855 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1462856 T4190 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1462857 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1462857 T4190 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1462859 T4190 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1462859 T4190 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1462860 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4]   2> 1462874 T4190 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 1462875 T4190 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60418/solr
[junit4:junit4]   2> 1462875 T4190 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1462893 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1462939 T4270 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10938485 name:ZooKeeperConnection Watcher:127.0.0.1:60418 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1462939 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1462960 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1462971 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1462979 T4272 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4d0f0cd0 name:ZooKeeperConnection Watcher:127.0.0.1:60418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1462980 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1462993 T4190 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1464101 T4190 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60464_
[junit4:junit4]   2> 1464108 T4190 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60464_
[junit4:junit4]   2> 1464118 T4272 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1464118 T4258 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1464119 T4230 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1464119 T4212 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1464119 T4217 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1464119 T4244 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 1464132 T4190 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 1464132 T4190 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 1464133 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1464138 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1464147 T4222 oasha.CollectionsHandler.handleCreateAction Creating Collection : numShards=2&name=nodes_used_collection&replicationFactor=2&action=CREATE&wt=javabin&version=2
[junit4:junit4]   2> 1464150 T4212 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4]   2> 1464155 T4214 oasc.OverseerCollectionProcessor.run Overseer Collection Processor: Get the message id:/overseer/collection-queue-work/qn-0000000000 message:{
[junit4:junit4]   2> 	  "operation":"createcollection",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "maxShardsPerNode":null,
[junit4:junit4]   2> 	  "createNodeSet":null,
[junit4:junit4]   2> 	  "name":"nodes_used_collection",
[junit4:junit4]   2> 	  "replicationFactor":"2"}
[junit4:junit4]   2> 1464155 T4214 oasc.OverseerCollectionProcessor.createCollection Creating shard nodes_used_collection_shard1_replica1 as part of slice shard1 of collection nodes_used_collection on 127.0.0.1:60464_
[junit4:junit4]   2> 1464157 T4214 oasc.OverseerCollectionProcessor.createCollection Creating shard nodes_used_collection_shard1_replica2 as part of slice shard1 of collection nodes_used_collection on 127.0.0.1:60437_
[junit4:junit4]   2> 1464159 T4214 oasc.OverseerCollectionProcessor.createCollection Creating shard nodes_used_collection_shard2_replica1 as part of slice shard2 of collection nodes_used_collection on 127.0.0.1:60455_
[junit4:junit4]   2> 1464160 T4214 oasc.OverseerCollectionProcessor.createCollection Creating shard nodes_used_collection_shard2_replica2 as part of slice shard2 of collection nodes_used_collection on 127.0.0.1:60425_
[junit4:junit4]   2> 1464163 T4266 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard1_replica1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\nodes_used_collection_shard1_replica1
[junit4:junit4]   2> 1464164 T4266 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4]   2> 1464164 T4252 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard2_replica1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\nodes_used_collection_shard2_replica1
[junit4:junit4]   2> 1464165 T4252 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4]   2> 1464165 T4223 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard1_replica2' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\nodes_used_collection_shard1_replica2
[junit4:junit4]   2> 1464166 T4223 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4]   2> 1464166 T4266 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4]   2> 1464167 T4266 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 1464168 T4252 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4]   2> 1464170 T4252 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 1464170 T4223 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4]   2> 1464171 T4223 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 1464171 T4206 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard2_replica2' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\nodes_used_collection_shard2_replica2
[junit4:junit4]   2> 1464173 T4206 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4]   2> 1464175 T4266 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 1464175 T4266 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4]   2> 1464176 T4223 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 1464176 T4223 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4]   2> 1464176 T4252 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 1464179 T4252 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4]   2> 1464176 T4206 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4]   2> 1464180 T4206 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 1464187 T4223 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4]   2> 1464188 T4266 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4]   2> 1464190 T4252 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4]   2> 1464190 T4206 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4]   2> 1464194 T4266 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\nodes_used_collection_shard1_replica1\'
[junit4:junit4]   2> 1464194 T4223 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\nodes_used_collection_shard1_replica2\'
[junit4:junit4]   2> 1464201 T4252 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\nodes_used_collection_shard2_replica1\'
[junit4:junit4]   2> 1464206 T4206 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4]   2> 1464215 T4206 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\nodes_used_collection_shard2_replica2\'
[junit4:junit4]   2> 1464312 T4223 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1464336 T4252 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1464416 T4206 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1464445 T4223 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1464462 T4223 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1464469 T4223 oass.IndexSchema.readSchema [nodes_used_collection_shard1_replica2] Schema name=test
[junit4:junit4]   2> 1464470 T4266 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1464576 T4206 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1464594 T4206 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1464602 T4206 oass.IndexSchema.readSchema [nodes_used_collection_shard2_replica2] Schema name=test
[junit4:junit4]   2> 1464640 T4252 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1464664 T4266 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1464686 T4252 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1464693 T4252 oass.IndexSchema.readSchema [nodes_used_collection_shard2_replica1] Schema name=test
[junit4:junit4]   2> 1464696 T4266 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1464701 T4266 oass.IndexSchema.readSchema [nodes_used_collection_shard1_replica1] Schema name=test
[junit4:junit4]   2> 1465445 T4223 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1465506 T4223 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1465510 T4223 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1465832 T4223 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1465956 T4223 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1466083 T4223 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1466118 T4223 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1466121 T4223 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1466121 T4223 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1466242 T4223 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1466242 T4223 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1466243 T4223 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1466244 T4223 oasc.SolrCore.<init> [nodes_used_collection_shard1_replica2] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\nodes_used_collection_shard1_replica2\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\nodes_used_collection_shard1_replica2\data\
[junit4:junit4]   2> 1466244 T4223 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@24769ece
[junit4:junit4]   2> 1466245 T4223 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1466246 T4223 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\nodes_used_collection_shard1_replica2\data\
[junit4:junit4]   2> 1466247 T4223 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\nodes_used_collection_shard1_replica2\data\index/
[junit4:junit4]   2> 1466247 T4223 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard1_replica2] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\nodes_used_collection_shard1_replica2\data\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1466248 T4223 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\nodes_used_collection_shard1_replica2\data\index
[junit4:junit4]   2> 1466258 T4223 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b6382d lockFactory=org.apache.lucene.store.NativeFSLockFactory@16506dc0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1466259 T4223 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1466265 T4223 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1466266 T4223 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1466267 T4223 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1466269 T4223 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1466270 T4223 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1466270 T4223 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1466271 T4223 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1466272 T4223 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1466273 T4223 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1466344 T4252 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1466363 T4252 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1466370 T4252 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1466428 T4223 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1466571 T4223 oass.SolrIndexSearcher.<init> Opening Searcher@7128a60c main
[junit4:junit4]   2> 1466573 T4223 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\nodes_used_collection_shard1_replica2\data\tlog
[junit4:junit4]   2> 1466575 T4223 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1466576 T4223 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1466582 T4266 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1466592 T4266 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1466595 T4266 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1466616 T4223 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica2 state=down
[junit4:junit4]   2> 1466617 T4278 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica2] Registered new searcher Searcher@7128a60c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1466635 T4252 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1466643 T4266 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1466656 T4266 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1466661 T4252 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1466668 T4206 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1466671 T4266 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1466677 T4206 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1466678 T4252 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1466682 T4206 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1466684 T4266 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1466686 T4266 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1466687 T4266 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1466685 T4252 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1466689 T4252 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1466690 T4252 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1466691 T4266 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1466692 T4266 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1466696 T4266 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1466697 T4266 oasc.SolrCore.<init> [nodes_used_collection_shard1_replica1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\nodes_used_collection_shard1_replica1\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\nodes_used_collection_shard1_replica1\data\
[junit4:junit4]   2> 1466697 T4266 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@24769ece
[junit4:junit4]   2> 1466696 T4252 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1466698 T4252 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1466698 T4252 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1466698 T4266 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1466699 T4252 oasc.SolrCore.<init> [nodes_used_collection_shard2_replica1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\nodes_used_collection_shard2_replica1\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\nodes_used_collection_shard2_replica1\data\
[junit4:junit4]   2> 1466700 T4252 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@24769ece
[junit4:junit4]   2> 1466700 T4266 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\nodes_used_collection_shard1_replica1\data\
[junit4:junit4]   2> 1466701 T4266 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\nodes_used_collection_shard1_replica1\data\index/
[junit4:junit4]   2> 1466701 T4266 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard1_replica1] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\nodes_used_collection_shard1_replica1\data\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1466701 T4252 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1466702 T4266 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\nodes_used_collection_shard1_replica1\data\index
[junit4:junit4]   2> 1466706 T4252 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\nodes_used_collection_shard2_replica1\data\
[junit4:junit4]   2> 1466708 T4252 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\nodes_used_collection_shard2_replica1\data\index/
[junit4:junit4]   2> 1466708 T4252 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard2_replica1] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\nodes_used_collection_shard2_replica1\data\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1466710 T4252 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\nodes_used_collection_shard2_replica1\data\index
[junit4:junit4]   2> 1466715 T4206 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1466716 T4266 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4a8b1458 lockFactory=org.apache.lucene.store.NativeFSLockFactory@64caa55a),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1466717 T4266 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1466722 T4266 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1466722 T4266 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1466723 T4266 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1466723 T4252 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4e335015 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d66b0d3),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1466724 T4252 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1466724 T4266 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1466727 T4266 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1466727 T4266 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1466728 T4266 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1466729 T4266 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1466730 T4266 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1466732 T4252 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1466733 T4252 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1466735 T4252 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1466737 T4252 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1466738 T4252 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1466738 T4252 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1466739 T4252 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1466740 T4252 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1466741 T4252 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1466750 T4252 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1466751 T4266 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1466759 T4252 oass.SolrIndexSearcher.<init> Opening Searcher@2f196c29 main
[junit4:junit4]   2> 1466759 T4252 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\nodes_used_collection_shard2_replica1\data\tlog
[junit4:junit4]   2> 1466761 T4252 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1466762 T4252 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1466764 T4266 oass.SolrIndexSearcher.<init> Opening Searcher@778a5549 main
[junit4:junit4]   2> 1466767 T4279 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica1] Registered new searcher Searcher@2f196c29 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1466767 T4266 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\nodes_used_collection_shard1_replica1\data\tlog
[junit4:junit4]   2> 1466769 T4266 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1466770 T4266 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1466770 T4206 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1466775 T4252 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica1 state=down
[junit4:junit4]   2> 1466777 T4280 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica1] Registered new searcher Searcher@778a5549 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1466778 T4266 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica1 state=down
[junit4:junit4]   2> 1466779 T4206 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1466783 T4206 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1466783 T4206 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1466784 T4206 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1466785 T4206 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1466785 T4206 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1466786 T4206 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1466786 T4206 oasc.SolrCore.<init> [nodes_used_collection_shard2_replica2] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\nodes_used_collection_shard2_replica2\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\nodes_used_collection_shard2_replica2\data\
[junit4:junit4]   2> 1466786 T4206 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@24769ece
[junit4:junit4]   2> 1466787 T4206 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1466788 T4206 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\nodes_used_collection_shard2_replica2\data\
[junit4:junit4]   2> 1466788 T4206 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\nodes_used_collection_shard2_replica2\data\index/
[junit4:junit4]   2> 1466788 T4206 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard2_replica2] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\nodes_used_collection_shard2_replica2\data\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1466789 T4206 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\nodes_used_collection_shard2_replica2\data\index
[junit4:junit4]   2> 1466795 T4206 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@202ba2e lockFactory=org.apache.lucene.store.NativeFSLockFactory@61cda73d),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1466796 T4206 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1466803 T4206 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1466803 T4206 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1466804 T4206 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1466805 T4206 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1466806 T4206 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1466806 T4206 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1466806 T4206 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1466807 T4206 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1466809 T4206 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1466818 T4206 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1466825 T4213 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1466826 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"nodes_used_collection_shard1_replica2",
[junit4:junit4]   2> 	  "collection":"nodes_used_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60437_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60437"}
[junit4:junit4]   2> 1466826 T4213 oasc.Overseer$ClusterStateUpdater.createCollection Create collection nodes_used_collection with numShards 2
[junit4:junit4]   2> 1466830 T4206 oass.SolrIndexSearcher.<init> Opening Searcher@25a29ce8 main
[junit4:junit4]   2> 1466831 T4206 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\nodes_used_collection_shard2_replica2\data\tlog
[junit4:junit4]   2> 1466835 T4206 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1466835 T4206 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1466838 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"nodes_used_collection_shard2_replica1",
[junit4:junit4]   2> 	  "collection":"nodes_used_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60455_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60455"}
[junit4:junit4]   2> 1466839 T4281 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica2] Registered new searcher Searcher@25a29ce8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1466840 T4206 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica2 state=down
[junit4:junit4]   2> 1466848 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"nodes_used_collection_shard1_replica1",
[junit4:junit4]   2> 	  "collection":"nodes_used_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60464_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60464"}
[junit4:junit4]   2> 1466858 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"nodes_used_collection_shard2_replica2",
[junit4:junit4]   2> 	  "collection":"nodes_used_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60425_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60425"}
[junit4:junit4]   2> 1466869 T4272 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1466870 T4217 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1466870 T4212 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1466870 T4244 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1466870 T4230 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1466870 T4258 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1467624 T4223 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard1_replica2
[junit4:junit4]   2> 1467624 T4223 oasc.ZkController.register Register replica - core:nodes_used_collection_shard1_replica2 address:http://127.0.0.1:60437 collection:nodes_used_collection shard:shard1
[junit4:junit4]   2> 1467626 T4223 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leader_elect/shard1/election
[junit4:junit4]   2> 1467643 T4223 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 1467653 T4223 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Waiting until we see more replicas up: total=2 found=1 timeoutin=179999
[junit4:junit4]   2> 1467771 T4252 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard2_replica1
[junit4:junit4]   2> 1467771 T4252 oasc.ZkController.register Register replica - core:nodes_used_collection_shard2_replica1 address:http://127.0.0.1:60455 collection:nodes_used_collection shard:shard2
[junit4:junit4]   2> 1467772 T4266 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard1_replica1
[junit4:junit4]   2> 1467772 T4266 oasc.ZkController.register Register replica - core:nodes_used_collection_shard1_replica1 address:http://127.0.0.1:60464 collection:nodes_used_collection shard:shard1
[junit4:junit4]   2> 1467773 T4252 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leader_elect/shard2/election
[junit4:junit4]   2> 1467790 T4252 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 1467796 T4252 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Waiting until we see more replicas up: total=2 found=1 timeoutin=180000
[junit4:junit4]   2> 1467833 T4206 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard2_replica2
[junit4:junit4]   2> 1467833 T4206 oasc.ZkController.register Register replica - core:nodes_used_collection_shard2_replica2 address:http://127.0.0.1:60425 collection:nodes_used_collection shard:shard2
[junit4:junit4]   2> 1468152 T4223 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 1468152 T4223 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 1468152 T4223 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:60437/nodes_used_collection_shard1_replica2/
[junit4:junit4]   2> 1468153 T4223 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard1_replica2 url=http://127.0.0.1:60437 START replicas=[http://127.0.0.1:60464/nodes_used_collection_shard1_replica1/] nUpdates=100
[junit4:junit4]   2> 1468153 T4223 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard1_replica2 url=http://127.0.0.1:60437 DONE.  We have no versions.  sync failed.
[junit4:junit4]   2> 1468153 T4223 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4]   2> 1468154 T4223 oasc.ShardLeaderElectionContext.runLeaderProcess We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4:junit4]   2> 1468155 T4223 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:60437/nodes_used_collection_shard1_replica2/
[junit4:junit4]   2> 1468155 T4223 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leaders/shard1
[junit4:junit4]   2> ASYNC  NEW_CORE C271 name=nodes_used_collection_shard1_replica1 org.apache.solr.core.SolrCore@f274094 url=http://127.0.0.1:60464/nodes_used_collection_shard1_replica1 node=127.0.0.1:60464_ C271_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica1 props:{shard=shard1, state=down, core=nodes_used_collection_shard1_replica1, collection=nodes_used_collection, node_name=127.0.0.1:60464_, base_url=http://127.0.0.1:60464}
[junit4:junit4]   2> 1468166 T4265 C271 P60464 oasc.SolrCore.execute [nodes_used_collection_shard1_replica1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1 
[junit4:junit4]   2> 1468293 T4252 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 1468293 T4252 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 1468293 T4252 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:60455/nodes_used_collection_shard2_replica1/
[junit4:junit4]   2> 1468293 T4252 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard2_replica1 url=http://127.0.0.1:60455 START replicas=[http://127.0.0.1:60425/nodes_used_collection_shard2_replica2/] nUpdates=100
[junit4:junit4]   2> 1468293 T4252 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard2_replica1 url=http://127.0.0.1:60455 DONE.  We have no versions.  sync failed.
[junit4:junit4]   2> 1468294 T4252 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4]   2> 1468294 T4252 oasc.ShardLeaderElectionContext.runLeaderProcess We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4:junit4]   2> 1468295 T4252 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:60455/nodes_used_collection_shard2_replica1/
[junit4:junit4]   2> 1468296 T4252 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leaders/shard2
[junit4:junit4]   2> ASYNC  NEW_CORE C272 name=nodes_used_collection_shard2_replica2 org.apache.solr.core.SolrCore@19b4078d url=http://127.0.0.1:60425/nodes_used_collection_shard2_replica2 node=127.0.0.1:60425_ C272_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica2 props:{shard=shard2, state=down, core=nodes_used_collection_shard2_replica2, collection=nodes_used_collection, node_name=127.0.0.1:60425_, base_url=http://127.0.0.1:60425}
[junit4:junit4]   2> 1468310 T4203 C272 P60425 oasc.SolrCore.execute [nodes_used_collection_shard2_replica2] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1 
[junit4:junit4]   2> 1468385 T4213 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1468497 T4272 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1468497 T4258 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1468497 T4230 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1468497 T4244 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1468497 T4212 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1468501 T4217 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1468513 T4252 oasc.ZkController.register We are http://127.0.0.1:60455/nodes_used_collection_shard2_replica1/ and leader is http://127.0.0.1:60455/nodes_used_collection_shard2_replica1/
[junit4:junit4]   2> 1468513 T4252 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard2_replica1 baseURL=http://127.0.0.1:60455
[junit4:junit4]   2> 1468513 T4252 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 1468513 T4252 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica1 state=active
[junit4:junit4]   2> 1468528 T4252 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1468535 T4252 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={numShards=2&shard=shard2&name=nodes_used_collection_shard2_replica1&action=CREATE&collection=nodes_used_collection&wt=javabin&qt=/admin/cores&version=2} status=0 QTime=4371 
[junit4:junit4]   2> 1468537 T4223 oasc.ZkController.register We are http://127.0.0.1:60437/nodes_used_collection_shard1_replica2/ and leader is http://127.0.0.1:60437/nodes_used_collection_shard1_replica2/
[junit4:junit4]   2> 1468537 T4223 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard1_replica2 baseURL=http://127.0.0.1:60437
[junit4:junit4]   2> 1468538 T4223 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 1468538 T4223 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica2 state=active
[junit4:junit4]   2> 1468552 T4223 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1468554 T4223 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={numShards=2&shard=shard1&name=nodes_used_collection_shard1_replica2&action=CREATE&collection=nodes_used_collection&wt=javabin&qt=/admin/cores&version=2} status=0 QTime=4389 
[junit4:junit4]   2> 1468773 T4266 oasc.ZkController.register We are http://127.0.0.1:60464/nodes_used_collection_shard1_replica1/ and leader is http://127.0.0.1:60437/nodes_used_collection_shard1_replica2/
[junit4:junit4]   2> 1468773 T4266 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard1_replica1 baseURL=http://127.0.0.1:60464
[junit4:junit4]   2> 1468774 T4266 oasc.ZkController.checkRecovery Core needs to recover:nodes_used_collection_shard1_replica1
[junit4:junit4]   2> 1468774 T4266 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> 1468777 T4284 C271 P60464 oasc.RecoveryStrategy.run Starting recovery process.  core=nodes_used_collection_shard1_replica1 recoveringAfterStartup=true
[junit4:junit4]   2> 1468777 T4284 C271 P60464 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 1468780 T4284 C271 P60464 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica1 state=recovering
[junit4:junit4]   2> 1468780 T4266 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1468785 T4284 C271 P60464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1468786 T4266 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={numShards=2&shard=shard1&name=nodes_used_collection_shard1_replica1&action=CREATE&collection=nodes_used_collection&wt=javabin&qt=/admin/cores&version=2} status=0 QTime=4624 
[junit4:junit4]   2> 1468802 T4225 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:60464__nodes_used_collection_shard1_replica1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 1468831 T4206 oasc.ZkController.register We are http://127.0.0.1:60425/nodes_used_collection_shard2_replica2/ and leader is http://127.0.0.1:60455/nodes_used_collection_shard2_replica1/
[junit4:junit4]   2> 1468832 T4206 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard2_replica2 baseURL=http://127.0.0.1:60425
[junit4:junit4]   2> 1468832 T4206 oasc.ZkController.checkRecovery Core needs to recover:nodes_used_collection_shard2_replica2
[junit4:junit4]   2> 1468832 T4206 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> 1468835 T4285 C272 P60425 oasc.RecoveryStrategy.run Starting recovery process.  core=nodes_used_collection_shard2_replica2 recoveringAfterStartup=true
[junit4:junit4]   2> 1468835 T4285 C272 P60425 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 1468836 T4206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1468837 T4285 C272 P60425 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica2 state=recovering
[junit4:junit4]   2> 1468838 T4206 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={numShards=2&shard=shard2&name=nodes_used_collection_shard2_replica2&action=CREATE&collection=nodes_used_collection&wt=javabin&qt=/admin/cores&version=2} status=0 QTime=4668 
[junit4:junit4]   2> 1468842 T4285 C272 P60425 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 1468842 T4214 oasc.OverseerCollectionProcessor.createCollection Finished create command on all shards for collection: nodes_used_collection
[junit4:junit4]   2> 1468852 T4250 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:60425__nodes_used_collection_shard2_replica2, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 1468863 T4230 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work/qnr-0000000000 state: SyncConnected type NodeDataChanged
[junit4:junit4]   2> 1468867 T4212 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4]   2> 1468867 T4214 oasc.OverseerCollectionProcessor.run Overseer Collection Processor: Message id:/overseer/collection-queue-work/qn-0000000000 complete, response:{success={null={responseHeader={status=0,QTime=4371},core=nodes_used_collection_shard2_replica1},null={responseHeader={status=0,QTime=4389},core=nodes_used_collection_shard1_replica2},null={responseHeader={status=0,QTime=4624},core=nodes_used_collection_shard1_replica1},null={responseHeader={status=0,QTime=4668},core=nodes_used_collection_shard2_replica2}}}
[junit4:junit4]   2> 1468872 T4222 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/collections params={numShards=2&name=nodes_used_collection&replicationFactor=2&action=CREATE&wt=javabin&version=2} status=0 QTime=4726 
[junit4:junit4]   2> 1468873 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 1468875 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1468882 T4287 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@390b4b11 name:ZooKeeperConnection Watcher:127.0.0.1:60418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1468882 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1468884 T4190 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1468890 T4190 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 1468894 T4190 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1468899 T4289 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7c0813ee name:ZooKeeperConnection Watcher:127.0.0.1:60418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1468900 T4190 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1468902 T4190 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1468913 T4207 oasha.CollectionsHandler.handleCreateAction Creating Collection : numShards=1&maxShardsPerNode=2&name=awholynewcollection_0&replicationFactor=5&action=CREATE&wt=javabin&version=2
[junit4:junit4]   2> 1468917 T4212 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4]   2> 1468922 T4214 oasc.OverseerCollectionProcessor.run Overseer Collection Processor: Get the message id:/overseer/collection-queue-work/qn-0000000002 message:{
[junit4:junit4]   2> 	  "operation":"createcollection",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "maxShardsPerNode":"2",
[junit4:junit4]   2> 	  "createNodeSet":null,
[junit4:junit4]   2> 	  "name":"awholynewcollection_0",
[junit4:junit4]   2> 	  "replicationFactor":"5"}
[junit4:junit4]   2> 1468923 T4214 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica1 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:60446_
[junit4:junit4]   2> 1468923 T4214 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica2 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:60437_
[junit4:junit4]   2> 1468923 T4214 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica3 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:60425_
[junit4:junit4]   2> 1468924 T4214 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica4 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:60455_
[junit4:junit4]   2> 1468924 T4214 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica5 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:60464_
[junit4:junit4]   2> 1468928 T4239 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard1_replica1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\awholynewcollection_0_shard1_replica1
[junit4:junit4]   2> 1468931 T4226 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard1_replica2' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\awholynewcollection_0_shard1_replica2
[junit4:junit4]   2> 1468932 T4239 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4]   2> 1468933 T4253 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard1_replica4' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\awholynewcollection_0_shard1_replica4
[junit4:junit4]   2> 1468936 T4253 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4]   2> 1468936 T4208 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard1_replica3' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\awholynewcollection_0_shard1_replica3
[junit4:junit4]   2> 1468937 T4208 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4]   2> 1468933 T4226 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4]   2> 1468938 T4253 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4]   2> 1468939 T4226 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4]   2> 1468939 T4226 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 1468937 T4239 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4]   2> 1468936 T4268 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard1_replica5' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\awholynewcollection_0_shard1_replica5
[junit4:junit4]   2> 1468941 T4268 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4]   2> 1468942 T4226 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 1468942 T4226 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4]   2> 1468940 T4239 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 1468939 T4253 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 1468939 T4208 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4]   2> 1468945 T4208 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 1468943 T4268 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4]   2> 1468946 T4268 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 1468949 T4253 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 1468951 T4253 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4]   2> 1468952 T4208 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 1468952 T4208 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4]   2> 1468954 T4268 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 1468954 T4268 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4]   2> 1468955 T4226 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4]   2> 1468953 T4239 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 1468957 T4239 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4]   2> 1468961 T4226 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\awholynewcollection_0_shard1_replica2\'
[junit4:junit4]   2> 1468963 T4253 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4]   2> 1468965 T4208 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4]   2> 1468966 T4268 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4]   2> 1468970 T4239 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4]   2> 1468976 T4253 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\awholynewcollection_0_shard1_replica4\'
[junit4:junit4]   2> 1468978 T4208 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\awholynewcollection_0_shard1_replica3\'
[junit4:junit4]   2> 1468988 T4239 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\awholynewcollection_0_shard1_replica1\'
[junit4:junit4]   2> 1468990 T4268 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\awholynewcollection_0_shard1_replica5\'
[junit4:junit4]   2> 1469124 T4253 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1469133 T4268 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1469166 T4208 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1469222 T4226 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1469252 T4253 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1469313 T4226 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1469317 T4268 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1469366 T4253 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1469369 T4208 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1469372 T4226 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1469376 T4253 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica4] Schema name=test
[junit4:junit4]   2> 1469376 T4239 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1469413 T4226 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica2] Schema name=test
[junit4:junit4]   2> 1469425 T4268 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1469427 T4208 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1469434 T4268 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica5] Schema name=test
[junit4:junit4]   2> 1469434 T4208 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica3] Schema name=test
[junit4:junit4]   2> 1469574 T4239 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1469792 T4239 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 1469800 T4239 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica1] Schema name=test
[junit4:junit4]   2> 1470302 T4213 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1470306 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:60455__nodes_used_collection_shard2_replica1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"nodes_used_collection_shard2_replica1",
[junit4:junit4]   2> 	  "collection":"nodes_used_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60455_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60455"}
[junit4:junit4]   2> 1470330 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:60437__nodes_used_collection_shard1_replica2",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"nodes_used_collection_shard1_replica2",
[junit4:junit4]   2> 	  "collection":"nodes_used_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60437_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60437"}
[junit4:junit4]   2> 1470355 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:60464__nodes_used_collection_shard1_replica1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"nodes_used_collection_shard1_replica1",
[junit4:junit4]   2> 	  "collection":"nodes_used_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60464_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60464"}
[junit4:junit4]   2> 1470389 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:60425__nodes_used_collection_shard2_replica2",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"nodes_used_collection_shard2_replica2",
[junit4:junit4]   2> 	  "collection":"nodes_used_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60425_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60425"}
[junit4:junit4]   2> 1470950 T4253 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1470966 T4253 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1470974 T4253 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1471055 T4226 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1471066 T4226 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1471071 T4226 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1471156 T4212 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1471157 T4244 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1471157 T4230 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1471158 T4258 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1471159 T4272 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1471163 T4287 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1471181 T4217 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1471182 T4289 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1471523 T4226 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1471547 T4253 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1471553 T4226 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1471559 T4253 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1471564 T4226 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1471580 T4253 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1471626 T4239 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1471639 T4239 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1471645 T4239 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1471707 T4226 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1471708 T4226 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1471708 T4226 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1471709 T4253 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1471710 T4253 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1471711 T4253 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1471715 T4226 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1471716 T4226 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1471716 T4226 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1471717 T4226 oasc.SolrCore.<init> [awholynewcollection_0_shard1_replica2] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\awholynewcollection_0_shard1_replica2\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\awholynewcollection_0_shard1_replica2\data\
[junit4:junit4]   2> 1471717 T4226 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@24769ece
[junit4:junit4]   2> 1471718 T4226 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1471720 T4253 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1471721 T4253 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1471722 T4253 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1471722 T4253 oasc.SolrCore.<init> [awholynewcollection_0_shard1_replica4] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\awholynewcollection_0_shard1_replica4\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\awholynewcollection_0_shard1_replica4\data\
[junit4:junit4]   2> 1471723 T4253 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@24769ece
[junit4:junit4]   2> 1471723 T4253 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1471729 T4208 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1471738 T4253 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\awholynewcollection_0_shard1_replica4\data\
[junit4:junit4]   2> 1471741 T4253 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\awholynewcollection_0_shard1_replica4\data\index/
[junit4:junit4]   2> 1471744 T4253 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard1_replica4] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\awholynewcollection_0_shard1_replica4\data\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1471740 T4226 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\awholynewcollection_0_shard1_replica2\data\
[junit4:junit4]   2> 1471746 T4226 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\awholynewcollection_0_shard1_replica2\data\index/
[junit4:junit4]   2> 1471745 T4253 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\awholynewcollection_0_shard1_replica4\data\index
[junit4:junit4]   2> 1471744 T4239 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1471746 T4226 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard1_replica2] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\awholynewcollection_0_shard1_replica2\data\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1471756 T4239 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1471762 T4268 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1471764 T4239 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1471766 T4239 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1471767 T4239 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1471767 T4239 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1471771 T4239 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1471772 T4239 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1471772 T4239 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1471773 T4239 oasc.SolrCore.<init> [awholynewcollection_0_shard1_replica1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\awholynewcollection_0_shard1_replica1\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\awholynewcollection_0_shard1_replica1\data\
[junit4:junit4]   2> 1471773 T4239 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@24769ece
[junit4:junit4]   2> 1471774 T4239 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1471774 T4268 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1471775 T4208 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1471780 T4268 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1471781 T4208 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1471785 T4226 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\awholynewcollection_0_shard1_replica2\data\index
[junit4:junit4]   2> 1471789 T4239 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\awholynewcollection_0_shard1_replica1\data\
[junit4:junit4]   2> 1471791 T4239 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\awholynewcollection_0_shard1_replica1\data\index/
[junit4:junit4]   2> 1471792 T4239 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard1_replica1] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\awholynewcollection_0_shard1_replica1\data\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1471793 T4239 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\awholynewcollection_0_shard1_replica1\data\index
[junit4:junit4]   2> 1471820 T4226 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@52791789 lockFactory=org.apache.lucene.store.NativeFSLockFactory@70c81b76),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1471822 T4268 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1471821 T4253 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7f5883c9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5f7ae0bb),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1471823 T4253 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1471823 T4208 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1471821 T4239 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3c463b7c lockFactory=org.apache.lucene.store.NativeFSLockFactory@7aaee686),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1471824 T4239 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1471828 T4253 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1471828 T4253 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1471829 T4253 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1471831 T4253 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1471822 T4226 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1471833 T4239 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1471834 T4239 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1471835 T4239 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1471836 T4239 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1471836 T4239 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1471837 T4239 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1471838 T4239 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1471839 T4239 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1471839 T4226 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1471840 T4226 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1471841 T4226 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1471840 T4239 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1471842 T4226 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1471843 T4226 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1471844 T4226 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1471844 T4226 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1471845 T4226 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1471846 T4226 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1471840 T4253 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1471847 T4253 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1471848 T4253 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1471849 T4253 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1471849 T4253 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1471867 T4239 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1471869 T4253 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1471869 T4226 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1471881 T4268 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1471886 T4208 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1471887 T4253 oass.SolrIndexSearcher.<init> Opening Searcher@153c1581 main
[junit4:junit4]   2> 1471888 T4253 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1368895001224\awholynewcollection_0_shard1_replica4\data\tlog
[junit4:junit4]   2> 1471890 T4226 oass.SolrIndexSearcher.<init> Opening Searcher@62ecee98 main
[junit4:junit4]   2> 1471894 T4268 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1471896 T4226 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1368894997005\awholynewcollection_0_shard1_replica2\data\tlog
[junit4:junit4]   2> 1471898 T4208 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1471892 T4239 oass.SolrIndexSearcher.<init> Opening Searcher@24e58d7d main
[junit4:junit4]   2> 1471892 T4253 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1471900 T4253 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1471900 T4268 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1471902 T4268 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1471903 T4268 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1471899 T4239 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1368894999080\awholynewcollection_0_shard1_replica1\data\tlog
[junit4:junit4]   2> 1471907 T4239 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1471907 T4239 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1471909 T4253 oasc.ZkController.publish publishing core=awholynewcollection_0_shard1_replica4 state=down
[junit4:junit4]   2> 1471898 T4226 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1471911 T4226 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1471910 T4291 oasc.SolrCore.registerSearcher [awholynewcollection_0_shard1_replica4] Registered new searcher Searcher@153c1581 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1471913 T4292 oasc.SolrCore.registerSearcher [awholynewcollection_0_shard1_replica1] Registered new searcher Searcher@24e58d7d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1471903 T4208 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1471914 T4208 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1471915 T4208 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1471919 T4239 oasc.ZkController.publish publishing core=awholynewcollection_0_shard1_replica1 state=down
[junit4:junit4]   2> 1471919 T4226 oasc.ZkController.publish publishing core=awholynewcollection_0_shard1_replica2 state=down
[junit4:junit4]   2> 1471919 T4293 oasc.SolrCore.registerSearcher [awholynewcollection_0_shard1_replica2] Registered new searcher Searcher@62ecee98 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1471989 T4268 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1471990 T4268 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1471990 T4268 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1471991 T4268 oasc.SolrCore.<init> [awholynewcollection_0_shard1_replica5] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\awholynewcollection_0_shard1_replica5\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\awholynewcollection_0_shard1_replica5\data\
[junit4:junit4]   2> 1471991 T4268 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@24769ece
[junit4:junit4]   2> 1471991 T4268 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1471992 T4268 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\awholynewcollection_0_shard1_replica5\data\
[junit4:junit4]   2> 1471993 T4268 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\awholynewcollection_0_shard1_replica5\data\index/
[junit4:junit4]   2> 1471993 T4268 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard1_replica5] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\awholynewcollection_0_shard1_replica5\data\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1471993 T4268 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\awholynewcollection_0_shard1_replica5\data\index
[junit4:junit4]   2> 1471997 T4268 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2d318fc0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ffddf72),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1471998 T4268 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1472002 T4268 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1472003 T4268 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1472003 T4268 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1472004 T4268 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1472004 T4268 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1472005 T4268 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1472005 T4268 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1472006 T4268 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1472006 T4268 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1472013 T4250 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:60425__nodes_used_collection_shard2_replica2, state: recovering, checkLive: true, onlyIfLeader: true for: 3 seconds.
[junit4:junit4]   2> 1472013 T4250 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:60425__nodes_used_collection_shard2_replica2&state=recovering&nodeName=127.0.0.1:60425_&action=PREPRECOVERY&checkLive=true&core=nodes_used_collection_shard2_replica1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=3161 
[junit4:junit4]   2> 1472015 T4225 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:60464__nodes_used_collection_shard1_replica1, state: recovering, checkLive: true, onlyIfLeader: true for: 3 seconds.
[junit4:junit4]   2> 1472015 T4225 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:60464__nodes_used_collection_shard1_replica1&state=recovering&nodeName=127.0.0.1:60464_&action=PREPRECOVERY&checkLive=true&core=nodes_used_collection_shard1_replica2&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=3213 
[junit4:junit4]   2> 1472019 T4268 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1472027 T4268 oass.SolrIndexSearcher.<init> Opening Searcher@6acc0571 main
[junit4:junit4]   2> 1472028 T4268 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\awholynewcollection_0_shard1_replica5\data\tlog
[junit4:junit4]   2> 1472030 T4268 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1472030 T4268 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1472033 T4294 oasc.SolrCore.registerSearcher [awholynewcollection_0_shard1_replica5] Registered new searcher Searcher@6acc0571 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1472034 T4268 oasc.ZkController.publish publishing core=awholynewcollection_0_shard1_replica5 state=down
[junit4:junit4]   2> 1472101 T4208 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1472102 T4208 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 1472103 T4208 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1472113 T4208 oasc.SolrCore.<init> [awholynewcollection_0_shard1_replica3] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\awholynewcollection_0_shard1_replica3\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\awholynewcollection_0_shard1_replica3\data\
[junit4:junit4]   2> 1472113 T4208 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@24769ece
[junit4:junit4]   2> 1472114 T4208 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1472114 T4208 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\awholynewcollection_0_shard1_replica3\data\
[junit4:junit4]   2> 1472115 T4208 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\awholynewcollection_0_shard1_replica3\data\index/
[junit4:junit4]   2> 1472115 T4208 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard1_replica3] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\awholynewcollection_0_shard1_replica3\data\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1472115 T4208 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\awholynewcollection_0_shard1_replica3\data\index
[junit4:junit4]   2> 1472123 T4208 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6421ac87 lockFactory=org.apache.lucene.store.NativeFSLockFactory@409fe330),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1472124 T4208 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1472130 T4208 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1472130 T4208 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1472131 T4208 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1472131 T4208 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1472132 T4208 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1472132 T4208 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1472132 T4208 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1472133 T4208 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1472133 T4208 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1472142 T4208 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1472149 T4208 oass.SolrIndexSearcher.<init> Opening Searcher@66d284cc main
[junit4:junit4]   2> 1472150 T4208 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\awholynewcollection_0_shard1_replica3\data\tlog
[junit4:junit4]   2> 1472153 T4208 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1472153 T4208 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1472156 T4295 oasc.SolrCore.registerSearcher [awholynewcollection_0_shard1_replica3] Registered new searcher Searcher@66d284cc main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1472158 T4208 oasc.ZkController.publish publishing core=awholynewcollection_0_shard1_replica3 state=down
[junit4:junit4]   2> 1472909 T4213 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1472911 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"awholynewcollection_0_shard1_replica4",
[junit4:junit4]   2> 	  "collection":"awholynewcollection_0",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60455_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60455"}
[junit4:junit4]   2> 1472911 T4213 oasc.Overseer$ClusterStateUpdater.createCollection Create collection awholynewcollection_0 with numShards 1
[junit4:junit4]   2> 1472920 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"awholynewcollection_0_shard1_replica1",
[junit4:junit4]   2> 	  "collection":"awholynewcollection_0",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60446_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60446"}
[junit4:junit4]   2> 1472928 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"awholynewcollection_0_shard1_replica2",
[junit4:junit4]   2> 	  "collection":"awholynewcollection_0",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60437_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60437"}
[junit4:junit4]   2> 1472934 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"awholynewcollection_0_shard1_replica5",
[junit4:junit4]   2> 	  "collection":"awholynewcollection_0",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60464_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60464"}
[junit4:junit4]   2> 1472942 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"awholynewcollection_0_shard1_replica3",
[junit4:junit4]   2> 	  "collection":"awholynewcollection_0",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60425_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60425"}
[junit4:junit4]   2> 1472952 T4272 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1472952 T4217 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1472953 T4287 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1472952 T4258 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1472953 T4289 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1472953 T4212 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1472952 T4244 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1472952 T4230 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1472979 T4253 oasc.CoreContainer.registerCore registering core: awholynewcollection_0_shard1_replica4
[junit4:junit4]   2> 1472980 T4253 oasc.ZkController.register Register replica - core:awholynewcollection_0_shard1_replica4 address:http://127.0.0.1:60455 collection:awholynewcollection_0 shard:shard1
[junit4:junit4]   2> 1472981 T4253 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0/leader_elect/shard1/election
[junit4:junit4]   2> 1472998 T4253 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 1473006 T4253 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Waiting until we see more replicas up: total=5 found=1 timeoutin=179999
[junit4:junit4]   2> 1473092 T4226 oasc.CoreContainer.registerCore registering core: awholynewcollection_0_shard1_replica2
[junit4:junit4]   2> 1473092 T4226 oasc.ZkController.register Register replica - core:awholynewcollection_0_shard1_replica2 address:http://127.0.0.1:60437 collection:awholynewcollection_0 shard:shard1
[junit4:junit4]   2> 1473092 T4239 oasc.CoreContainer.registerCore registering core: awholynewcollection_0_shard1_replica1
[junit4:junit4]   2> 1473093 T4239 oasc.ZkController.register Register replica - core:awholynewcollection_0_shard1_replica1 address:http://127.0.0.1:60446 collection:awholynewcollection_0 shard:shard1
[junit4:junit4]   2> 1473103 T4268 oasc.CoreContainer.registerCore registering core: awholynewcollection_0_shard1_replica5
[junit4:junit4]   2> 1473103 T4268 oasc.ZkController.register Register replica - core:awholynewcollection_0_shard1_replica5 address:http://127.0.0.1:60464 collection:awholynewcollection_0 shard:shard1
[junit4:junit4]   2> 1473154 T4208 oasc.CoreContainer.registerCore registering core: awholynewcollection_0_shard1_replica3
[junit4:junit4]   2> 1473155 T4208 oasc.ZkController.register Register replica - core:awholynewcollection_0_shard1_replica3 address:http://127.0.0.1:60425 collection:awholynewcollection_0 shard:shard1
[junit4:junit4]   2> 1473504 T4253 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 1473504 T4253 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 1473504 T4253 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:60455/awholynewcollection_0_shard1_replica4/
[junit4:junit4]   2> 1473505 T4253 oasu.PeerSync.sync PeerSync: core=awholynewcollection_0_shard1_replica4 url=http://127.0.0.1:60455 START replicas=[http://127.0.0.1:60446/awholynewcollection_0_shard1_replica1/, http://127.0.0.1:60437/awholynewcollection_0_shard1_replica2/, http://127.0.0.1:60464/awholynewcollection_0_shard1_replica5/, http://127.0.0.1:60425/awholynewcollection_0_shard1_replica3/] nUpdates=100
[junit4:junit4]   2> 1473511 T4253 oasu.PeerSync.sync PeerSync: core=awholynewcollection_0_shard1_replica4 url=http://127.0.0.1:60455 DONE.  We have no versions.  sync failed.
[junit4:junit4]   2> 1473523 T4253 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4]   2> 1473524 T4253 oasc.ShardLeaderElectionContext.runLeaderProcess We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4:junit4]   2> 1473524 T4253 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:60455/awholynewcollection_0_shard1_replica4/
[junit4:junit4]   2> 1473524 T4253 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0/leaders/shard1
[junit4:junit4]   2> ASYNC  NEW_CORE C273 name=awholynewcollection_0_shard1_replica5 org.apache.solr.core.SolrCore@4fa156f2 url=http://127.0.0.1:60464/awholynewcollection_0_shard1_replica5 node=127.0.0.1:60464_ C273_STATE=coll:awholynewcollection_0 core:awholynewcollection_0_shard1_replica5 props:{shard=shard1, state=down, core=awholynewcollection_0_shard1_replica5, collection=awholynewcollection_0, node_name=127.0.0.1:60464_, base_url=http://127.0.0.1:60464}
[junit4:junit4]   2> 1473528 T4264 C273 P60464 oasc.SolrCore.execute [awholynewcollection_0_shard1_replica5] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=4 
[junit4:junit4]   2> ASYNC  NEW_CORE C274 name=awholynewcollection_0_shard1_replica1 org.apache.solr.core.SolrCore@35b52946 url=http://127.0.0.1:60446/awholynewcollection_0_shard1_replica1 node=127.0.0.1:60446_ C274_STATE=coll:awholynewcollection_0 core:awholynewcollection_0_shard1_replica1 props:{shard=shard1, state=down, core=awholynewcollection_0_shard1_replica1, collection=awholynewcollection_0, node_name=127.0.0.1:60446_, base_url=http://127.0.0.1:60446}
[junit4:junit4]   2> 1473529 T4235 C274 P60446 oasc.SolrCore.execute [awholynewcollection_0_shard1_replica1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=6 
[junit4:junit4]   2> ASYNC  NEW_CORE C275 name=awholynewcollection_0_shard1_replica2 org.apache.solr.core.SolrCore@5fe5d56e url=http://127.0.0.1:60437/awholynewcollection_0_shard1_replica2 node=127.0.0.1:60437_ C275_STATE=coll:awholynewcollection_0 core:awholynewcollection_0_shard1_replica2 props:{shard=shard1, state=down, core=awholynewcollection_0_shard1_replica2, collection=awholynewcollection_0, node_name=127.0.0.1:60437_, base_url=http://127.0.0.1:60437}
[junit4:junit4]   2> 1473537 T4222 C275 P60437 oasc.SolrCore.execute [awholynewcollection_0_shard1_replica2] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1 
[junit4:junit4]   2> ASYNC  NEW_CORE C276 name=awholynewcollection_0_shard1_replica3 org.apache.solr.core.SolrCore@3f338c1e url=http://127.0.0.1:60425/awholynewcollection_0_shard1_replica3 node=127.0.0.1:60425_ C276_STATE=coll:awholynewcollection_0 core:awholynewcollection_0_shard1_replica3 props:{shard=shard1, state=down, core=awholynewcollection_0_shard1_replica3, collection=awholynewcollection_0, node_name=127.0.0.1:60425_, base_url=http://127.0.0.1:60425}
[junit4:junit4]   2> 1473544 T4205 C276 P60425 oasc.SolrCore.execute [awholynewcollection_0_shard1_replica3] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1 
[junit4:junit4]   2>  C272_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica2 props:{shard=shard2, state=recovering, core=nodes_used_collection_shard2_replica2, collection=nodes_used_collection, node_name=127.0.0.1:60425_, base_url=http://127.0.0.1:60425}
[junit4:junit4]   2> 1473994 T4285 C272 P60425 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:60455/nodes_used_collection_shard2_replica1/ core=nodes_used_collection_shard2_replica2 - recoveringAfterStartup=true
[junit4:junit4]   2> 1473994 T4285 C272 P60425 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard2_replica2 url=http://127.0.0.1:60425 START replicas=[http://127.0.0.1:60455/nodes_used_collection_shard2_replica1/] nUpdates=100
[junit4:junit4]   2> 1473995 T4285 C272 P60425 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 1473995 T4285 C272 P60425 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=nodes_used_collection_shard2_replica2
[junit4:junit4]   2> 1473996 T4285 C272 P60425 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=nodes_used_collection_shard2_replica2
[junit4:junit4]   2> 1473996 T4285 C272 P60425 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=nodes_used_collection_shard2_replica2
[junit4:junit4]   2> 1473996 T4285 C272 P60425 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 1473996 T4285 C272 P60425 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:60455/nodes_used_collection_shard2_replica1/. core=nodes_used_collection_shard2_replica2
[junit4:junit4]   2> 1473997 T4285 C272 P60425 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2>  C271_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica1 props:{shard=shard1, state=recovering, core=nodes_used_collection_shard1_replica1, collection=nodes_used_collection, node_name=127.0.0.1:60464_, base_url=http://127.0.0.1:60464}
[junit4:junit4]   2> 1473997 T4284 C271 P60464 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:60437/nodes_used_collection_shard1_replica2/ core=nodes_used_collection_shard1_replica1 - recoveringAfterStartup=true
[junit4:junit4]   2> 1473998 T4284 C271 P60464 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard1_replica1 url=http://127.0.0.1:60464 START replicas=[http://127.0.0.1:60437/nodes_used_collection_shard1_replica2/] nUpdates=100
[junit4:junit4]   2> 1473999 T4284 C271 P60464 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 1473999 T4284 C271 P60464 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=nodes_used_collection_shard1_replica1
[junit4:junit4]   2> 1473999 T4284 C271 P60464 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=nodes_used_collection_shard1_replica1
[junit4:junit4]   2> 1473999 T4284 C271 P60464 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=nodes_used_collection_shard1_replica1
[junit4:junit4]   2> 1474000 T4284 C271 P60464 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 1474001 T4284 C271 P60464 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:60437/nodes_used_collection_shard1_replica2/. core=nodes_used_collection_shard1_replica1
[junit4:junit4]   2> 1474001 T4284 C271 P60464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C277 name=nodes_used_collection_shard2_replica1 org.apache.solr.core.SolrCore@6ce85c77 url=http://127.0.0.1:60455/nodes_used_collection_shard2_replica1 node=127.0.0.1:60455_ C277_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica1 props:{shard=shard2, state=active, core=nodes_used_collection_shard2_replica1, collection=nodes_used_collection, node_name=127.0.0.1:60455_, base_url=http://127.0.0.1:60455, leader=true}
[junit4:junit4]   2> 1474033 T4250 C277 P60455 oasc.SolrCore.execute [nodes_used_collection_shard2_replica1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=25 
[junit4:junit4]   2> 1474042 T4254 C277 P60455 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> ASYNC  NEW_CORE C278 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@71fc9a0a url=http://127.0.0.1:60437/nodes_used_collection_shard1_replica2 node=127.0.0.1:60437_ C278_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica2 props:{shard=shard1, state=active, core=nodes_used_collection_shard1_replica2, collection=nodes_used_collection, node_name=127.0.0.1:60437_, base_url=http://127.0.0.1:60437, leader=true}
[junit4:junit4]   2> 1474051 T4221 C278 P60437 oasc.SolrCore.execute [nodes_used_collection_shard1_replica2] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1 
[junit4:junit4]   2> 1474053 T4254 C277 P60455 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4e335015 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d66b0d3),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1474056 T4254 C277 P60455 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1474057 T4223 C278 P60437 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 1474057 T4254 C277 P60455 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4e335015 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d66b0d3),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4e335015 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d66b0d3),segFN=segments_2,generation=2}
[junit4:junit4]   2> 1474058 T4254 C277 P60455 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 1474059 T4254 C277 P60455 oass.SolrIndexSearcher.<init> Opening Searcher@4cf9914a realtime
[junit4:junit4]   2> 1474059 T4254 C277 P60455 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1474059 T4254 C277 P60455 oasup.LogUpdateProcessor.finish [nodes_used_collection_shard2_replica1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 17
[junit4:junit4]   2> 1474061 T4285 C272 P60425 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 1474061 T4285 C272 P60425 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 1474062 T4223 C278 P60437 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b6382d lockFactory=org.apache.lucene.store.NativeFSLockFactory@16506dc0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 1474062 T4223 C278 P60437 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 1474064 T4223 C278 P60437 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b6382d lockFactory=org.apache.lucene.store.NativeFSLockFactory@16506dc0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b6382d lockFactory=org.apache.lucene.store.NativeFSLockFactory@16506dc0),segFN=segments_2,generation=2}
[junit4:junit4]   2> 1474064 T4223 C278 P60437 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 1474064 T4252 C277 P60455 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 1474065 T4223 C278 P60437 oass.SolrIndexSearcher.<init> Opening Searcher@26535437 realtime
[junit4:junit4]   2> 1474065 T4223 C278 P60437 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1474065 T4252 C277 P60455 oasc.SolrCore.execute [nodes_used_collection_shard2_replica1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   2> 1474066 T4223 C278 P60437 oasup.LogUpdateProcessor.finish [nodes_used_collection_shard1_replica2] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4]   2> 1474067 T4285 C272 P60425 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 1474067 T4285 C272 P60425 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 1474067 T4285 C272 P60425 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 1474067 T4284 C271 P60464 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 1474068 T4284 C271 P60464 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 1474074 T4251 C277 P60455 oasc.SolrCore.execute [nodes_used_collection_shard2_replica1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1 
[junit4:junit4]   2> 1474075 T4285 C272 P60425 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 1474075 T4224 C278 P60437 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 1474083 T4224 C278 P60437 oasc.SolrCore.execute [nodes_used_collection_shard1_replica2] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=9 
[junit4:junit4]   2> 1474084 T4285 C272 P60425 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\nodes_used_collection_shard2_replica2\data\index.20130518183655765
[junit4:junit4]   2> 1474084 T4285 C272 P60425 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@5882f052 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4df40479) fullCopy=false
[junit4:junit4]   2> 1474084 T4284 C271 P60464 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 1474084 T4284 C271 P60464 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 1474085 T4284 C271 P60464 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 1474086 T4250 C277 P60455 oasc.SolrCore.execute [nodes_used_collection_shard2_replica1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 1474088 T4222 C278 P60437 oasc.SolrCore.execute [nodes_used_collection_shard1_replica2] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1 
[junit4:junit4]   2> 1474089 T4285 C272 P60425 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 1474090 T4284 C271 P60464 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 1474091 T4285 C272 P60425 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 1474093 T4285 C272 P60425 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=nodes_used_collection_shard2_replica2
[junit4:junit4]   2> 1474093 T4284 C271 P60464 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\nodes_used_collection_shard1_replica1\data\index.20130518183655780
[junit4:junit4]   2> 1474093 T4284 C271 P60464 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@447eb677 lockFactory=org.apache.lucene.store.NativeFSLockFactory@74d2f15f) fullCopy=false
[junit4:junit4]   2> 1474096 T4225 C278 P60437 oasc.SolrCore.execute [nodes_used_collection_shard1_replica2] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1 
[junit4:junit4]   2> 1474096 T4285 C272 P60425 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@202ba2e lockFactory=org.apache.lucene.store.NativeFSLockFactory@61cda73d),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@202ba2e lockFactory=org.apache.lucene.store.NativeFSLockFactory@61cda73d),segFN=segments_2,generation=2}
[junit4:junit4]   2> 1474097 T4285 C272 P60425 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 1474097 T4285 C272 P60425 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 1474098 T4285 C272 P60425 oass.SolrIndexSearcher.<init> Opening Searcher@5f4e906a main
[junit4:junit4]   2> 1474098 T4284 C271 P60464 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 1474099 T4281 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica2] Registered new searcher Searcher@5f4e906a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1474103 T4284 C271 P60464 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 1474103 T4284 C271 P60464 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=nodes_used_collection_shard1_replica1
[junit4:junit4]   2> 1474104 T4285 C272 P60425 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\nodes_used_collection_shard2_replica2\data\index.20130518183655765 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\nodes_used_collection_shard2_replica2\data\index.20130518183655765;done=true>>]
[junit4:junit4]   2> 1474104 T4285 C272 P60425 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\nodes_used_collection_shard2_replica2\data\index.20130518183655765
[junit4:junit4]   2> 1474104 T4285 C272 P60425 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1368894996050\nodes_used_collection_shard2_replica2\data\index.20130518183655765
[junit4:junit4]   2> 1474105 T4285 C272 P60425 oasc.RecoveryStrategy.replay No replay needed. core=nodes_used_collection_shard2_replica2
[junit4:junit4]   2> 1474105 T4285 C272 P60425 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=nodes_used_collection_shard2_replica2
[junit4:junit4]   2> 1474105 T4285 C272 P60425 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica2 state=active
[junit4:junit4]   2> 1474108 T4284 C271 P60464 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4a8b1458 lockFactory=org.apache.lucene.store.NativeFSLockFactory@64caa55a),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4a8b1458 lockFactory=org.apache.lucene.store.NativeFSLockFactory@64caa55a),segFN=segments_2,generation=2}
[junit4:junit4]   2> 1474109 T4284 C271 P60464 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 1474109 T4284 C271 P60464 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 1474110 T4284 C271 P60464 oass.SolrIndexSearcher.<init> Opening Searcher@7c7ceb1 main
[junit4:junit4]   2> 1474111 T4280 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica1] Registered new searcher Searcher@7c7ceb1 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 1474111 T4284 C271 P60464 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\nodes_used_collection_shard1_replica1\data\index.20130518183655780 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\nodes_used_collection_shard1_replica1\data\index.20130518183655780;done=true>>]
[junit4:junit4]   2> 1474111 T4284 C271 P60464 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\nodes_used_collection_shard1_replica1\data\index.20130518183655780
[junit4:junit4]   2> 1474111 T4284 C271 P60464 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1368895003373\nodes_used_collection_shard1_replica1\data\index.20130518183655780
[junit4:junit4]   2> 1474112 T4284 C271 P60464 oasc.RecoveryStrategy.replay No replay needed. core=nodes_used_collection_shard1_replica1
[junit4:junit4]   2> 1474112 T4284 C271 P60464 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=nodes_used_collection_shard1_replica1
[junit4:junit4]   2> 1474112 T4284 C271 P60464 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica1 state=active
[junit4:junit4]   2> 1474112 T4285 C272 P60425 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=nodes_used_collection_shard2_replica2
[junit4:junit4]   2> 1474115 T4284 C271 P60464 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=nodes_used_collection_shard1_replica1
[junit4:junit4]   2> 1474464 T4213 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1474501 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:60425__nodes_used_collection_shard2_replica2",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"nodes_used_collection_shard2_replica2",
[junit4:junit4]   2> 	  "collection":"nodes_used_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60425_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60425"}
[junit4:junit4]   2> 1474511 T4213 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:60464__nodes_used_collection_shard1_replica1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"nodes_used_collection_shard1_replica1",
[junit4:junit4]   2> 	  "collection":"nodes_used_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60464_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60464"}
[junit4:junit4]   2> 1474523 T4217 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1474524 T4244 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1474525 T4212 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1474524 T4289 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1474524 T4287 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 1474524 T4272 oascc.ZkStateReader$2.process A cluster state c

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

 /solr/collections/awholynewcollection_1/leader_elect/shard2/election/89711902448222216-127.0.0.1:60446__awholynewcollection_1_shard2_replica2-n_0000000002 (0)
[junit4:junit4]   1>      /solr/collections/awholynewcollection_1/leader_elect/shard3 (1)
[junit4:junit4]   1>       /solr/collections/awholynewcollection_1/leader_elect/shard3/election (3)
[junit4:junit4]   1>        /solr/collections/awholynewcollection_1/leader_elect/shard3/election/89711902448222211-127.0.0.1:60425__awholynewcollection_1_shard3_replica3-n_0000000002 (0)
[junit4:junit4]   1>        /solr/collections/awholynewcollection_1/leader_elect/shard3/election/89711902448222214-127.0.0.1:60437__awholynewcollection_1_shard3_replica1-n_0000000001 (0)
[junit4:junit4]   1>        /solr/collections/awholynewcollection_1/leader_elect/shard3/election/89711902448222218-127.0.0.1:60455__awholynewcollection_1_shard3_replica2-n_0000000000 (0)
[junit4:junit4]   1>     /solr/collections/awholynewcollection_1/leaders (4)
[junit4:junit4]   1>      /solr/collections/awholynewcollection_1/leaders/shard1 (0)
[junit4:junit4]   1>      DATA:
[junit4:junit4]   1>          {
[junit4:junit4]   1>            "core":"awholynewcollection_1_shard1_replica2",
[junit4:junit4]   1>            "node_name":"127.0.0.1:60437_",
[junit4:junit4]   1>            "base_url":"http://127.0.0.1:60437"}
[junit4:junit4]   1>      /solr/collections/awholynewcollection_1/leaders/shard4 (0)
[junit4:junit4]   1>      DATA:
[junit4:junit4]   1>          {
[junit4:junit4]   1>            "core":"awholynewcollection_1_shard4_replica2",
[junit4:junit4]   1>            "node_name":"127.0.0.1:60464_",
[junit4:junit4]   1>            "base_url":"http://127.0.0.1:60464"}
[junit4:junit4]   1>      /solr/collections/awholynewcollection_1/leaders/shard2 (0)
[junit4:junit4]   1>      DATA:
[junit4:junit4]   1>          {
[junit4:junit4]   1>            "core":"awholynewcollection_1_shard2_replica3",
[junit4:junit4]   1>            "node_name":"127.0.0.1:60464_",
[junit4:junit4]   1>            "base_url":"http://127.0.0.1:60464"}
[junit4:junit4]   1>      /solr/collections/awholynewcollection_1/leaders/shard3 (0)
[junit4:junit4]   1>      DATA:
[junit4:junit4]   1>          {
[junit4:junit4]   1>            "core":"awholynewcollection_1_shard3_replica2",
[junit4:junit4]   1>            "node_name":"127.0.0.1:60455_",
[junit4:junit4]   1>            "base_url":"http://127.0.0.1:60455"}
[junit4:junit4]   1>   /solr/overseer_elect (2)
[junit4:junit4]   1>    /solr/overseer_elect/election (5)
[junit4:junit4]   1>     /solr/overseer_elect/election/89711902448222220-127.0.0.1:60464_-n_0000000004 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89711902448222216-127.0.0.1:60446_-n_0000000002 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89711902448222214-127.0.0.1:60437_-n_0000000001 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89711902448222218-127.0.0.1:60455_-n_0000000003 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89711902448222211-127.0.0.1:60425_-n_0000000000 (0)
[junit4:junit4]   1>    /solr/overseer_elect/leader (0)
[junit4:junit4]   1>    DATA:
[junit4:junit4]   1>        {"id":"89711902448222211-127.0.0.1:60425_-n_0000000000"}
[junit4:junit4]   1>  /zookeeper (1)
[junit4:junit4]   1>  DATA:
[junit4:junit4]   1>      
[junit4:junit4]   1> 
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=CollectionsAPIDistributedZkTest -Dtests.method=testDistribSearch -Dtests.seed=7DA14641F86B0A99 -Dtests.slow=true -Dtests.locale=es_CL -Dtests.timezone=Africa/Lubumbashi -Dtests.file.encoding=Cp1252
[junit4:junit4] FAILURE  321s | CollectionsAPIDistributedZkTest.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: java.lang.AssertionError: There are still nodes recoverying - waited for 230 seconds
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([7DA14641F86B0A99:FC47C8598F346AA5]:0)
[junit4:junit4]    > 	at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:173)
[junit4:junit4]    > 	at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:131)
[junit4:junit4]    > 	at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:126)
[junit4:junit4]    > 	at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollectionsAPI(CollectionsAPIDistributedZkTest.java:512)
[junit4:junit4]    > 	at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.doTest(CollectionsAPIDistributedZkTest.java:146)
[junit4:junit4]    > 	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4]    > 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 1775264 T4190 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 321125 T4189 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4]   2> NOTE: test params are: codec=Lucene40, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=es_CL, timezone=Africa/Lubumbashi
[junit4:junit4]   2> NOTE: Windows 7 6.1 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=2,threads=1,free=172068232,total=357433344
[junit4:junit4]   2> NOTE: All tests run in this JVM: [BadCopyFieldTest, UpdateParamsTest, TestFastLRUCache, TestDefaultSimilarityFactory, QueryEqualityTest, SyncSliceTest, TestQueryTypes, TestReload, SolrCmdDistributorTest, XmlUpdateRequestHandlerTest, TestPseudoReturnFields, IndexBasedSpellCheckerTest, TimeZoneUtilsTest, TestAnalyzedSuggestions, TestLRUCache, RecoveryZkTest, ShardRoutingCustomTest, CoreContainerCoreInitFailuresTest, CurrencyFieldOpenExchangeTest, UpdateRequestProcessorFactoryTest, TestSweetSpotSimilarityFactory, TermsComponentTest, SolrTestCaseJ4Test, TestUpdate, OpenCloseCoreStressTest, TestDefaultSearchFieldResource, TestManagedSchemaFieldResource, TestJmxMonitoredMap, TestGroupingSearch, TestBinaryField, HighlighterConfigTest, TestStressVersions, ChaosMonkeyNothingIsSafeTest, TestCSVLoader, TestSchemaSimilarityResource, TestSerializedLuceneMatchVersion, TestLMJelinekMercerSimilarityFactory, TestCoreDiscovery, TestLFUCache, MoreLikeThisHandlerTest, PolyFieldTest, TestConfig, SortByFunctionTest, TestPropInject, StatsComponentTest, DocValuesMultiTest, TestDFRSimilarityFactory, LukeRequestHandlerTest, UUIDFieldTest, TestSystemIdResolver, SpatialFilterTest, DirectUpdateHandlerTest, PrimitiveFieldTypeTest, AnalysisAfterCoreReloadTest, SuggesterWFSTTest, UnloadDistributedZkTest, BasicFunctionalityTest, TestCSVResponseWriter, TestSearchPerf, DirectSolrSpellCheckerTest, FastVectorHighlighterTest, BinaryUpdateRequestHandlerTest, TestDistributedSearch, ZkNodePropsTest, TestFieldTypeCollectionResource, URLClassifyProcessorTest, DocValuesTest, TestBM25SimilarityFactory, TestCodecSupport, TestRecovery, TestFaceting, TestWordDelimiterFilterFactory, PathHierarchyTokenizerFactoryTest, TestLuceneMatchVersion, NotRequiredUniqueKeyTest, TestSchemaNameResource, ChaosMonkeyShardSplitTest, RequiredFieldsTest, SystemInfoHandlerTest, RequestHandlersTest, PrimUtilsTest, SuggesterTSTTest, CachingDirectoryFactoryTest, TestMultiCoreConfBootstrap, DistributedQueryElevationComponentTest, TestFiltering, TestFastWriter, ZkControllerTest, TestSuggestSpellingConverter, MultiTermTest, TestSolr4Spatial, TestAddFieldRealTimeGet, TestSolrXml, ZkCLITest, CSVRequestHandlerTest, TestSolrJ, RAMDirectoryFactoryTest, TestZkChroot, ChaosMonkeySafeLeaderTest, TestSolrQueryParserResource, TestFoldingMultitermQuery, MinimalSchemaTest, OutputWriterTest, LeaderElectionIntegrationTest, DisMaxRequestHandlerTest, ScriptEngineTest, SuggesterTest, QueryElevationComponentTest, TestHashPartitioner, SolrCoreTest, JsonLoaderTest, TestLMDirichletSimilarityFactory, TestRandomFaceting, TestSolrIndexConfig, ResourceLoaderTest, SearchHandlerTest, OverseerTest, TestQuerySenderListener, TestLazyCores, TestArbitraryIndexDir, TestUniqueKeyFieldResource, TestComponentsName, TestIndexSearcher, LoggingHandlerTest, TestSchemaResource, DistanceFunctionTest, SolrRequestParserTest, TestFieldCollectionResource, TestDocSet, BasicDistributedZk2Test, TestIBSimilarityFactory, PingRequestHandlerTest, TestDistributedGrouping, TestRTGBase, TestSolrXMLSerializer, FullSolrCloudDistribCmdsTest, TestQueryUtils, ExternalFileFieldSortTest, IndexSchemaRuntimeFieldTest, DOMUtilTest, CurrencyFieldXmlFileTest, BasicDistributedZkTest, CollectionsAPIDistributedZkTest]
[junit4:junit4] Completed in 322.43s, 1 test, 1 failure <<< FAILURES!

[...truncated 454 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:377: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:357: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build.xml:181: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\common-build.xml:437: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:1240: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:884: There were test failures: 295 suites, 1231 tests, 1 failure, 18 ignored (12 assumptions)

Total time: 65 minutes 42 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0_21 -XX:+UseCompressedOops -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message