You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/04 02:59:03 UTC
[JENKINS] Lucene-Solr-trunk-Windows (32bit/jdk1.7.0_21) - Build #
2888 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Windows/2888/
Java: 32bit/jdk1.7.0_21 -client -XX:+UseSerialGC
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([65A77A85F2F859A7:E441F49D85A7399B]: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 9367 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.CollectionsAPIDistributedZkTest
[junit4:junit4] 2> 838123 T2665 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 838127 T2665 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-1370305552400
[junit4:junit4] 2> 838131 T2665 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 838133 T2666 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 838234 T2665 oasc.ZkTestServer.run start zk server on port:59238
[junit4:junit4] 2> 838237 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 838254 T2672 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b9a19a name:ZooKeeperConnection Watcher:127.0.0.1:59238 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 838255 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 838255 T2665 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 838274 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 838279 T2674 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f1054e name:ZooKeeperConnection Watcher:127.0.0.1:59238/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 838279 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 838279 T2665 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 838290 T2665 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 838297 T2665 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 838303 T2665 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 838325 T2665 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> 838325 T2665 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 838364 T2665 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> 838365 T2665 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 838373 T2665 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> 838374 T2665 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 838380 T2665 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> 838381 T2665 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 838387 T2665 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> 838388 T2665 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 838394 T2665 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> 838394 T2665 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 838401 T2665 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> 838402 T2665 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 838409 T2665 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> 838410 T2665 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 838416 T2665 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> 838416 T2665 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 838928 T2665 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 838941 T2665 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59245
[junit4:junit4] 2> 838942 T2665 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 838942 T2665 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 838944 T2665 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-1370305552695
[junit4:junit4] 2> 838944 T2665 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-1370305552695\solr.xml
[junit4:junit4] 2> 838945 T2665 oasc.CoreContainer.<init> New CoreContainer 15801214
[junit4:junit4] 2> 838945 T2665 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-1370305552695\'
[junit4:junit4] 2> 838946 T2665 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-1370305552695\'
[junit4:junit4] 2> 839113 T2665 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-1370305552695
[junit4:junit4] 2> 839117 T2665 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-1370305552695\collection1
[junit4:junit4] 2> 839120 T2665 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-1370305552695\collection1\conf
[junit4:junit4] 2> 839401 T2665 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-1370305552695\collection1\conf\xslt
[junit4:junit4] 2> 839409 T2665 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-1370305552695\collection1\lib
[junit4:junit4] 2> 839412 T2665 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-1370305552695\collection1\lib\classes
[junit4:junit4] 2> 839418 T2665 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-1370305552695\conf\core.properties, adding to cores
[junit4:junit4] 2> 839437 T2665 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 839437 T2665 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 839438 T2665 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 839439 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 839439 T2665 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 839439 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 839439 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 839440 T2665 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 839440 T2665 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 839441 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 839450 T2665 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 839451 T2665 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:59238/solr
[junit4:junit4] 2> 839451 T2665 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 839454 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 839465 T2685 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1ca0c name:ZooKeeperConnection Watcher:127.0.0.1:59238 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 839465 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 839470 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 839471 T2667 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f0c93601f0002, 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> 839479 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 839483 T2687 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1964780 name:ZooKeeperConnection Watcher:127.0.0.1:59238/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 839484 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 839488 T2665 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 839497 T2665 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 839503 T2665 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 839508 T2665 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59245_
[junit4:junit4] 2> 839511 T2665 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59245_
[junit4:junit4] 2> 839520 T2665 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 839535 T2665 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 839540 T2665 oasc.Overseer.start Overseer (id=89804344683069443-127.0.0.1:59245_-n_0000000000) starting
[junit4:junit4] 2> 839549 T2665 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 839560 T2689 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 839563 T2665 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 839570 T2665 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 839575 T2665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 839581 T2688 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 839585 T2665 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 839586 T2665 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 839586 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 839591 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 839594 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 839599 T2692 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1498c1f name:ZooKeeperConnection Watcher:127.0.0.1:59238/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 839600 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 839602 T2665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 839607 T2665 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 840084 T2665 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 840088 T2665 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59257
[junit4:junit4] 2> 840088 T2665 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 840088 T2665 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 840089 T2665 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-1370305553877
[junit4:junit4] 2> 840089 T2665 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-1370305553877\solr.xml
[junit4:junit4] 2> 840089 T2665 oasc.CoreContainer.<init> New CoreContainer 20773283
[junit4:junit4] 2> 840090 T2665 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-1370305553877\'
[junit4:junit4] 2> 840091 T2665 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-1370305553877\'
[junit4:junit4] 2> 840210 T2665 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-1370305553877
[junit4:junit4] 2> 840212 T2665 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-1370305553877\collection1
[junit4:junit4] 2> 840213 T2665 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-1370305553877\collection1\conf
[junit4:junit4] 2> 840476 T2665 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-1370305553877\collection1\conf\xslt
[junit4:junit4] 2> 840484 T2665 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-1370305553877\collection1\lib
[junit4:junit4] 2> 840487 T2665 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-1370305553877\collection1\lib\classes
[junit4:junit4] 2> 840495 T2665 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-1370305553877\conf\core.properties, adding to cores
[junit4:junit4] 2> 840517 T2665 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 840518 T2665 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 840518 T2665 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 840519 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 840519 T2665 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 840520 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 840520 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 840520 T2665 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 840521 T2665 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 840521 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 840531 T2665 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 840532 T2665 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:59238/solr
[junit4:junit4] 2> 840533 T2665 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 840535 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 840548 T2703 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@124bf98 name:ZooKeeperConnection Watcher:127.0.0.1:59238 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 840549 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 840553 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 840553 T2667 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f0c93601f0005, 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> 840561 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 840564 T2705 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@dc1ff5 name:ZooKeeperConnection Watcher:127.0.0.1:59238/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 840565 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 840573 T2665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 841577 T2665 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59257_
[junit4:junit4] 2> 841585 T2665 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59257_
[junit4:junit4] 2> 841593 T2692 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 841593 T2687 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 841594 T2705 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 841606 T2665 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 841607 T2665 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 841607 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 842075 T2665 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 842080 T2665 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59266
[junit4:junit4] 2> 842081 T2665 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 842081 T2665 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 842082 T2665 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-1370305555885
[junit4:junit4] 2> 842082 T2665 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-1370305555885\solr.xml
[junit4:junit4] 2> 842082 T2665 oasc.CoreContainer.<init> New CoreContainer 18031456
[junit4:junit4] 2> 842082 T2665 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-1370305555885\'
[junit4:junit4] 2> 842084 T2665 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-1370305555885\'
[junit4:junit4] 2> 842197 T2665 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-1370305555885
[junit4:junit4] 2> 842200 T2665 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-1370305555885\collection1
[junit4:junit4] 2> 842201 T2665 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-1370305555885\collection1\conf
[junit4:junit4] 2> 842441 T2665 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-1370305555885\collection1\conf\xslt
[junit4:junit4] 2> 842451 T2665 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-1370305555885\collection1\lib
[junit4:junit4] 2> 842454 T2665 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-1370305555885\collection1\lib\classes
[junit4:junit4] 2> 842460 T2665 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-1370305555885\conf\core.properties, adding to cores
[junit4:junit4] 2> 842479 T2665 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 842479 T2665 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 842479 T2665 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 842480 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 842480 T2665 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 842481 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 842481 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 842482 T2665 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 842482 T2665 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 842482 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 842491 T2665 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 842492 T2665 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:59238/solr
[junit4:junit4] 2> 842492 T2665 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 842494 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 842510 T2717 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@17c1578 name:ZooKeeperConnection Watcher:127.0.0.1:59238 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 842510 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 842514 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 842515 T2667 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f0c93601f0007, 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> 842522 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 842526 T2719 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ee4108 name:ZooKeeperConnection Watcher:127.0.0.1:59238/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 842527 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 842536 T2665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 843541 T2665 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59266_
[junit4:junit4] 2> 843547 T2665 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59266_
[junit4:junit4] 2> 843553 T2692 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 843554 T2687 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 843554 T2705 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 843554 T2719 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 843567 T2665 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 843568 T2665 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 843569 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 843989 T2665 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 843994 T2665 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59275
[junit4:junit4] 2> 843995 T2665 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 843995 T2665 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 843995 T2665 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-1370305557851
[junit4:junit4] 2> 843996 T2665 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-1370305557851\solr.xml
[junit4:junit4] 2> 843996 T2665 oasc.CoreContainer.<init> New CoreContainer 7810645
[junit4:junit4] 2> 843997 T2665 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-1370305557851\'
[junit4:junit4] 2> 843997 T2665 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-1370305557851\'
[junit4:junit4] 2> 844117 T2665 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-1370305557851
[junit4:junit4] 2> 844120 T2665 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-1370305557851\collection1
[junit4:junit4] 2> 844122 T2665 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-1370305557851\collection1\conf
[junit4:junit4] 2> 844356 T2665 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-1370305557851\collection1\conf\xslt
[junit4:junit4] 2> 844368 T2665 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-1370305557851\collection1\lib
[junit4:junit4] 2> 844372 T2665 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-1370305557851\collection1\lib\classes
[junit4:junit4] 2> 844380 T2665 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-1370305557851\conf\core.properties, adding to cores
[junit4:junit4] 2> 844398 T2665 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 844398 T2665 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 844398 T2665 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 844398 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 844399 T2665 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 844400 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 844400 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 844401 T2665 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 844401 T2665 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 844401 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 844410 T2665 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 844410 T2665 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:59238/solr
[junit4:junit4] 2> 844410 T2665 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 844412 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 844434 T2731 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6d99f name:ZooKeeperConnection Watcher:127.0.0.1:59238 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 844434 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 844440 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 844452 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 844457 T2733 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@df0c1f name:ZooKeeperConnection Watcher:127.0.0.1:59238/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 844458 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 844474 T2665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 845479 T2665 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59275_
[junit4:junit4] 2> 845482 T2665 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59275_
[junit4:junit4] 2> 845491 T2692 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 845491 T2719 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 845492 T2733 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 845492 T2705 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 845493 T2687 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 845507 T2665 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 845507 T2665 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 845508 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 845970 T2665 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 845975 T2665 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59284
[junit4:junit4] 2> 845975 T2665 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 845975 T2665 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 845975 T2665 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-1370305559783
[junit4:junit4] 2> 845977 T2665 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-1370305559783\solr.xml
[junit4:junit4] 2> 845977 T2665 oasc.CoreContainer.<init> New CoreContainer 15116011
[junit4:junit4] 2> 845977 T2665 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-1370305559783\'
[junit4:junit4] 2> 845978 T2665 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-1370305559783\'
[junit4:junit4] 2> 846080 T2665 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-1370305559783
[junit4:junit4] 2> 846081 T2665 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-1370305559783\collection1
[junit4:junit4] 2> 846084 T2665 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-1370305559783\collection1\conf
[junit4:junit4] 2> 846286 T2665 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-1370305559783\collection1\conf\xslt
[junit4:junit4] 2> 846293 T2665 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-1370305559783\collection1\lib
[junit4:junit4] 2> 846297 T2665 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-1370305559783\collection1\lib\classes
[junit4:junit4] 2> 846307 T2665 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-1370305559783\conf\core.properties, adding to cores
[junit4:junit4] 2> 846332 T2665 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 846332 T2665 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 846334 T2665 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 846334 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 846335 T2665 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 846335 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 846335 T2665 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 846335 T2665 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 846336 T2665 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 846336 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 846345 T2665 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 846345 T2665 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:59238/solr
[junit4:junit4] 2> 846346 T2665 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 846348 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 846368 T2745 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e25693 name:ZooKeeperConnection Watcher:127.0.0.1:59238 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 846369 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 846374 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 846397 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 846403 T2747 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@18320fd name:ZooKeeperConnection Watcher:127.0.0.1:59238/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 846403 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 846415 T2665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 847420 T2665 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59284_
[junit4:junit4] 2> 847423 T2665 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59284_
[junit4:junit4] 2> 847431 T2692 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 847432 T2687 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 847432 T2747 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 847433 T2719 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 847433 T2733 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 847433 T2705 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 847444 T2665 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 847444 T2665 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 847445 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 847454 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 847461 T2701 oasha.CollectionsHandler.handleCreateAction Creating Collection : numShards=2&name=nodes_used_collection&replicationFactor=2&action=CREATE&wt=javabin&version=2
[junit4:junit4] 2> 847465 T2687 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4] 2> 847469 T2689 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> 847469 T2689 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:59257_
[junit4:junit4] 2> 847470 T2689 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:59284_
[junit4:junit4] 2> 847471 T2689 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:59245_
[junit4:junit4] 2> 847472 T2689 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:59266_
[junit4:junit4] 2> 847474 T2740 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-jetty4-1370305559783\nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 847475 T2740 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4] 2> 847474 T2695 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-jetty1-1370305553877\nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 847475 T2695 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4] 2> 847475 T2680 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-controljetty-1370305552695\nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 847477 T2680 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4] 2> 847477 T2712 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-jetty2-1370305555885\nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 847478 T2712 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4] 2> 847476 T2740 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4] 2> 847478 T2680 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4] 2> 847480 T2680 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 847477 T2695 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4] 2> 847481 T2695 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 847481 T2712 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4] 2> 847482 T2712 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 847480 T2740 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 847484 T2680 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 847484 T2680 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4] 2> 847485 T2695 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 847486 T2695 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4] 2> 847487 T2712 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 847487 T2712 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4] 2> 847488 T2740 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 847489 T2740 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4] 2> 847492 T2695 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4] 2> 847493 T2680 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4] 2> 847496 T2712 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4] 2> 847498 T2695 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-1370305553877\nodes_used_collection_shard1_replica1\'
[junit4:junit4] 2> 847499 T2740 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4] 2> 847504 T2680 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-1370305552695\nodes_used_collection_shard2_replica1\'
[junit4:junit4] 2> 847515 T2740 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-1370305559783\nodes_used_collection_shard1_replica2\'
[junit4:junit4] 2> 847521 T2712 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-1370305555885\nodes_used_collection_shard2_replica2\'
[junit4:junit4] 2> 847611 T2695 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 847611 T2740 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 847688 T2712 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 847716 T2695 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 847822 T2712 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 847836 T2680 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 847865 T2695 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 847872 T2695 oass.IndexSchema.readSchema [nodes_used_collection_shard1_replica1] Schema name=test
[junit4:junit4] 2> 847880 T2740 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 847885 T2712 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 847891 T2712 oass.IndexSchema.readSchema [nodes_used_collection_shard2_replica2] Schema name=test
[junit4:junit4] 2> 848052 T2680 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 848054 T2740 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 848061 T2740 oass.IndexSchema.readSchema [nodes_used_collection_shard1_replica2] Schema name=test
[junit4:junit4] 2> 848134 T2680 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 848145 T2680 oass.IndexSchema.readSchema [nodes_used_collection_shard2_replica1] Schema name=test
[junit4:junit4] 2> 849481 T2695 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 849492 T2695 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 849497 T2695 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 849811 T2712 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 849819 T2712 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 849825 T2712 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 849907 T2680 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 849916 T2680 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 849920 T2680 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 849961 T2695 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 849971 T2695 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 849982 T2695 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 849983 T2680 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 849986 T2695 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 849988 T2695 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 849988 T2695 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 849992 T2680 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 849997 T2712 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 850001 T2680 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 850002 T2695 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 850003 T2695 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 850003 T2695 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 850004 T2695 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-jetty1-1370305553877\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-jetty1-1370305553877\nodes_used_collection_shard1_replica1\data\
[junit4:junit4] 2> 850004 T2695 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5918a5
[junit4:junit4] 2> 850005 T2695 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 850007 T2695 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-1370305553877\nodes_used_collection_shard1_replica1\data\
[junit4:junit4] 2> 850007 T2695 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-1370305553877\nodes_used_collection_shard1_replica1\data\index/
[junit4:junit4] 2> 850008 T2695 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-jetty1-1370305553877\nodes_used_collection_shard1_replica1\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 850008 T2695 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-1370305553877\nodes_used_collection_shard1_replica1\data\index
[junit4:junit4] 2> 850014 T2680 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 850016 T2680 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 850016 T2680 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 850019 T2712 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 850021 T2695 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c3ccf8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18b50e9),segFN=segments_1,generation=1}
[junit4:junit4] 2> 850021 T2695 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 850028 T2695 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 850028 T2695 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 850029 T2695 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 850029 T2695 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 850030 T2695 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 850030 T2695 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 850030 T2695 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 850032 T2695 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 850032 T2695 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 850047 T2695 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 850051 T2695 oass.SolrIndexSearcher.<init> Opening Searcher@198f000 main
[junit4:junit4] 2> 850052 T2695 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-1370305553877\nodes_used_collection_shard1_replica1\data\tlog
[junit4:junit4] 2> 850054 T2680 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 850054 T2680 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 850054 T2680 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 850054 T2695 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 850055 T2680 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-controljetty-1370305552695\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-controljetty-1370305552695\nodes_used_collection_shard2_replica1\data\
[junit4:junit4] 2> 850056 T2695 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 850056 T2680 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5918a5
[junit4:junit4] 2> 850057 T2680 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 850075 T2712 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 850078 T2680 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-1370305552695\nodes_used_collection_shard2_replica1\data\
[junit4:junit4] 2> 850078 T2680 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-1370305552695\nodes_used_collection_shard2_replica1\data\index/
[junit4:junit4] 2> 850079 T2680 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-controljetty-1370305552695\nodes_used_collection_shard2_replica1\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 850080 T2680 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-1370305552695\nodes_used_collection_shard2_replica1\data\index
[junit4:junit4] 2> 850084 T2712 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 850100 T2712 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 850100 T2712 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 850099 T2695 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica1 state=down
[junit4:junit4] 2> 850103 T2753 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica1] Registered new searcher Searcher@198f000 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 850114 T2712 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 850114 T2712 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 850115 T2712 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 850115 T2712 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-jetty2-1370305555885\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-jetty2-1370305555885\nodes_used_collection_shard2_replica2\data\
[junit4:junit4] 2> 850116 T2712 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5918a5
[junit4:junit4] 2> 850117 T2712 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 850114 T2680 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@15b2704 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f80ba5),segFN=segments_1,generation=1}
[junit4:junit4] 2> 850118 T2680 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 850119 T2712 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-1370305555885\nodes_used_collection_shard2_replica2\data\
[junit4:junit4] 2> 850119 T2712 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-1370305555885\nodes_used_collection_shard2_replica2\data\index/
[junit4:junit4] 2> 850120 T2712 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-jetty2-1370305555885\nodes_used_collection_shard2_replica2\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 850122 T2712 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-1370305555885\nodes_used_collection_shard2_replica2\data\index
[junit4:junit4] 2> 850129 T2712 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1cab7be lockFactory=org.apache.lucene.store.NativeFSLockFactory@10fdf2),segFN=segments_1,generation=1}
[junit4:junit4] 2> 850130 T2712 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 850135 T2712 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 850135 T2712 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 850136 T2712 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 850137 T2712 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 850138 T2712 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 850139 T2712 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 850139 T2712 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 850141 T2712 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 850141 T2712 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 850148 T2740 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 850157 T2712 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 850161 T2740 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 850166 T2680 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 850167 T2712 oass.SolrIndexSearcher.<init> Opening Searcher@1a42f9d main
[junit4:junit4] 2> 850166 T2740 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 850168 T2712 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-1370305555885\nodes_used_collection_shard2_replica2\data\tlog
[junit4:junit4] 2> 850167 T2680 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 850170 T2680 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 850171 T2712 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 850171 T2680 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 850173 T2680 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 850173 T2680 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 850174 T2680 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 850171 T2712 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 850175 T2680 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 850176 T2680 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 850178 T2680 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 850181 T2712 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica2 state=down
[junit4:junit4] 2> 850183 T2754 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica2] Registered new searcher Searcher@1a42f9d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 850183 T2680 oass.SolrIndexSearcher.<init> Opening Searcher@9db347 main
[junit4:junit4] 2> 850186 T2680 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-1370305552695\nodes_used_collection_shard2_replica1\data\tlog
[junit4:junit4] 2> 850189 T2680 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 850191 T2680 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 850199 T2680 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica1 state=down
[junit4:junit4] 2> 850200 T2755 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica1] Registered new searcher Searcher@9db347 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 850210 T2740 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 850232 T2740 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 850241 T2740 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 850245 T2740 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 850245 T2740 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 850246 T2740 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 850248 T2740 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 850248 T2740 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 850249 T2740 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 850249 T2740 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-jetty4-1370305559783\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-jetty4-1370305559783\nodes_used_collection_shard1_replica2\data\
[junit4:junit4] 2> 850250 T2740 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5918a5
[junit4:junit4] 2> 850251 T2740 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 850251 T2740 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-1370305559783\nodes_used_collection_shard1_replica2\data\
[junit4:junit4] 2> 850251 T2740 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-1370305559783\nodes_used_collection_shard1_replica2\data\index/
[junit4:junit4] 2> 850251 T2740 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-jetty4-1370305559783\nodes_used_collection_shard1_replica2\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 850253 T2740 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-1370305559783\nodes_used_collection_shard1_replica2\data\index
[junit4:junit4] 2> 850259 T2740 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@15148c7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@12a17cc),segFN=segments_1,generation=1}
[junit4:junit4] 2> 850260 T2740 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 850264 T2740 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 850264 T2740 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 850265 T2740 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 850265 T2740 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 850267 T2740 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 850267 T2740 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 850267 T2740 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 850268 T2740 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 850268 T2740 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 850281 T2740 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 850290 T2740 oass.SolrIndexSearcher.<init> Opening Searcher@3f72ca main
[junit4:junit4] 2> 850291 T2740 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-1370305559783\nodes_used_collection_shard1_replica2\data\tlog
[junit4:junit4] 2> 850294 T2740 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 850295 T2740 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 850302 T2756 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica2] Registered new searcher Searcher@3f72ca main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 850305 T2740 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica2 state=down
[junit4:junit4] 2> 850644 T2688 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 850645 T2688 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:59257_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59257"}
[junit4:junit4] 2> 850645 T2688 oasc.Overseer$ClusterStateUpdater.createCollection Create collection nodes_used_collection with numShards 2
[junit4:junit4] 2> 850659 T2688 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:59266_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59266"}
[junit4:junit4] 2> 850669 T2688 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:59245_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59245"}
[junit4:junit4] 2> 850678 T2688 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:59284_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59284"}
[junit4:junit4] 2> 850688 T2733 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> 850689 T2719 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> 850689 T2687 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> 850688 T2692 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> 850691 T2705 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> 850691 T2747 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> 851213 T2695 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 851213 T2695 oasc.ZkController.register Register replica - core:nodes_used_collection_shard1_replica1 address:http://127.0.0.1:59257 collection:nodes_used_collection shard:shard1
[junit4:junit4] 2> 851214 T2695 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leader_elect/shard1/election
[junit4:junit4] 2> 851245 T2695 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 851252 T2695 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Waiting until we see more replicas up: total=2 found=1 timeoutin=179999
[junit4:junit4] 2> 851287 T2712 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 851287 T2712 oasc.ZkController.register Register replica - core:nodes_used_collection_shard2_replica2 address:http://127.0.0.1:59266 collection:nodes_used_collection shard:shard2
[junit4:junit4] 2> 851288 T2712 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leader_elect/shard2/election
[junit4:junit4] 2> 851302 T2680 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 851302 T2680 oasc.ZkController.register Register replica - core:nodes_used_collection_shard2_replica1 address:http://127.0.0.1:59245 collection:nodes_used_collection shard:shard2
[junit4:junit4] 2> 851312 T2712 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 851320 T2712 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 851320 T2712 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 851321 T2712 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59266/nodes_used_collection_shard2_replica2/
[junit4:junit4] 2> 851321 T2712 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard2_replica2 url=http://127.0.0.1:59266 START replicas=[http://127.0.0.1:59245/nodes_used_collection_shard2_replica1/] nUpdates=100
[junit4:junit4] 2> 851322 T2712 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard2_replica2 url=http://127.0.0.1:59266 DONE. We have no versions. sync failed.
[junit4:junit4] 2> 851322 T2712 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4] 2> 851322 T2712 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> 851323 T2712 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59266/nodes_used_collection_shard2_replica2/
[junit4:junit4] 2> 851324 T2712 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leaders/shard2
[junit4:junit4] 2> ASYNC NEW_CORE C6899 name=nodes_used_collection_shard2_replica1 org.apache.solr.core.SolrCore@1b4bced url=http://127.0.0.1:59245/nodes_used_collection_shard2_replica1 node=127.0.0.1:59245_ C6899_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica1 props:{shard=shard2, state=down, core=nodes_used_collection_shard2_replica1, collection=nodes_used_collection, node_name=127.0.0.1:59245_, base_url=http://127.0.0.1:59245}
[junit4:junit4] 2> 851338 T2679 C6899 P59245 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=1
[junit4:junit4] 2> 851409 T2740 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 851409 T2740 oasc.ZkController.register Register replica - core:nodes_used_collection_shard1_replica2 address:http://127.0.0.1:59284 collection:nodes_used_collection shard:shard1
[junit4:junit4] 2> 851803 T2695 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 851803 T2695 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 851804 T2695 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59257/nodes_used_collection_shard1_replica1/
[junit4:junit4] 2> 851806 T2695 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard1_replica1 url=http://127.0.0.1:59257 START replicas=[http://127.0.0.1:59284/nodes_used_collection_shard1_replica2/] nUpdates=100
[junit4:junit4] 2> 851807 T2695 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard1_replica1 url=http://127.0.0.1:59257 DONE. We have no versions. sync failed.
[junit4:junit4] 2> 851807 T2695 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4] 2> 851808 T2695 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> 851809 T2695 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59257/nodes_used_collection_shard1_replica1/
[junit4:junit4] 2> 851809 T2695 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leaders/shard1
[junit4:junit4] 2> ASYNC NEW_CORE C6900 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@7479f0 url=http://127.0.0.1:59284/nodes_used_collection_shard1_replica2 node=127.0.0.1:59284_ C6900_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica2 props:{shard=shard1, state=down, core=nodes_used_collection_shard1_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59284_, base_url=http://127.0.0.1:59284}
[junit4:junit4] 2> 851829 T2739 C6900 P59284 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> 852364 T2688 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 852414 T2733 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> 852414 T2687 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> 852415 T2719 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> 852416 T2747 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> 852416 T2705 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> 852415 T2692 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> 852443 T2695 oasc.ZkController.register We are http://127.0.0.1:59257/nodes_used_collection_shard1_replica1/ and leader is http://127.0.0.1:59257/nodes_used_collection_shard1_replica1/
[junit4:junit4] 2> 852443 T2695 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard1_replica1 baseURL=http://127.0.0.1:59257
[junit4:junit4] 2> 852444 T2695 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 852444 T2695 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica1 state=active
[junit4:junit4] 2> 852450 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 852451 T2695 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=4977
[junit4:junit4] 2> 852461 T2712 oasc.ZkController.register We are http://127.0.0.1:59266/nodes_used_collection_shard2_replica2/ and leader is http://127.0.0.1:59266/nodes_used_collection_shard2_replica2/
[junit4:junit4] 2> 852461 T2712 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard2_replica2 baseURL=http://127.0.0.1:59266
[junit4:junit4] 2> 852462 T2712 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 852462 T2712 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica2 state=active
[junit4:junit4] 2> 852467 T2712 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 852469 T2712 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=4992
[junit4:junit4] 2> 852478 T2680 oasc.ZkController.register We are http://127.0.0.1:59245/nodes_used_collection_shard2_replica1/ and leader is http://127.0.0.1:59266/nodes_used_collection_shard2_replica2/
[junit4:junit4] 2> 852478 T2680 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard2_replica1 baseURL=http://127.0.0.1:59245
[junit4:junit4] 2> 852479 T2680 oasc.ZkController.checkRecovery Core needs to recover:nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 852480 T2680 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> 852481 T2759 C6899 P59245 oasc.RecoveryStrategy.run Starting recovery process. core=nodes_used_collection_shard2_replica1 recoveringAfterStartup=true
[junit4:junit4] 2> 852481 T2759 C6899 P59245 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 852482 T2680 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 852483 T2680 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=5008
[junit4:junit4] 2> 852484 T2759 C6899 P59245 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica1 state=recovering
[junit4:junit4] 2> 852489 T2759 C6899 P59245 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 852501 T2714 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:59245__nodes_used_collection_shard2_replica1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 852521 T2740 oasc.ZkController.register We are http://127.0.0.1:59284/nodes_used_collection_shard1_replica2/ and leader is http://127.0.0.1:59257/nodes_used_collection_shard1_replica1/
[junit4:junit4] 2> 852521 T2740 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard1_replica2 baseURL=http://127.0.0.1:59284
[junit4:junit4] 2> 852521 T2740 oasc.ZkController.checkRecovery Core needs to recover:nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 852522 T2740 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> 852523 T2760 C6900 P59284 oasc.RecoveryStrategy.run Starting recovery process. core=nodes_used_collection_shard1_replica2 recoveringAfterStartup=true
[junit4:junit4] 2> 852523 T2760 C6900 P59284 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 852525 T2760 C6900 P59284 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica2 state=recovering
[junit4:junit4] 2> 852526 T2740 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 852528 T2760 C6900 P59284 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 852530 T2740 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=5056
[junit4:junit4] 2> 852532 T2689 oasc.OverseerCollectionProcessor.createCollection Finished create command on all shards for collection: nodes_used_collection
[junit4:junit4] 2> 852537 T2705 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work/qnr-0000000000 state: SyncConnected type NodeDataChanged
[junit4:junit4] 2> 852539 T2700 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:59284__nodes_used_collection_shard1_replica2, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 852542 T2687 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4] 2> 852543 T2689 oasc.OverseerCollectionProcessor.run Overseer Collection Processor: Message id:/overseer/collection-queue-work/qn-0000000000 complete, response:{success={null={responseHeader={status=0,QTime=4977},core=nodes_used_collection_shard1_replica1},null={responseHeader={status=0,QTime=4992},core=nodes_used_collection_shard2_replica2},null={responseHeader={status=0,QTime=5008},core=nodes_used_collection_shard2_replica1},null={responseHeader={status=0,QTime=5056},core=nodes_used_collection_shard1_replica2}}}
[junit4:junit4] 2> 852547 T2701 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=5086
[junit4:junit4] 2> 852547 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 852551 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 852555 T2762 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c4eb4a name:ZooKeeperConnection Watcher:127.0.0.1:59238/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 852556 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 852559 T2665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 852564 T2665 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 852567 T2665 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 852571 T2764 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8a155d name:ZooKeeperConnection Watcher:127.0.0.1:59238/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 852572 T2665 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 852575 T2665 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 852586 T2683 oasha.CollectionsHandler.handleCreateAction Creating Collection : numShards=4&maxShardsPerNode=4&name=awholynewcollection_0&replicationFactor=4&action=CREATE&wt=javabin&version=2
[junit4:junit4] 2> 852594 T2687 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4] 2> 852605 T2689 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":"4",
[junit4:junit4] 2> "maxShardsPerNode":"4",
[junit4:junit4] 2> "createNodeSet":null,
[junit4:junit4] 2> "name":"awholynewcollection_0",
[junit4:junit4] 2> "replicationFactor":"4"}
[junit4:junit4] 2> 852605 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica1 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:59266_
[junit4:junit4] 2> 852606 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica2 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:59275_
[junit4:junit4] 2> 852606 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica3 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:59284_
[junit4:junit4] 2> 852606 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica4 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:59245_
[junit4:junit4] 2> 852606 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard2_replica1 as part of slice shard2 of collection awholynewcollection_0 on 127.0.0.1:59257_
[junit4:junit4] 2> 852607 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard2_replica2 as part of slice shard2 of collection awholynewcollection_0 on 127.0.0.1:59266_
[junit4:junit4] 2> 852608 T2729 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-jetty3-1370305557851\awholynewcollection_0_shard1_replica2
[junit4:junit4] 2> 852609 T2729 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852608 T2715 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-1370305555885\awholynewcollection_0_shard1_replica1
[junit4:junit4] 2> 852612 T2715 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852613 T2729 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 852613 T2729 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 852611 T2697 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard2_replica1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370305553877\awholynewcollection_0_shard2_replica1
[junit4:junit4] 2> 852611 T2742 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-jetty4-1370305559783\awholynewcollection_0_shard1_replica3
[junit4:junit4] 2> 852615 T2742 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852610 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard2_replica3 as part of slice shard2 of collection awholynewcollection_0 on 127.0.0.1:59275_
[junit4:junit4] 2> 852609 T2678 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-controljetty-1370305552695\awholynewcollection_0_shard1_replica4
[junit4:junit4] 2> 852618 T2678 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852618 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard2_replica4 as part of slice shard2 of collection awholynewcollection_0 on 127.0.0.1:59284_
[junit4:junit4] 2> 852617 T2729 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 852614 T2697 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852613 T2715 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 852623 T2715 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 852613 T2710 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard2_replica2' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370305555885\awholynewcollection_0_shard2_replica2
[junit4:junit4] 2> 852623 T2743 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard2_replica4' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370305559783\awholynewcollection_0_shard2_replica4
[junit4:junit4] 2> 852625 T2743 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852623 T2697 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 852627 T2697 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 852627 T2743 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 852622 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard3_replica1 as part of slice shard3 of collection awholynewcollection_0 on 127.0.0.1:59245_
[junit4:junit4] 2> 852622 T2729 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 852621 T2724 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard2_replica3' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370305557851\awholynewcollection_0_shard2_replica3
[junit4:junit4] 2> 852631 T2724 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852632 T2681 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard3_replica1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370305552695\awholynewcollection_0_shard3_replica1
[junit4:junit4] 2> 852632 T2681 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852621 T2678 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 852634 T2678 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 852618 T2742 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 852636 T2742 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 852635 T2681 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 852637 T2681 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 852633 T2724 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 852639 T2724 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 852631 T2697 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 852641 T2697 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 852628 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard3_replica2 as part of slice shard3 of collection awholynewcollection_0 on 127.0.0.1:59257_
[junit4:junit4] 2> 852628 T2743 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 852644 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard3_replica3 as part of slice shard3 of collection awholynewcollection_0 on 127.0.0.1:59266_
[junit4:junit4] 2> 852644 T2678 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 852626 T2715 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 852647 T2715 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 852647 T2681 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 852625 T2710 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852648 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard3_replica4 as part of slice shard3 of collection awholynewcollection_0 on 127.0.0.1:59275_
[junit4:junit4] 2> 852649 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard4_replica1 as part of slice shard4 of collection awholynewcollection_0 on 127.0.0.1:59284_
[junit4:junit4] 2> 852647 T2742 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 852655 T2710 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 852660 T2710 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852641 T2729 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852660 T2738 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard4_replica1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370305559783\awholynewcollection_0_shard4_replica1
[junit4:junit4] 2> 852662 T2738 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852658 T2697 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852658 T2711 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard3_replica3' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370305555885\awholynewcollection_0_shard3_replica3
[junit4:junit4] 2> 852665 T2711 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852656 T2743 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 852667 T2715 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852655 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard4_replica2 as part of slice shard4 of collection awholynewcollection_0 on 127.0.0.1:59245_
[junit4:junit4] 2> 852653 T2725 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard3_replica4' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370305557851\awholynewcollection_0_shard3_replica4
[junit4:junit4] 2> 852669 T2725 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852651 T2698 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard3_replica2' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370305553877\awholynewcollection_0_shard3_replica2
[junit4:junit4] 2> 852675 T2698 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852676 T2742 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852651 T2724 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 852677 T2697 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-1370305553877\awholynewcollection_0_shard2_replica1\'
[junit4:junit4] 2> 852676 T2738 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 852679 T2738 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852676 T2682 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard4_replica2' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370305552695\awholynewcollection_0_shard4_replica2
[junit4:junit4] 2> 852681 T2682 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852675 T2725 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 852683 T2725 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852684 T2698 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 852684 T2698 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852675 T2710 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-1370305555885\awholynewcollection_0_shard2_replica2\'
[junit4:junit4] 2> 852693 T2682 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 852693 T2682 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852673 T2729 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-1370305557851\awholynewcollection_0_shard1_replica2\'
[junit4:junit4] 2> 852671 T2711 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 852698 T2711 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852701 T2742 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-1370305559783\awholynewcollection_0_shard1_replica3\'
[junit4:junit4] 2> 852710 T2738 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-1370305559783\awholynewcollection_0_shard4_replica1\'
[junit4:junit4] 2> 852718 T2743 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852671 T2681 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852669 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard4_replica3 as part of slice shard4 of collection awholynewcollection_0 on 127.0.0.1:59257_
[junit4:junit4] 2> 852663 T2678 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852679 T2715 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-1370305555885\awholynewcollection_0_shard1_replica1\'
[junit4:junit4] 2> 852735 T2689 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard4_replica4 as part of slice shard4 of collection awholynewcollection_0 on 127.0.0.1:59266_
[junit4:junit4] 2> 852741 T2699 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard4_replica3' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370305553877\awholynewcollection_0_shard4_replica3
[junit4:junit4] 2> 852741 T2699 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852741 T2698 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-1370305553877\awholynewcollection_0_shard3_replica2\'
[junit4:junit4] 2> 852754 T2724 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852755 T2699 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 852836 T2699 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852827 T2710 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 852839 T2678 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-1370305552695\awholynewcollection_0_shard1_replica4\'
[junit4:junit4] 2> 852791 T2725 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-1370305557851\awholynewcollection_0_shard3_replica4\'
[junit4:junit4] 2> 852844 T2743 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-1370305559783\awholynewcollection_0_shard2_replica4\'
[junit4:junit4] 2> 852846 T2724 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-1370305557851\awholynewcollection_0_shard2_replica3\'
[junit4:junit4] 2> 852765 T2713 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard4_replica4' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370305555885\awholynewcollection_0_shard4_replica4
[junit4:junit4] 2> 852888 T2713 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 852890 T2681 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-1370305552695\awholynewcollection_0_shard3_replica1\'
[junit4:junit4] 2> 852763 T2711 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-1370305555885\awholynewcollection_0_shard3_replica3\'
[junit4:junit4] 2> 852912 T2697 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 852763 T2682 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-1370305552695\awholynewcollection_0_shard4_replica2\'
[junit4:junit4] 2> 852964 T2699 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-1370305553877\awholynewcollection_0_shard4_replica3\'
[junit4:junit4] 2> 852965 T2713 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 852966 T2713 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 852975 T2713 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-1370305555885\awholynewcollection_0_shard4_replica4\'
[junit4:junit4] 2> 853005 T2698 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 853076 T2715 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 853114 T2698 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 853124 T2698 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 853169 T2682 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 853192 T2698 oass.IndexSchema.readSchema [awholynewcollection_0_shard3_replica2] Schema name=test
[junit4:junit4] 2> 853198 T2678 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 853204 T2729 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 853294 T2729 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 853342 T2738 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 853365 T2711 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 853448 T2710 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 853516 T2742 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 853531 T2729 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 853561 T2710 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 853581 T2682 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 853584 T2711 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 853613 T2710 oass.IndexSchema.readSchema [awholynewcollection_0_shard2_replica2] Schema name=test
[junit4:junit4] 2> 853651 T2678 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 853682 T2711 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 853685 T2682 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 853691 T2682 oass.IndexSchema.readSchema [awholynewcollection_0_shard4_replica2] Schema name=test
[junit4:junit4] 2> 853752 T2678 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 853758 T2678 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica4] Schema name=test
[junit4:junit4] 2> 853808 T2725 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 853862 T2724 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 853894 T2711 oass.IndexSchema.readSchema [awholynewcollection_0_shard3_replica3] Schema name=test
[junit4:junit4] 2> 853978 T2697 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 853994 T2681 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 853999 T2729 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica2] Schema name=test
[junit4:junit4] 2> 854044 T2738 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 854069 T2697 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 854071 T2738 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 854112 T2738 oass.IndexSchema.readSchema [awholynewcollection_0_shard4_replica1] Schema name=test
[junit4:junit4] 2> 854435 T2688 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 854445 T2742 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 854446 T2688 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59257__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:59257_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59257"}
[junit4:junit4] 2> 854484 T2743 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 854632 T2742 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 854635 T2713 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 854645 T2742 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica3] Schema name=test
[junit4:junit4] 2> 854702 T2697 oass.IndexSchema.readSchema [awholynewcollection_0_shard2_replica1] Schema name=test
[junit4:junit4] 2> 854726 T2743 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 854748 T2724 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 854763 T2715 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 854793 T2713 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 854850 T2725 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 854902 T2681 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 854915 T2713 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 854922 T2713 oass.IndexSchema.readSchema [awholynewcollection_0_shard4_replica4] Schema name=test
[junit4:junit4] 2> 854942 T2743 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 854949 T2743 oass.IndexSchema.readSchema [awholynewcollection_0_shard2_replica4] Schema name=test
[junit4:junit4] 2> 854999 T2715 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 855001 T2688 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59266__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:59266_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59266"}
[junit4:junit4] 2> 855002 T2724 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 855006 T2681 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 855014 T2725 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 855036 T2715 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica1] Schema name=test
[junit4:junit4] 2> 855036 T2724 oass.IndexSchema.readSchema [awholynewcollection_0_shard2_replica3] Schema name=test
[junit4:junit4] 2> 855038 T2688 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59245__nodes_used_collection_shard2_replica1",
[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_replica1",
[junit4:junit4] 2> "collection":"nodes_used_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59245_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59245"}
[junit4:junit4] 2> 855041 T2681 oass.IndexSchema.readSchema [awholynewcollection_0_shard3_replica1] Schema name=test
[junit4:junit4] 2> 855049 T2725 oass.IndexSchema.readSchema [awholynewcollection_0_shard3_replica4] Schema name=test
[junit4:junit4] 2> 855065 T2688 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59284__nodes_used_collection_shard1_replica2",
[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_replica2",
[junit4:junit4] 2> "collection":"nodes_used_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59284_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59284"}
[junit4:junit4] 2> 855246 T2762 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> 855247 T2764 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> 855247 T2692 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> 855249 T2733 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> 855249 T2687 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> 855249 T2719 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> 855249 T2705 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> 855250 T2747 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> 855865 T2714 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:59245__nodes_used_collection_shard2_replica1, state: recovering, checkLive: true, onlyIfLeader: true for: 3 seconds.
[junit4:junit4] 2> 855866 T2714 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:59245__nodes_used_collection_shard2_replica1&state=recovering&nodeName=127.0.0.1:59245_&action=PREPRECOVERY&checkLive=true&core=nodes_used_collection_shard2_replica2&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=3365
[junit4:junit4] 2> 855970 T2700 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:59284__nodes_used_collection_shard1_replica2, state: recovering, checkLive: true, onlyIfLeader: true for: 3 seconds.
[junit4:junit4] 2> 855973 T2700 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:59284__nodes_used_collection_shard1_replica2&state=recovering&nodeName=127.0.0.1:59284_&action=PREPRECOVERY&checkLive=true&core=nodes_used_collection_shard1_replica1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=3434
[junit4:junit4] 2> 856012 T2699 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 856784 T2699 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 856819 T2699 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 857253 T2699 oass.IndexSchema.readSchema [awholynewcollection_0_shard4_replica3] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C6901 name=nodes_used_collection_shard2_replica1 org.apache.solr.core.SolrCore@1b4bced url=http://127.0.0.1:59245/nodes_used_collection_shard2_replica1 node=127.0.0.1:59245_ C6901_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica1 props:{shard=shard2, state=recovering, core=nodes_used_collection_shard2_replica1, collection=nodes_used_collection, node_name=127.0.0.1:59245_, base_url=http://127.0.0.1:59245}
[junit4:junit4] 2> 858128 T2759 C6901 P59245 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:59266/nodes_used_collection_shard2_replica2/ core=nodes_used_collection_shard2_replica1 - recoveringAfterStartup=true
[junit4:junit4] 2> 858128 T2759 C6901 P59245 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard2_replica1 url=http://127.0.0.1:59245 START replicas=[http://127.0.0.1:59266/nodes_used_collection_shard2_replica2/] nUpdates=100
[junit4:junit4] 2> 858171 T2759 C6901 P59245 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 858172 T2759 C6901 P59245 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 858172 T2759 C6901 P59245 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 858172 T2759 C6901 P59245 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 858172 T2759 C6901 P59245 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 858173 T2759 C6901 P59245 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:59266/nodes_used_collection_shard2_replica2/. core=nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 858173 T2759 C6901 P59245 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C6902 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@7479f0 url=http://127.0.0.1:59284/nodes_used_collection_shard1_replica2 node=127.0.0.1:59284_ C6902_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica2 props:{shard=shard1, state=recovering, core=nodes_used_collection_shard1_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59284_, base_url=http://127.0.0.1:59284}
[junit4:junit4] 2> 858174 T2760 C6902 P59284 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:59257/nodes_used_collection_shard1_replica1/ core=nodes_used_collection_shard1_replica2 - recoveringAfterStartup=true
[junit4:junit4] 2> 858176 T2760 C6902 P59284 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard1_replica2 url=http://127.0.0.1:59284 START replicas=[http://127.0.0.1:59257/nodes_used_collection_shard1_replica1/] nUpdates=100
[junit4:junit4] 2> 858177 T2760 C6902 P59284 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 858177 T2760 C6902 P59284 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 858177 T2760 C6902 P59284 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 858178 T2760 C6902 P59284 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 858178 T2760 C6902 P59284 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 858178 T2760 C6902 P59284 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:59257/nodes_used_collection_shard1_replica1/. core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 858178 T2760 C6902 P59284 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C6903 name=nodes_used_collection_shard2_replica2 org.apache.solr.core.SolrCore@1cdaaf1 url=http://127.0.0.1:59266/nodes_used_collection_shard2_replica2 node=127.0.0.1:59266_ C6903_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica2 props:{shard=shard2, state=active, core=nodes_used_collection_shard2_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59266_, base_url=http://127.0.0.1:59266, leader=true}
[junit4:junit4] 2> 858564 T2714 C6903 P59266 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> ASYNC NEW_CORE C6904 name=nodes_used_collection_shard1_replica1 org.apache.solr.core.SolrCore@ba7bcc url=http://127.0.0.1:59257/nodes_used_collection_shard1_replica1 node=127.0.0.1:59257_ C6904_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica1 props:{shard=shard1, state=active, core=nodes_used_collection_shard1_replica1, collection=nodes_used_collection, node_name=127.0.0.1:59257_, base_url=http://127.0.0.1:59257, leader=true}
[junit4:junit4] 2> 858673 T2700 C6904 P59257 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=0
[junit4:junit4] 2> 858682 T2701 C6904 P59257 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C6905 name=nodes_used_collection_shard2_replica2 org.apache.solr.core.SolrCore@1cdaaf1 url=http://127.0.0.1:59266/nodes_used_collection_shard2_replica2 node=127.0.0.1:59266_ C6905_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica2 props:{shard=shard2, state=active, core=nodes_used_collection_shard2_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59266_, base_url=http://127.0.0.1:59266, leader=true}
[junit4:junit4] 2> 858689 T2712 C6905 P59266 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 858693 T2701 C6904 P59257 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c3ccf8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18b50e9),segFN=segments_1,generation=1}
[junit4:junit4] 2> 858696 T2701 C6904 P59257 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> ASYNC NEW_CORE C6906 name=nodes_used_collection_shard2_replica2 org.apache.solr.core.SolrCore@1cdaaf1 url=http://127.0.0.1:59266/nodes_used_collection_shard2_replica2 node=127.0.0.1:59266_ C6906_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica2 props:{shard=shard2, state=active, core=nodes_used_collection_shard2_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59266_, base_url=http://127.0.0.1:59266, leader=true}
[junit4:junit4] 2> 858721 T2712 C6906 P59266 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1cab7be lockFactory=org.apache.lucene.store.NativeFSLockFactory@10fdf2),segFN=segments_1,generation=1}
[junit4:junit4] 2> 858722 T2712 C6906 P59266 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 858727 T2682 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> ASYNC NEW_CORE C6907 name=nodes_used_collection_shard1_replica1 org.apache.solr.core.SolrCore@ba7bcc url=http://127.0.0.1:59257/nodes_used_collection_shard1_replica1 node=127.0.0.1:59257_ C6907_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica1 props:{shard=shard1, state=active, core=nodes_used_collection_shard1_replica1, collection=nodes_used_collection, node_name=127.0.0.1:59257_, base_url=http://127.0.0.1:59257, leader=true}
[junit4:junit4] 2> 858724 T2701 C6907 P59257 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c3ccf8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18b50e9),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c3ccf8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18b50e9),segFN=segments_2,generation=2}
[junit4:junit4] 2> ASYNC NEW_CORE C6908 name=nodes_used_collection_shard1_replica1 org.apache.solr.core.SolrCore@ba7bcc url=http://127.0.0.1:59257/nodes_used_collection_shard1_replica1 node=127.0.0.1:59257_ C6908_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica1 props:{shard=shard1, state=active, core=nodes_used_collection_shard1_replica1, collection=nodes_used_collection, node_name=127.0.0.1:59257_, base_url=http://127.0.0.1:59257, leader=true}
[junit4:junit4] 2> 858810 T2701 C6908 P59257 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 858810 T2701 C6908 P59257 oass.SolrIndexSearcher.<init> Opening Searcher@14fe71b realtime
[junit4:junit4] 2> 858810 T2701 C6908 P59257 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 858810 T2701 C6908 P59257 oasup.LogUpdateProcessor.finish [nodes_used_collection_shard1_replica1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 128
[junit4:junit4] 2> ASYNC NEW_CORE C6909 name=nodes_used_collection_shard2_replica2 org.apache.solr.core.SolrCore@1cdaaf1 url=http://127.0.0.1:59266/nodes_used_collection_shard2_replica2 node=127.0.0.1:59266_ C6909_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica2 props:{shard=shard2, state=active, core=nodes_used_collection_shard2_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59266_, base_url=http://127.0.0.1:59266, leader=true}
[junit4:junit4] 2> 858789 T2712 C6909 P59266 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1cab7be lockFactory=org.apache.lucene.store.NativeFSLockFactory@10fdf2),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1cab7be lockFactory=org.apache.lucene.store.NativeFSLockFactory@10fdf2),segFN=segments_2,generation=2}
[junit4:junit4] 2> 858810 T2712 C6909 P59266 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 858810 T2712 C6909 P59266 oass.SolrIndexSearcher.<init> Opening Searcher@1d8c256 realtime
[junit4:junit4] 2> 858813 T2712 C6909 P59266 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> ASYNC NEW_CORE C6910 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@7479f0 url=http://127.0.0.1:59284/nodes_used_collection_shard1_replica2 node=127.0.0.1:59284_ C6910_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica2 props:{shard=shard1, state=recovering, core=nodes_used_collection_shard1_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59284_, base_url=http://127.0.0.1:59284}
[junit4:junit4] 2> 858813 T2760 C6910 P59284 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 858813 T2760 C6910 P59284 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 858813 T2712 C6909 P59266 oasup.LogUpdateProcessor.finish [nodes_used_collection_shard2_replica2] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 124
[junit4:junit4] 2> ASYNC NEW_CORE C6911 name=nodes_used_collection_shard2_replica1 org.apache.solr.core.SolrCore@1b4bced url=http://127.0.0.1:59245/nodes_used_collection_shard2_replica1 node=127.0.0.1:59245_ C6911_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica1 props:{shard=shard2, state=recovering, core=nodes_used_collection_shard2_replica1, collection=nodes_used_collection, node_name=127.0.0.1:59245_, base_url=http://127.0.0.1:59245}
[junit4:junit4] 2> 858903 T2759 C6911 P59245 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 858903 T2759 C6911 P59245 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> ASYNC NEW_CORE C6912 name=nodes_used_collection_shard1_replica1 org.apache.solr.core.SolrCore@ba7bcc url=http://127.0.0.1:59257/nodes_used_collection_shard1_replica1 node=127.0.0.1:59257_ C6912_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica1 props:{shard=shard1, state=active, core=nodes_used_collection_shard1_replica1, collection=nodes_used_collection, node_name=127.0.0.1:59257_, base_url=http://127.0.0.1:59257, leader=true}
[junit4:junit4] 2> 858909 T2695 C6912 P59257 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 858909 T2695 C6912 P59257 oasc.SolrCore.execute [nodes_used_collection_shard1_replica1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=6
[junit4:junit4] 2> ASYNC NEW_CORE C6913 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@7479f0 url=http://127.0.0.1:59284/nodes_used_collection_shard1_replica2 node=127.0.0.1:59284_ C6913_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica2 props:{shard=shard1, state=recovering, core=nodes_used_collection_shard1_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59284_, base_url=http://127.0.0.1:59284}
[junit4:junit4] 2> 858911 T2760 C6913 P59284 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 858912 T2760 C6913 P59284 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 858912 T2760 C6913 P59284 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 858915 T2701 C6912 P59257 oasc.SolrCore.execute [nodes_used_collection_shard1_replica1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 858944 T2760 C6913 P59284 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> ASYNC NEW_CORE C6914 name=nodes_used_collection_shard2_replica2 org.apache.solr.core.SolrCore@1cdaaf1 url=http://127.0.0.1:59266/nodes_used_collection_shard2_replica2 node=127.0.0.1:59266_ C6914_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica2 props:{shard=shard2, state=active, core=nodes_used_collection_shard2_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59266_, base_url=http://127.0.0.1:59266, leader=true}
[junit4:junit4] 2> 858947 T2714 C6914 P59266 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 858947 T2714 C6914 P59266 oasc.SolrCore.execute [nodes_used_collection_shard2_replica2] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=10
[junit4:junit4] 2> 858948 T2759 C6911 P59245 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 858949 T2759 C6911 P59245 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 858949 T2759 C6911 P59245 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> ASYNC NEW_CORE C6915 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@7479f0 url=http://127.0.0.1:59284/nodes_used_collection_shard1_replica2 node=127.0.0.1:59284_ C6915_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica2 props:{shard=shard1, state=recovering, core=nodes_used_collection_shard1_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59284_, base_url=http://127.0.0.1:59284}
[junit4:junit4] 2> 859022 T2760 C6915 P59284 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-1370305559783\nodes_used_collection_shard1_replica2\data\index.20130604095613215
[junit4:junit4] 2> 859024 T2760 C6915 P59284 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@130726f lockFactory=org.apache.lucene.store.NativeFSLockFactory@ca865c) fullCopy=false
[junit4:junit4] 2> ASYNC NEW_CORE C6916 name=nodes_used_collection_shard2_replica2 org.apache.solr.core.SolrCore@1cdaaf1 url=http://127.0.0.1:59266/nodes_used_collection_shard2_replica2 node=127.0.0.1:59266_ C6916_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica2 props:{shard=shard2, state=active, core=nodes_used_collection_shard2_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59266_, base_url=http://127.0.0.1:59266, leader=true}
[junit4:junit4] 2> 859025 T2712 C6916 P59266 oasc.SolrCore.execute [nodes_used_collection_shard2_replica2] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C6917 name=nodes_used_collection_shard2_replica1 org.apache.solr.core.SolrCore@1b4bced url=http://127.0.0.1:59245/nodes_used_collection_shard2_replica1 node=127.0.0.1:59245_ C6917_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica1 props:{shard=shard2, state=recovering, core=nodes_used_collection_shard2_replica1, collection=nodes_used_collection, node_name=127.0.0.1:59245_, base_url=http://127.0.0.1:59245}
[junit4:junit4] 2> 859026 T2759 C6917 P59245 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> ASYNC NEW_CORE C6918 name=nodes_used_collection_shard1_replica1 org.apache.solr.core.SolrCore@ba7bcc url=http://127.0.0.1:59257/nodes_used_collection_shard1_replica1 node=127.0.0.1:59257_ C6918_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica1 props:{shard=shard1, state=active, core=nodes_used_collection_shard1_replica1, collection=nodes_used_collection, node_name=127.0.0.1:59257_, base_url=http://127.0.0.1:59257, leader=true}
[junit4:junit4] 2> 859026 T2700 C6918 P59257 oasc.SolrCore.execute [nodes_used_collection_shard1_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> 859029 T2760 C6915 P59284 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 859029 T2759 C6917 P59245 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-1370305552695\nodes_used_collection_shard2_replica1\data\index.20130604095613296
[junit4:junit4] 2> ASYNC NEW_CORE C6919 name=nodes_used_collection_shard2_replica1 org.apache.solr.core.SolrCore@1b4bced url=http://127.0.0.1:59245/nodes_used_collection_shard2_replica1 node=127.0.0.1:59245_ C6919_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica1 props:{shard=shard2, state=recovering, core=nodes_used_collection_shard2_replica1, collection=nodes_used_collection, node_name=127.0.0.1:59245_, base_url=http://127.0.0.1:59245}
[junit4:junit4] 2> 859122 T2759 C6919 P59245 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1b8855 lockFactory=org.apache.lucene.store.NativeFSLockFactory@162c6c4) fullCopy=false
[junit4:junit4] 2> ASYNC NEW_CORE C6920 name=nodes_used_collection_shard2_replica2 org.apache.solr.core.SolrCore@1cdaaf1 url=http://127.0.0.1:59266/nodes_used_collection_shard2_replica2 node=127.0.0.1:59266_ C6920_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica2 props:{shard=shard2, state=active, core=nodes_used_collection_shard2_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59266_, base_url=http://127.0.0.1:59266, leader=true}
[junit4:junit4] 2> 859143 T2712 C6920 P59266 oasc.SolrCore.execute [nodes_used_collection_shard2_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> 859144 T2759 C6919 P59245 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> ASYNC NEW_CORE C6921 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@7479f0 url=http://127.0.0.1:59284/nodes_used_collection_shard1_replica2 node=127.0.0.1:59284_ C6921_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica2 props:{shard=shard1, state=recovering, core=nodes_used_collection_shard1_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59284_, base_url=http://127.0.0.1:59284}
[junit4:junit4] 2> 859151 T2760 C6921 P59284 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 859177 T2760 C6921 P59284 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 859179 T2759 C6919 P59245 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 859180 T2759 C6919 P59245 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 859206 T2682 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> ASYNC NEW_CORE C6922 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@7479f0 url=http://127.0.0.1:59284/nodes_used_collection_shard1_replica2 node=127.0.0.1:59284_ C6922_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica2 props:{shard=shard1, state=recovering, core=nodes_used_collection_shard1_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59284_, base_url=http://127.0.0.1:59284}
[junit4:junit4] 2> 859223 T2760 C6922 P59284 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@15148c7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@12a17cc),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@15148c7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@12a17cc),segFN=segments_2,generation=2}
[junit4:junit4] 2> 859224 T2760 C6922 P59284 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 859224 T2760 C6922 P59284 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 859225 T2760 C6922 P59284 oass.SolrIndexSearcher.<init> Opening Searcher@3f7186 main
[junit4:junit4] 2> 859239 T2756 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica2] Registered new searcher Searcher@3f7186 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 859240 T2760 C6922 P59284 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-1370305559783\nodes_used_collection_shard1_replica2\data\index.20130604095613215 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370305559783\nodes_used_collection_shard1_replica2\data\index.20130604095613215;done=true>>]
[junit4:junit4] 2> 859240 T2760 C6922 P59284 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-1370305559783\nodes_used_collection_shard1_replica2\data\index.20130604095613215
[junit4:junit4] 2> 859242 T2760 C6922 P59284 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-1370305559783\nodes_used_collection_shard1_replica2\data\index.20130604095613215
[junit4:junit4] 2> 859242 T2760 C6922 P59284 oasc.RecoveryStrategy.replay No replay needed. core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> ASYNC NEW_CORE C6923 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@7479f0 url=http://127.0.0.1:59284/nodes_used_collection_shard1_replica2 node=127.0.0.1:59284_ C6923_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica2 props:{shard=shard1, state=recovering, core=nodes_used_collection_shard1_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59284_, base_url=http://127.0.0.1:59284}
[junit4:junit4] 2> 859333 T2760 C6923 P59284 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 859334 T2760 C6923 P59284 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica2 state=active
[junit4:junit4] 2> ASYNC NEW_CORE C6924 name=nodes_used_collection_shard2_replica1 org.apache.solr.core.SolrCore@1b4bced url=http://127.0.0.1:59245/nodes_used_collection_shard2_replica1 node=127.0.0.1:59245_ C6924_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica1 props:{shard=shard2, state=recovering, core=nodes_used_collection_shard2_replica1, collection=nodes_used_collection, node_name=127.0.0.1:59245_, base_url=http://127.0.0.1:59245}
[junit4:junit4] 2> 859333 T2759 C6924 P59245 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@15b2704 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f80ba5),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@15b2704 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f80ba5),segFN=segments_2,generation=2}
[junit4:junit4] 2> 859336 T2759 C6924 P59245 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 859336 T2759 C6924 P59245 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 859267 T2682 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> ASYNC NEW_CORE C6925 name=nodes_used_collection_shard2_replica1 org.apache.solr.core.SolrCore@1b4bced url=http://127.0.0.1:59245/nodes_used_collection_shard2_replica1 node=127.0.0.1:59245_ C6925_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica1 props:{shard=shard2, state=recovering, core=nodes_used_collection_shard2_replica1, collection=nodes_used_collection, node_name=127.0.0.1:59245_, base_url=http://127.0.0.1:59245}
[junit4:junit4] 2> 859424 T2759 C6925 P59245 oass.SolrIndexSearcher.<init> Opening Searcher@3649dc main
[junit4:junit4] 2> 859429 T2755 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica1] Registered new searcher Searcher@3649dc main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> ASYNC NEW_CORE C6926 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@7479f0 url=http://127.0.0.1:59284/nodes_used_collection_shard1_replica2 node=127.0.0.1:59284_ C6926_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica2 props:{shard=shard1, state=recovering, core=nodes_used_collection_shard1_replica2, collection=nodes_used_collection, node_name=127.0.0.1:59284_, base_url=http://127.0.0.1:59284}
[junit4:junit4] 2> 859575 T2760 C6926 P59284 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> ASYNC NEW_CORE C6927 name=nodes_used_collection_shard2_replica1 org.apache.solr.core.SolrCore@1b4bced url=http://127.0.0.1:59245/nodes_used_collection_shard2_replica1 node=127.0.0.1:59245_ C6927_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica1 props:{shard=shard2, state=recovering, core=nodes_used_collection_shard2_replica1, collection=nodes_used_collection, node_name=127.0.0.1:59245_, base_url=http://127.0.0.1:59245}
[junit4:junit4] 2> 859745 T2759 C6927 P59245 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-1370305552695\nodes_used_collection_shard2_replica1\data\index.20130604095613296 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370305552695\nodes_used_collection_shard2_replica1\data\index.20130604095613296;done=true>>]
[junit4:junit4] 2> 859745 T2759 C6927 P59245 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-1370305552695\nodes_used_collection_shard2_replica1\data\index.20130604095613296
[junit4:junit4] 2> 859745 T2759 C6927 P59245 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-1370305552695\nodes_used_collection_shard2_replica1\data\index.20130604095613296
[junit4:junit4] 2> 859745 T2759 C6927 P59245 oasc.RecoveryStrategy.replay No replay needed. core=nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 859745 T2759 C6927 P59245 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 859745 T2759 C6927 P59245 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica1 state=active
[junit4:junit4] 2> 859761 T2759 C6927 P59245 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 859838 T2682 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 859863 T2682 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 859908 T2682 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 859919 T2682 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 859920 T2682 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 859920 T2682 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 859928 T2682 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 859928 T2682 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 859929 T2682 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 859930 T2682 oasc.SolrCore.<init> [awholynewcollection_0_shard4_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-1370305552695\awholynewcollection_0_shard4_replica2\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370305552695\awholynewcollection_0_shard4_replica2\data\
[junit4:junit4] 2> 859931 T2682 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5918a5
[junit4:junit4] 2> 859931 T2682 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 859952 T2682 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-1370305552695\awholynewcollection_0_shard4_replica2\data\
[junit4:junit4] 2> 859952 T2682 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-1370305552695\awholynewcollection_0_shard4_replica2\data\index/
[junit4:junit4] 2> 859953 T2682 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard4_replica2] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370305552695\awholynewcollection_0_shard4_replica2\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 859954 T2682 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-1370305552695\awholynewcollection_0_shard4_replica2\data\index
[junit4:junit4] 2> 859978 T2682 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@142e4f6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f2516d),segFN=segments_1,generation=1}
[junit4:junit4] 2> 859985 T2682 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 859997 T2682 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 859998 T2682 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 859999 T2682 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 860000 T2682 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 860001 T2682 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 860002 T2682 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 860003 T2682 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 860004 T2682 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 860006 T2682 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 860185 T2682 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 860205 T2682 oass.SolrIndexSearcher.<init> Opening Searcher@669754 main
[junit4:junit4] 2> 860206 T2682 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-1370305552695\awholynewcollection_0_shard4_replica2\data\tlog
[junit4:junit4] 2> 860209 T2682 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 860209 T2682 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 860231 T2781 oasc.SolrCore.registerSearcher [awholynewcollection_0_shard4_replica2] Registered new searcher Searcher@669754 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 860232 T2682 oasc.ZkController.publish publishing core=awholynewcollection_0_shard4_replica2 state=down
[junit4:junit4] 2> 860607 T2688 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 860610 T2688 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59284__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:59284_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59284"}
[junit4:junit4] 2> 860641 T2688 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59245__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:59245_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59245"}
[junit4:junit4] 2> 860673 T2688 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=4 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"4",
[junit4:junit4] 2> "shard":"shard4",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"awholynewcollection_0_shard4_replica2",
[junit4:junit4] 2> "collection":"awholynewcollection_0",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59245_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59245"}
[junit4:junit4] 2> 860673 T2688 oasc.Overseer$ClusterStateUpdater.createCollection Create collection awholynewcollection_0 with numShards 4
[junit4:junit4] 2> 861487 T2733 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> 861488 T2687 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> 861488 T2719 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> 861487 T2692 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> 861497 T2705 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> 861487 T2762 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> 861487 T2764 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> 861495 T2747 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> 861726 T2724 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 861844 T2724 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 861849 T2724 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 862033 T2698 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 862042 T2698 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 862046 T2698 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 862226 T2681 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 862239 T2681 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 862392 T2711 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 862400 T2711 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 862405 T2711 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 862411 T2681 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 862507 T2738 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 862530 T2738 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 862563 T2738 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 862583 T2711 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 862583 T2698 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 862588 T2724 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 862614 T2681 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 862764 T2724 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 862792 T2742 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 862881 T2715 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 862890 T2715 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 862904 T2743 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 862912 T2743 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 862917 T2743 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 862947 T2742 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 862951 T2742 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 862970 T2698 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 862978 T2715 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 862990 T2711 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 863005 T2738 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 863019 T2681 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 863021 T2724 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 863037 T2724 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 863038 T2724 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 863039 T2724 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 863047 T2724 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 863047 T2724 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 863048 T2724 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 863048 T2724 oasc.SolrCore.<init> [awholynewcollection_0_shard2_replica3] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370305557851\awholynewcollection_0_shard2_replica3\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370305557851\awholynewcollection_0_shard2_replica3\data\
[junit4:junit4] 2> 863048 T2724 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5918a5
[junit4:junit4] 2> 863049 T2724 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 863051 T2698 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 863054 T2724 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-1370305557851\awholynewcollection_0_shard2_replica3\data\
[junit4:junit4] 2> 863054 T2724 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-1370305557851\awholynewcollection_0_shard2_replica3\data\index/
[junit4:junit4] 2> 863055 T2724 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard2_replica3] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370305557851\awholynewcollection_0_shard2_replica3\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 863057 T2698 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 863057 T2698 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 863058 T2698 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 863064 T2724 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-1370305557851\awholynewcollection_0_shard2_replica3\data\index
[junit4:junit4] 2> 863066 T2711 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 863068 T2698 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 863069 T2698 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 863069 T2698 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 863070 T2698 oasc.SolrCore.<init> [awholynewcollection_0_shard3_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-1370305553877\awholynewcollection_0_shard3_replica2\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370305553877\awholynewcollection_0_shard3_replica2\data\
[ju
[...truncated too long message...]
t4:junit4] 1> /solr/collections/awholynewcollection_0/leader_elect/shard3/election/89804344683069448-127.0.0.1:59266__awholynewcollection_0_shard3_replica3-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_0/leader_elect/shard3/election/89804344683069448-127.0.0.1:59266__awholynewcollection_0_shard3_replica3-n_0000000007 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_0/leader_elect/shard3/election/89804344683069443-127.0.0.1:59245__awholynewcollection_0_shard3_replica1-n_0000000004 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_0/leader_elect/shard3/election/89804344683069450-127.0.0.1:59275__awholynewcollection_0_shard3_replica4-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_0/leader_elect/shard3/election/89804344683069446-127.0.0.1:59257__awholynewcollection_0_shard3_replica2-n_0000000005 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_0/leader_elect/shard3/election/89804344683069450-127.0.0.1:59275__awholynewcollection_0_shard3_replica4-n_0000000006 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_0/leader_elect/shard3/election/89804344683069446-127.0.0.1:59257__awholynewcollection_0_shard3_replica2-n_0000000002 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_0/leader_elect/shard3/election/89804344683069443-127.0.0.1:59245__awholynewcollection_0_shard3_replica1-n_0000000001 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_0/leaders (4)
[junit4:junit4] 1> /solr/collections/awholynewcollection_0/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"awholynewcollection_0_shard1_replica3",
[junit4:junit4] 1> "node_name":"127.0.0.1:59284_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59284"}
[junit4:junit4] 1> /solr/collections/awholynewcollection_0/leaders/shard4 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"awholynewcollection_0_shard4_replica2",
[junit4:junit4] 1> "node_name":"127.0.0.1:59245_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59245"}
[junit4:junit4] 1> /solr/collections/awholynewcollection_0/leaders/shard2 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"awholynewcollection_0_shard2_replica4",
[junit4:junit4] 1> "node_name":"127.0.0.1:59284_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59284"}
[junit4:junit4] 1> /solr/collections/awholynewcollection_0/leaders/shard3 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"awholynewcollection_0_shard3_replica3",
[junit4:junit4] 1> "node_name":"127.0.0.1:59266_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59266"}
[junit4:junit4] 1> /solr/collections/collection1 (1)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/collection1/shards (0)
[junit4:junit4] 1> /solr/collections/control_collection (1)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/control_collection/shards (0)
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (5)
[junit4:junit4] 1> /solr/overseer_elect/election/89804344683069450-127.0.0.1:59275_-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89804344683069446-127.0.0.1:59257_-n_0000000001 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89804344683069448-127.0.0.1:59266_-n_0000000002 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89804344683069452-127.0.0.1:59284_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89804344683069443-127.0.0.1:59245_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89804344683069443-127.0.0.1:59245_-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=65A77A85F2F859A7 -Dtests.slow=true -Dtests.locale=zh_SG -Dtests.timezone=Australia/North -Dtests.file.encoding=Cp1252
[junit4:junit4] FAILURE 290s | CollectionsAPIDistributedZkTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: There are still nodes recoverying - waited for 230 seconds
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([65A77A85F2F859A7:E441F49D85A7399B]: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> 1127708 T2665 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 289592 T2664 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {timestamp=PostingsFormat(name=Memory doPackFST= false), range_facet_l=PostingsFormat(name=Memory doPackFST= false), id=PostingsFormat(name=Memory doPackFST= true), range_facet_sl=PostingsFormat(name=Memory doPackFST= true), a_t=PostingsFormat(name=Memory doPackFST= false), text=PostingsFormat(name=SimpleText), range_facet_si=PostingsFormat(name=Memory doPackFST= false), _version_=PostingsFormat(name=Direct), other_tl1=PostingsFormat(name=Direct), multiDefault=PostingsFormat(name=Memory doPackFST= false), a_si=PostingsFormat(name=Direct), intDefault=PostingsFormat(name=Direct)}, docValues:{timestamp=DocValuesFormat(name=Disk)}, sim=DefaultSimilarity, locale=zh_SG, timezone=Australia/North
[junit4:junit4] 2> NOTE: Windows 7 6.1 x86/Oracle Corporation 1.7.0_21 (32-bit)/cpus=2,threads=1,free=44667064,total=124817408
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestDocumentBuilder, TestRandomDVFaceting, ReturnFieldsTest, AlternateDirectoryTest, TestSolrIndexConfig, DebugComponentTest, SignatureUpdateProcessorFactoryTest, OpenCloseCoreStressTest, LukeRequestHandlerTest, DefaultValueUpdateProcessorTest, TestFieldTypeResource, StatelessScriptUpdateProcessorFactoryTest, PreAnalyzedUpdateProcessorTest, TestReplicationHandler, TestPostingsSolrHighlighter, TestFieldCollectionResource, BasicDistributedZkTest, BadIndexSchemaTest, TestSolrJ, ConvertedLegacyTest, TestQuerySenderListener, TestFieldTypeCollectionResource, TestUtils, TestFunctionQuery, CurrencyFieldOpenExchangeTest, TestTrie, TestFuzzyAnalyzedSuggestions, PreAnalyzedFieldTest, DistributedQueryElevationComponentTest, TestRTGBase, ChaosMonkeySafeLeaderTest, ExternalFileFieldSortTest, TestDocSet, BasicDistributedZk2Test, OutputWriterTest, URLClassifyProcessorTest, QueryResultKeyTest, TestMaxScoreQueryParser, CurrencyFieldXmlFileTest, TestRecovery, TestWordDelimiterFilterFactory, TestLMDirichletSimilarityFactory, DistributedTermsComponentTest, SpellingQueryConverterTest, CacheHeaderTest, DisMaxRequestHandlerTest, TestSolrQueryParserResource, TestCharFilters, UpdateRequestProcessorFactoryTest, TermVectorComponentTest, ChaosMonkeyShardSplitTest, IndexBasedSpellCheckerTest, TestOmitPositions, MultiTermTest, FileUtilsTest, CoreContainerCoreInitFailuresTest, TestNumberUtils, TestPhraseSuggestions, TestFastWriter, TestCSVResponseWriter, CSVRequestHandlerTest, TestArbitraryIndexDir, TestUpdate, HighlighterTest, TestComponentsName, DistributedSpellCheckComponentTest, CollectionsAPIDistributedZkTest]
[junit4:junit4] Completed in 292.16s, 1 test, 1 failure <<< FAILURES!
[...truncated 706 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:380: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:360: 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: 296 suites, 1235 tests, 1 failure, 18 ignored (12 assumptions)
Total time: 68 minutes 50 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_21 -client -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure