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/05/28 09:35:55 UTC
[JENKINS] Lucene-Solr-4.x-Windows (64bit/jdk1.6.0_45) - Build #
2836 - Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Windows/2836/
Java: 64bit/jdk1.6.0_45 -XX:+UseCompressedOops -XX:+UseSerialGC
1 tests failed.
FAILED: 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([188F903AD8C8D850:99691E22AF97B86C]: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:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
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:662)
Build Log:
[...truncated 8892 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.CollectionsAPIDistributedZkTest
[junit4:junit4] 2> 1014059 T2976 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /_/
[junit4:junit4] 2> 1014065 T2976 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\solrtest-CollectionsAPIDistributedZkTest-1369724769499
[junit4:junit4] 2> 1014069 T2976 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1014070 T2977 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1014207 T2976 oasc.ZkTestServer.run start zk server on port:61805
[junit4:junit4] 2> 1014210 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1014226 T2983 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1105f774 name:ZooKeeperConnection Watcher:127.0.0.1:61805 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1014226 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1014226 T2976 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1014238 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1014244 T2985 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@35f2cd29 name:ZooKeeperConnection Watcher:127.0.0.1:61805/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1014245 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1014245 T2976 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1014255 T2976 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1014261 T2976 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1014268 T2976 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1014276 T2976 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1014276 T2976 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1014291 T2976 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 1014292 T2976 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1014302 T2976 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1014302 T2976 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1014310 T2976 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 1014310 T2976 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1014318 T2976 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 1014318 T2976 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1014326 T2976 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1014327 T2976 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1014335 T2976 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1014335 T2976 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1014343 T2976 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1014343 T2976 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1014351 T2976 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1014354 T2976 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1014988 T2976 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1014995 T2976 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:61812
[junit4:junit4] 2> 1014996 T2976 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1014996 T2976 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1014996 T2976 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798
[junit4:junit4] 2> 1014998 T2976 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\solr.xml
[junit4:junit4] 2> 1014998 T2976 oasc.CoreContainer.<init> New CoreContainer 654950952
[junit4:junit4] 2> 1014999 T2976 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\'
[junit4:junit4] 2> 1014999 T2976 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\'
[junit4:junit4] 2> 1015136 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798
[junit4:junit4] 2> 1015139 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\collection1
[junit4:junit4] 2> 1015142 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\collection1\conf
[junit4:junit4] 2> 1015440 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\collection1\conf\xslt
[junit4:junit4] 2> 1015450 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\collection1\lib
[junit4:junit4] 2> 1015454 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\collection1\lib\classes
[junit4:junit4] 2> 1015465 T2976 oasc.SolrCoreDiscoverer.addCore Discovered properties file C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\conf\core.properties, adding to cores
[junit4:junit4] 2> 1015488 T2976 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 1015488 T2976 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1015489 T2976 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 1015489 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1015489 T2976 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1015489 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1015490 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1015490 T2976 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1015492 T2976 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1015492 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 1015504 T2976 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1015505 T2976 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:61805/solr
[junit4:junit4] 2> 1015505 T2976 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1015508 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1015525 T2996 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@dcfca31 name:ZooKeeperConnection Watcher:127.0.0.1:61805 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1015527 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1015531 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1015531 T2978 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13ee9f554e80002, 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:662)
[junit4:junit4] 2>
[junit4:junit4] 2> 1015539 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1015543 T2998 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@41f57568 name:ZooKeeperConnection Watcher:127.0.0.1:61805/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1015544 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1015548 T2976 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1015556 T2976 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1015564 T2976 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1015568 T2976 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:61812__
[junit4:junit4] 2> 1015571 T2976 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:61812__
[junit4:junit4] 2> 1015578 T2976 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1015591 T2976 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1015597 T2976 oasc.Overseer.start Overseer (id=89766282494738435-127.0.0.1:61812__-n_0000000000) starting
[junit4:junit4] 2> 1015605 T2976 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1015614 T3000 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1015615 T2976 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1015621 T2976 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1015625 T2976 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1015630 T2999 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1015634 T2976 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 1015634 T2976 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1015634 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1015641 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1015642 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1015648 T3003 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@71b9f11e name:ZooKeeperConnection Watcher:127.0.0.1:61805/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1015648 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1015650 T2976 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1015655 T2976 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1016263 T2976 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1016267 T2976 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:61824
[junit4:junit4] 2> 1016268 T2976 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1016270 T2976 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1016270 T2976 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087
[junit4:junit4] 2> 1016270 T2976 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\solr.xml
[junit4:junit4] 2> 1016271 T2976 oasc.CoreContainer.<init> New CoreContainer 1649323776
[junit4:junit4] 2> 1016271 T2976 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\'
[junit4:junit4] 2> 1016272 T2976 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\'
[junit4:junit4] 2> 1016404 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087
[junit4:junit4] 2> 1016408 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\collection1
[junit4:junit4] 2> 1016410 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\collection1\conf
[junit4:junit4] 2> 1016704 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\collection1\conf\xslt
[junit4:junit4] 2> 1016717 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\collection1\lib
[junit4:junit4] 2> 1016719 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\collection1\lib\classes
[junit4:junit4] 2> 1016727 T2976 oasc.SolrCoreDiscoverer.addCore Discovered properties file C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\conf\core.properties, adding to cores
[junit4:junit4] 2> 1016750 T2976 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 1016750 T2976 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1016752 T2976 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 1016752 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1016752 T2976 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1016753 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1016753 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1016753 T2976 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1016754 T2976 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1016754 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 1016764 T2976 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1016764 T2976 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:61805/solr
[junit4:junit4] 2> 1016765 T2976 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1016766 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1016793 T3014 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@158e6b7f name:ZooKeeperConnection Watcher:127.0.0.1:61805 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1016795 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1016800 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1016808 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1016812 T3016 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@30065856 name:ZooKeeperConnection Watcher:127.0.0.1:61805/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1016812 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1016822 T2976 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1018207 T2976 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:61824__
[junit4:junit4] 2> 1018215 T2976 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:61824__
[junit4:junit4] 2> 1018223 T3003 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1018223 T3016 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1018224 T2998 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1018239 T2976 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 1018239 T2976 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1018240 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1018837 T2976 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1018842 T2976 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:61833
[junit4:junit4] 2> 1018843 T2976 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1018843 T2976 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1018845 T2976 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679
[junit4:junit4] 2> 1018845 T2976 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\solr.xml
[junit4:junit4] 2> 1018845 T2976 oasc.CoreContainer.<init> New CoreContainer 1325668163
[junit4:junit4] 2> 1018846 T2976 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\'
[junit4:junit4] 2> 1018846 T2976 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\'
[junit4:junit4] 2> 1018981 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679
[junit4:junit4] 2> 1018983 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\collection1
[junit4:junit4] 2> 1018985 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\collection1\conf
[junit4:junit4] 2> 1019284 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\collection1\conf\xslt
[junit4:junit4] 2> 1019293 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\collection1\lib
[junit4:junit4] 2> 1019302 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\collection1\lib\classes
[junit4:junit4] 2> 1019312 T2976 oasc.SolrCoreDiscoverer.addCore Discovered properties file C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\conf\core.properties, adding to cores
[junit4:junit4] 2> 1019335 T2976 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 1019336 T2976 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1019336 T2976 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 1019337 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1019337 T2976 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1019337 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1019337 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1019339 T2976 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1019339 T2976 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1019340 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 1019350 T2976 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1019350 T2976 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:61805/solr
[junit4:junit4] 2> 1019351 T2976 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1019352 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1019374 T3028 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@36b22fca name:ZooKeeperConnection Watcher:127.0.0.1:61805 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1019376 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1019382 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1019382 T2978 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13ee9f554e80007, 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:662)
[junit4:junit4] 2>
[junit4:junit4] 2> 1019394 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1019399 T3030 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@72df4653 name:ZooKeeperConnection Watcher:127.0.0.1:61805/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1019399 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1019410 T2976 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1020794 T2976 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:61833__
[junit4:junit4] 2> 1020806 T2976 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:61833__
[junit4:junit4] 2> 1020813 T3003 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1020814 T3016 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1020814 T3030 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1020815 T2998 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1020826 T2976 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 1020826 T2976 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1020828 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1021361 T2976 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1021366 T2976 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:61842
[junit4:junit4] 2> 1021366 T2976 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1021367 T2976 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1021367 T2976 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265
[junit4:junit4] 2> 1021367 T2976 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\solr.xml
[junit4:junit4] 2> 1021369 T2976 oasc.CoreContainer.<init> New CoreContainer 1424796126
[junit4:junit4] 2> 1021370 T2976 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\'
[junit4:junit4] 2> 1021370 T2976 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\'
[junit4:junit4] 2> 1021507 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265
[junit4:junit4] 2> 1021509 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\collection1
[junit4:junit4] 2> 1021513 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\collection1\conf
[junit4:junit4] 2> 1021767 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\collection1\conf\xslt
[junit4:junit4] 2> 1021777 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\collection1\lib
[junit4:junit4] 2> 1021779 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\collection1\lib\classes
[junit4:junit4] 2> 1021786 T2976 oasc.SolrCoreDiscoverer.addCore Discovered properties file C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\conf\core.properties, adding to cores
[junit4:junit4] 2> 1021808 T2976 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 1021808 T2976 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1021808 T2976 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 1021808 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1021809 T2976 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1021809 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1021809 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1021809 T2976 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1021809 T2976 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1021810 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 1021820 T2976 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1021821 T2976 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:61805/solr
[junit4:junit4] 2> 1021822 T2976 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1021825 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1021847 T3042 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7658ab53 name:ZooKeeperConnection Watcher:127.0.0.1:61805 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1021847 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1021852 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1021860 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1021864 T3044 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3344ec94 name:ZooKeeperConnection Watcher:127.0.0.1:61805/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1021865 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1021876 T2976 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1023260 T2976 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:61842__
[junit4:junit4] 2> 1023268 T2976 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:61842__
[junit4:junit4] 2> 1023275 T3016 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1023276 T3030 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1023276 T3044 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1023277 T2998 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1023277 T3003 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1023290 T2976 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 1023290 T2976 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1023290 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1023817 T2976 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1023821 T2976 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:61851
[junit4:junit4] 2> 1023823 T2976 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1023824 T2976 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1023824 T2976 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728
[junit4:junit4] 2> 1023824 T2976 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\solr.xml
[junit4:junit4] 2> 1023824 T2976 oasc.CoreContainer.<init> New CoreContainer 945188962
[junit4:junit4] 2> 1023825 T2976 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\'
[junit4:junit4] 2> 1023825 T2976 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\'
[junit4:junit4] 2> 1023965 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728
[junit4:junit4] 2> 1023968 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\collection1
[junit4:junit4] 2> 1023971 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\collection1\conf
[junit4:junit4] 2> 1024252 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\collection1\conf\xslt
[junit4:junit4] 2> 1024264 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\collection1\lib
[junit4:junit4] 2> 1024267 T2976 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\collection1\lib\classes
[junit4:junit4] 2> 1024276 T2976 oasc.SolrCoreDiscoverer.addCore Discovered properties file C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\conf\core.properties, adding to cores
[junit4:junit4] 2> 1024299 T2976 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 1024301 T2976 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1024301 T2976 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 1024301 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1024302 T2976 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1024302 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1024303 T2976 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1024303 T2976 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1024303 T2976 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1024303 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 1024315 T2976 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1024317 T2976 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:61805/solr
[junit4:junit4] 2> 1024317 T2976 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1024319 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1024341 T3056 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1566c704 name:ZooKeeperConnection Watcher:127.0.0.1:61805 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1024342 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1024348 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1024358 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1024366 T3058 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@746fcac5 name:ZooKeeperConnection Watcher:127.0.0.1:61805/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1024368 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1024379 T2976 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1025670 T2976 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:61851__
[junit4:junit4] 2> 1025680 T2976 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:61851__
[junit4:junit4] 2> 1025686 T3003 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1025687 T3016 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1025687 T3030 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1025687 T3044 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1025689 T2998 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1025689 T3058 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1025700 T2976 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 1025700 T2976 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1025701 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1025707 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1025714 T3012 oasha.CollectionsHandler.handleCreateAction Creating Collection : numShards=2&name=nodes_used_collection&replicationFactor=2&action=CREATE&wt=javabin&version=2
[junit4:junit4] 2> 1025718 T2998 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4] 2> 1025721 T2998 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4] 2> 1025723 T3000 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> 1025723 T3000 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:61812__
[junit4:junit4] 2> 1025724 T3000 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:61842__
[junit4:junit4] 2> 1025724 T3000 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:61824__
[junit4:junit4] 2> 1025725 T3000 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:61851__
[junit4:junit4] 2> 1025729 T3007 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard2_replica1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 1025730 T3007 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4] 2> 1025730 T2990 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard1_replica1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 1025730 T2990 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4] 2> 1025730 T3040 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard1_replica2' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 1025731 T3040 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4] 2> 1025732 T3007 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4] 2> 1025733 T3007 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 1025733 T3052 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard2_replica2' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 1025733 T3052 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4] 2> 1025733 T3040 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4] 2> 1025735 T3040 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 1025733 T2990 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4] 2> 1025736 T2990 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 1025736 T3052 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4] 2> 1025736 T3007 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 1025737 T3007 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4] 2> 1025737 T3052 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 1025740 T3040 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 1025740 T3040 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4] 2> 1025740 T2990 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 1025741 T2990 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4] 2> 1025742 T3052 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 1025742 T3052 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4] 2> 1025746 T3007 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4] 2> 1025749 T3040 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4] 2> 1025749 T2990 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4] 2> 1025752 T3052 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4] 2> 1025754 T3007 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\nodes_used_collection_shard2_replica1\'
[junit4:junit4] 2> 1025754 T3040 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\nodes_used_collection_shard1_replica2\'
[junit4:junit4] 2> 1025760 T3052 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\nodes_used_collection_shard2_replica2\'
[junit4:junit4] 2> 1025761 T2990 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\nodes_used_collection_shard1_replica1\'
[junit4:junit4] 2> 1025852 T3007 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1025952 T3007 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1025958 T3052 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1025968 T2990 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1026028 T3040 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1026061 T2990 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1026078 T3052 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1026082 T3007 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1026090 T3007 oass.IndexSchema.readSchema [nodes_used_collection_shard2_replica1] Schema name=test
[junit4:junit4] 2> 1026102 T2990 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1026104 T3052 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1026111 T3052 oass.IndexSchema.readSchema [nodes_used_collection_shard2_replica2] Schema name=test
[junit4:junit4] 2> 1026113 T2990 oass.IndexSchema.readSchema [nodes_used_collection_shard1_replica1] Schema name=test
[junit4:junit4] 2> 1026147 T3040 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1026469 T3040 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1026476 T3040 oass.IndexSchema.readSchema [nodes_used_collection_shard1_replica2] Schema name=test
[junit4:junit4] 2> 1027577 T3007 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1027593 T3007 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1027598 T3007 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1027720 T3052 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1027764 T3052 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1027769 T3052 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1027881 T2990 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1027891 T2990 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1027896 T2990 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1028001 T3007 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1028010 T3007 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1028015 T3052 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1028020 T3007 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1028024 T2990 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1028026 T3007 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1028028 T3007 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1028028 T3007 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1028033 T3052 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1028038 T3007 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1028038 T3007 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1028039 T3007 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1028040 T3007 oasc.SolrCore.<init> [nodes_used_collection_shard2_replica1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\nodes_used_collection_shard2_replica1\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\nodes_used_collection_shard2_replica1\data\
[junit4:junit4] 2> 1028040 T3007 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3041876
[junit4:junit4] 2> 1028040 T3007 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1028041 T3007 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\nodes_used_collection_shard2_replica1\data\
[junit4:junit4] 2> 1028041 T3007 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\nodes_used_collection_shard2_replica1\data\index/
[junit4:junit4] 2> 1028041 T3007 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard2_replica1] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\nodes_used_collection_shard2_replica1\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1028043 T3007 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\nodes_used_collection_shard2_replica1\data\index
[junit4:junit4] 2> 1028049 T3007 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e3a9fc5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3c26ee7b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1028050 T3007 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1028055 T3007 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1028055 T3007 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1028056 T3007 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1028056 T3007 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1028057 T3007 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1028057 T3007 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1028057 T3007 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1028058 T3007 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1028060 T3007 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1028060 T2990 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1028073 T3007 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1028078 T3007 oass.SolrIndexSearcher.<init> Opening Searcher@7b3adc87 main
[junit4:junit4] 2> 1028079 T3007 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1369724771087\nodes_used_collection_shard2_replica1\data\tlog
[junit4:junit4] 2> 1028080 T3007 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1028080 T3007 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1028087 T3007 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica1 state=down
[junit4:junit4] 2> 1028096 T3052 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1028102 T2990 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1028103 T3064 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica1] Registered new searcher Searcher@7b3adc87 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1028107 T3052 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1028115 T3052 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1028115 T2990 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1028115 T2990 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1028115 T3052 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1028116 T2990 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1028119 T3052 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1028119 T3052 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1028120 T3052 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1028120 T3052 oasc.SolrCore.<init> [nodes_used_collection_shard2_replica2] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\nodes_used_collection_shard2_replica2\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\nodes_used_collection_shard2_replica2\data\
[junit4:junit4] 2> 1028120 T3052 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3041876
[junit4:junit4] 2> 1028121 T3052 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1028123 T3052 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\nodes_used_collection_shard2_replica2\data\
[junit4:junit4] 2> 1028123 T3052 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\nodes_used_collection_shard2_replica2\data\index/
[junit4:junit4] 2> 1028123 T3052 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard2_replica2] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\nodes_used_collection_shard2_replica2\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1028124 T3052 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\nodes_used_collection_shard2_replica2\data\index
[junit4:junit4] 2> 1028149 T3040 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1028163 T3040 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1028167 T3040 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1028169 T2990 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1028170 T2990 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1028170 T2990 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1028170 T2990 oasc.SolrCore.<init> [nodes_used_collection_shard1_replica1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\nodes_used_collection_shard1_replica1\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\nodes_used_collection_shard1_replica1\data\
[junit4:junit4] 2> 1028170 T2990 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3041876
[junit4:junit4] 2> 1028171 T2990 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1028172 T2990 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\nodes_used_collection_shard1_replica1\data\
[junit4:junit4] 2> 1028173 T2990 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\nodes_used_collection_shard1_replica1\data\index/
[junit4:junit4] 2> 1028173 T2990 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard1_replica1] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\nodes_used_collection_shard1_replica1\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1028175 T2990 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\nodes_used_collection_shard1_replica1\data\index
[junit4:junit4] 2> 1028175 T3052 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2d708739 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b5184f9),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1028178 T3052 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1028190 T3052 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1028192 T3052 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1028192 T3052 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1028193 T3052 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1028193 T3052 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1028194 T3052 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1028194 T3052 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1028194 T3052 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1028195 T3052 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1028200 T2990 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@646d3b1e lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ef6a5b6),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1028200 T2990 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1028205 T2990 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1028205 T2990 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1028206 T2990 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1028207 T2990 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1028209 T2990 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1028209 T2990 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1028209 T2990 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1028210 T2990 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1028210 T3052 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1028211 T2990 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1028221 T3040 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1028222 T3052 oass.SolrIndexSearcher.<init> Opening Searcher@45e76b8 main
[junit4:junit4] 2> 1028223 T3052 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\nodes_used_collection_shard2_replica2\data\tlog
[junit4:junit4] 2> 1028227 T2990 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1028227 T3052 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1028228 T3052 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1028234 T3052 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica2 state=down
[junit4:junit4] 2> 1028235 T3065 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica2] Registered new searcher Searcher@45e76b8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1028236 T2990 oass.SolrIndexSearcher.<init> Opening Searcher@20bae15b main
[junit4:junit4] 2> 1028238 T2990 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\nodes_used_collection_shard1_replica1\data\tlog
[junit4:junit4] 2> 1028241 T3040 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1028242 T2990 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1028244 T2990 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1028247 T3066 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica1] Registered new searcher Searcher@20bae15b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1028250 T2990 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica1 state=down
[junit4:junit4] 2> 1028256 T3040 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1028258 T3040 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1028258 T3040 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1028259 T3040 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1028261 T3040 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1028261 T3040 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1028261 T3040 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1028263 T3040 oasc.SolrCore.<init> [nodes_used_collection_shard1_replica2] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\nodes_used_collection_shard1_replica2\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\nodes_used_collection_shard1_replica2\data\
[junit4:junit4] 2> 1028263 T3040 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3041876
[junit4:junit4] 2> 1028263 T3040 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1028263 T3040 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\nodes_used_collection_shard1_replica2\data\
[junit4:junit4] 2> 1028265 T3040 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\nodes_used_collection_shard1_replica2\data\index/
[junit4:junit4] 2> 1028265 T3040 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard1_replica2] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\nodes_used_collection_shard1_replica2\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1028265 T3040 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\nodes_used_collection_shard1_replica2\data\index
[junit4:junit4] 2> 1028272 T3040 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@43497848 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1466fd25),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1028272 T3040 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1028276 T3040 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1028276 T3040 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1028278 T3040 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1028278 T3040 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1028280 T3040 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1028280 T3040 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1028280 T3040 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1028281 T3040 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1028281 T3040 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1028291 T3040 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1028301 T3040 oass.SolrIndexSearcher.<init> Opening Searcher@6cfdfa1 main
[junit4:junit4] 2> 1028301 T3040 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\nodes_used_collection_shard1_replica2\data\tlog
[junit4:junit4] 2> 1028303 T3040 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1028304 T3040 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1028308 T3067 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica2] Registered new searcher Searcher@6cfdfa1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1028310 T3040 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica2 state=down
[junit4:junit4] 2> 1029863 T2999 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1029865 T2999 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:61824__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61824/_"}
[junit4:junit4] 2> 1029865 T2999 oasc.Overseer$ClusterStateUpdater.createCollection Create collection nodes_used_collection with numShards 2
[junit4:junit4] 2> 1029874 T2999 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:61851__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61851/_"}
[junit4:junit4] 2> 1029884 T2999 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:61812__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61812/_"}
[junit4:junit4] 2> 1029893 T2999 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:61842__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61842/_"}
[junit4:junit4] 2> 1029903 T3058 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> 1029905 T3003 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> 1029905 T3030 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> 1029905 T3044 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> 1029906 T2998 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> 1029905 T3016 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> 1030587 T3007 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 1030587 T3007 oasc.ZkController.register Register replica - core:nodes_used_collection_shard2_replica1 address:http://127.0.0.1:61824/_ collection:nodes_used_collection shard:shard2
[junit4:junit4] 2> 1030589 T3007 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leader_elect/shard2/election
[junit4:junit4] 2> 1030635 T3007 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1030642 T3007 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Waiting until we see more replicas up: total=2 found=1 timeoutin=179999
[junit4:junit4] 2> 1030730 T3052 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 1030730 T3052 oasc.ZkController.register Register replica - core:nodes_used_collection_shard2_replica2 address:http://127.0.0.1:61851/_ collection:nodes_used_collection shard:shard2
[junit4:junit4] 2> 1030736 T2990 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 1030736 T2990 oasc.ZkController.register Register replica - core:nodes_used_collection_shard1_replica1 address:http://127.0.0.1:61812/_ collection:nodes_used_collection shard:shard1
[junit4:junit4] 2> 1030737 T2990 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1030753 T2990 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1030760 T2990 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Waiting until we see more replicas up: total=2 found=1 timeoutin=179999
[junit4:junit4] 2> 1030795 T3040 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 1030795 T3040 oasc.ZkController.register Register replica - core:nodes_used_collection_shard1_replica2 address:http://127.0.0.1:61842/_ collection:nodes_used_collection shard:shard1
[junit4:junit4] 2> 1031264 T3007 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1031264 T3007 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1031265 T3007 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:61824/_/nodes_used_collection_shard2_replica1/
[junit4:junit4] 2> 1031265 T3007 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard2_replica1 url=http://127.0.0.1:61824/_ START replicas=[http://127.0.0.1:61851/_/nodes_used_collection_shard2_replica2/] nUpdates=100
[junit4:junit4] 2> 1031266 T3007 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard2_replica1 url=http://127.0.0.1:61824/_ DONE. We have no versions. sync failed.
[junit4:junit4] 2> 1031266 T3007 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4] 2> 1031268 T3007 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> 1031269 T3007 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:61824/_/nodes_used_collection_shard2_replica1/
[junit4:junit4] 2> 1031269 T3007 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leaders/shard2
[junit4:junit4] 2> ASYNC NEW_CORE C6320 name=nodes_used_collection_shard2_replica2 org.apache.solr.core.SolrCore@17bf619a url=http://127.0.0.1:61851/_/nodes_used_collection_shard2_replica2 node=127.0.0.1:61851__ C6320_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica2 props:{shard=shard2, state=down, core=nodes_used_collection_shard2_replica2, collection=nodes_used_collection, node_name=127.0.0.1:61851__, base_url=http://127.0.0.1:61851/_}
[junit4:junit4] 2> 1031285 T3054 C6320 P61851 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=2
[junit4:junit4] 2> 1031381 T2990 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1031381 T2990 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1031381 T2990 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:61812/_/nodes_used_collection_shard1_replica1/
[junit4:junit4] 2> 1031381 T2990 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard1_replica1 url=http://127.0.0.1:61812/_ START replicas=[http://127.0.0.1:61842/_/nodes_used_collection_shard1_replica2/] nUpdates=100
[junit4:junit4] 2> 1031384 T2990 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard1_replica1 url=http://127.0.0.1:61812/_ DONE. We have no versions. sync failed.
[junit4:junit4] 2> 1031396 T2990 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4] 2> 1031397 T2990 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> 1031397 T2990 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:61812/_/nodes_used_collection_shard1_replica1/
[junit4:junit4] 2> 1031398 T2990 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leaders/shard1
[junit4:junit4] 2> ASYNC NEW_CORE C6321 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@49f6eb98 url=http://127.0.0.1:61842/_/nodes_used_collection_shard1_replica2 node=127.0.0.1:61842__ C6321_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:61842__, base_url=http://127.0.0.1:61842/_}
[junit4:junit4] 2> 1031418 T3036 C6321 P61842 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> 1031792 T2999 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1031843 T3058 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> 1031843 T3016 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> 1031844 T3030 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> 1031843 T3003 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> 1031845 T2998 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> 1031844 T3044 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> 1031858 T3007 oasc.ZkController.register We are http://127.0.0.1:61824/_/nodes_used_collection_shard2_replica1/ and leader is http://127.0.0.1:61824/_/nodes_used_collection_shard2_replica1/
[junit4:junit4] 2> 1031858 T3007 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard2_replica1 baseURL=http://127.0.0.1:61824/_
[junit4:junit4] 2> 1031859 T3007 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1031859 T3007 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica1 state=active
[junit4:junit4] 2> 1031867 T3007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1031870 T3007 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=6141
[junit4:junit4] 2> 1031922 T2990 oasc.ZkController.register We are http://127.0.0.1:61812/_/nodes_used_collection_shard1_replica1/ and leader is http://127.0.0.1:61812/_/nodes_used_collection_shard1_replica1/
[junit4:junit4] 2> 1031922 T2990 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard1_replica1 baseURL=http://127.0.0.1:61812/_
[junit4:junit4] 2> 1031923 T2990 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1031923 T2990 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica1 state=active
[junit4:junit4] 2> 1031928 T2990 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1031929 T2990 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=6200
[junit4:junit4] 2> 1031979 T3052 oasc.ZkController.register We are http://127.0.0.1:61851/_/nodes_used_collection_shard2_replica2/ and leader is http://127.0.0.1:61824/_/nodes_used_collection_shard2_replica1/
[junit4:junit4] 2> 1031979 T3052 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard2_replica2 baseURL=http://127.0.0.1:61851/_
[junit4:junit4] 2> 1031979 T3052 oasc.ZkController.checkRecovery Core needs to recover:nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 1031980 T3052 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C6322 name=nodes_used_collection_shard2_replica2 org.apache.solr.core.SolrCore@17bf619a url=http://127.0.0.1:61851/_/nodes_used_collection_shard2_replica2 node=127.0.0.1:61851__ C6322_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica2 props:{shard=shard2, state=down, core=nodes_used_collection_shard2_replica2, collection=nodes_used_collection, node_name=127.0.0.1:61851__, base_url=http://127.0.0.1:61851/_}
[junit4:junit4] 2> 1031980 T3070 C6322 P61851 oasc.RecoveryStrategy.run Starting recovery process. core=nodes_used_collection_shard2_replica2 recoveringAfterStartup=true
[junit4:junit4] 2> 1031981 T3070 C6322 P61851 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1031981 T3052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1031984 T3070 C6322 P61851 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica2 state=recovering
[junit4:junit4] 2> 1031986 T3052 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=6253
[junit4:junit4] 2> 1031990 T3070 C6322 P61851 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1032008 T3008 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:61851___nodes_used_collection_shard2_replica2, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1032043 T3040 oasc.ZkController.register We are http://127.0.0.1:61842/_/nodes_used_collection_shard1_replica2/ and leader is http://127.0.0.1:61812/_/nodes_used_collection_shard1_replica1/
[junit4:junit4] 2> 1032044 T3040 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard1_replica2 baseURL=http://127.0.0.1:61842/_
[junit4:junit4] 2> 1032044 T3040 oasc.ZkController.checkRecovery Core needs to recover:nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 1032044 T3040 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> 1032047 T3071 C6321 P61842 oasc.RecoveryStrategy.run Starting recovery process. core=nodes_used_collection_shard1_replica2 recoveringAfterStartup=true
[junit4:junit4] 2> 1032047 T3071 C6321 P61842 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1032049 T3071 C6321 P61842 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica2 state=recovering
[junit4:junit4] 2> 1032049 T3040 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1032053 T3071 C6321 P61842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1032054 T3040 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=6324
[junit4:junit4] 2> 1032056 T3000 oasc.OverseerCollectionProcessor.createCollection Finished create command on all shards for collection: nodes_used_collection
[junit4:junit4] 2> 1032064 T2993 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:61842___nodes_used_collection_shard1_replica2, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1032068 T3016 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work/qnr-0000000000 state: SyncConnected type NodeDataChanged
[junit4:junit4] 2> 1032074 T3000 oasc.OverseerCollectionProcessor.run Overseer Collection Processor: Message id:/overseer/collection-queue-work/qn-0000000000 complete, response:{success={null={responseHeader={status=0,QTime=6141},core=nodes_used_collection_shard2_replica1},null={responseHeader={status=0,QTime=6200},core=nodes_used_collection_shard1_replica1},null={responseHeader={status=0,QTime=6253},core=nodes_used_collection_shard2_replica2},null={responseHeader={status=0,QTime=6324},core=nodes_used_collection_shard1_replica2}}}
[junit4:junit4] 2> 1032085 T3012 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=6371
[junit4:junit4] 2> 1032087 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1032089 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1032094 T3073 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@658b1e65 name:ZooKeeperConnection Watcher:127.0.0.1:61805/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1032095 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1032097 T2976 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1032105 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1032110 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1032116 T3075 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7d453291 name:ZooKeeperConnection Watcher:127.0.0.1:61805/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1032117 T2976 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1032119 T2976 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1032134 T2989 oasha.CollectionsHandler.handleCreateAction Creating Collection : numShards=2&maxShardsPerNode=1&name=awholynewcollection_0&replicationFactor=2&action=CREATE&wt=javabin&version=2
[junit4:junit4] 2> 1032140 T2998 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4] 2> 1032146 T3000 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":"2",
[junit4:junit4] 2> "maxShardsPerNode":"1",
[junit4:junit4] 2> "createNodeSet":null,
[junit4:junit4] 2> "name":"awholynewcollection_0",
[junit4:junit4] 2> "replicationFactor":"2"}
[junit4:junit4] 2> 1032146 T3000 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica1 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:61833__
[junit4:junit4] 2> 1032146 T3000 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica2 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:61812__
[junit4:junit4] 2> 1032147 T3000 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard2_replica1 as part of slice shard2 of collection awholynewcollection_0 on 127.0.0.1:61842__
[junit4:junit4] 2> 1032147 T3000 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard2_replica2 as part of slice shard2 of collection awholynewcollection_0 on 127.0.0.1:61851__
[junit4:junit4] 2> 1032152 T3022 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard1_replica1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\awholynewcollection_0_shard1_replica1
[junit4:junit4] 2> 1032152 T3022 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 1032152 T2991 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard1_replica2' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\awholynewcollection_0_shard1_replica2
[junit4:junit4] 2> 1032154 T3037 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard2_replica1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\awholynewcollection_0_shard2_replica1
[junit4:junit4] 2> 1032156 T3037 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 1032154 T3050 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard2_replica2' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\awholynewcollection_0_shard2_replica2
[junit4:junit4] 2> 1032157 T3050 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 1032154 T2991 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 1032157 T3037 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 1032158 T3037 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 1032160 T2991 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 1032160 T2991 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 1032157 T3022 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 1032162 T3022 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 1032160 T3050 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 1032164 T3050 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 1032163 T3037 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 1032167 T3037 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 1032168 T2991 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 1032169 T2991 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 1032168 T3022 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 1032171 T3022 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 1032170 T3050 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 1032173 T3050 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 1032181 T2991 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 1032183 T3037 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 1032185 T3022 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 1032188 T3050 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 1032191 T3037 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\awholynewcollection_0_shard2_replica1\'
[junit4:junit4] 2> 1032193 T2991 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\awholynewcollection_0_shard1_replica2\'
[junit4:junit4] 2> 1032193 T3022 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\awholynewcollection_0_shard1_replica1\'
[junit4:junit4] 2> 1032198 T3050 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\awholynewcollection_0_shard2_replica2\'
[junit4:junit4] 2> 1032337 T3037 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1032362 T3050 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1032422 T2991 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1032428 T3022 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1032528 T3050 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1032568 T3037 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1032571 T2991 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1032574 T3050 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1032581 T3050 oass.IndexSchema.readSchema [awholynewcollection_0_shard2_replica2] Schema name=test
[junit4:junit4] 2> 1032603 T3022 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1032606 T3037 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1032612 T3037 oass.IndexSchema.readSchema [awholynewcollection_0_shard2_replica1] Schema name=test
[junit4:junit4] 2> 1032649 T2991 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1032655 T2991 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica2] Schema name=test
[junit4:junit4] 2> 1032675 T3022 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1032681 T3022 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica1] Schema name=test
[junit4:junit4] 2> 1034144 T2999 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1034147 T2999 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:61824___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:61824__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61824/_"}
[junit4:junit4] 2> 1034220 T3022 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1034243 T3022 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1034248 T3022 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1034275 T3050 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1034287 T3050 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1034291 T3050 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1034319 T2991 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1034329 T2991 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1034334 T2991 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1034341 T2999 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:61812___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:61812__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61812/_"}
[junit4:junit4] 2> 1034368 T2999 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:61851___nodes_used_collection_shard2_replica2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"nodes_used_collection_shard2_replica2",
[junit4:junit4] 2> "collection":"nodes_used_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:61851__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61851/_"}
[junit4:junit4] 2> 1034393 T2999 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:61842___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:61842__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61842/_"}
[junit4:junit4] 2> 1034403 T3050 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1034407 T3022 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1034415 T3050 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1034422 T3022 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1034438 T3050 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1034450 T3022 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1034466 T3075 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> 1034467 T3073 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> 1034467 T3003 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> 1034468 T2991 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1034470 T3058 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> 1034471 T3016 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> 1034471 T3030 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> 1034471 T3044 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> 1034471 T2998 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> 1034476 T3050 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1034476 T3050 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1034477 T3050 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1034479 T3022 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1034479 T3022 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1034479 T3022 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1034490 T2991 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1034491 T3022 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1034493 T3022 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1034493 T3022 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1034493 T3022 oasc.SolrCore.<init> [awholynewcollection_0_shard1_replica1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\awholynewcollection_0_shard1_replica1\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\awholynewcollection_0_shard1_replica1\data\
[junit4:junit4] 2> 1034493 T3022 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3041876
[junit4:junit4] 2> 1034494 T3022 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1034495 T3050 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1034495 T3050 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1034496 T3050 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1034496 T3050 oasc.SolrCore.<init> [awholynewcollection_0_shard2_replica2] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\awholynewcollection_0_shard2_replica2\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\awholynewcollection_0_shard2_replica2\data\
[junit4:junit4] 2> 1034496 T3050 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3041876
[junit4:junit4] 2> 1034496 T3050 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1034499 T3022 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\awholynewcollection_0_shard1_replica1\data\
[junit4:junit4] 2> 1034500 T3022 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\awholynewcollection_0_shard1_replica1\data\index/
[junit4:junit4] 2> 1034501 T3022 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard1_replica1] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\awholynewcollection_0_shard1_replica1\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1034501 T3050 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\awholynewcollection_0_shard2_replica2\data\
[junit4:junit4] 2> 1034502 T3050 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\awholynewcollection_0_shard2_replica2\data\index/
[junit4:junit4] 2> 1034502 T3050 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard2_replica2] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\awholynewcollection_0_shard2_replica2\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1034502 T3022 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\awholynewcollection_0_shard1_replica1\data\index
[junit4:junit4] 2> 1034503 T3050 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\awholynewcollection_0_shard2_replica2\data\index
[junit4:junit4] 2> 1034514 T3022 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4f9ed367 lockFactory=org.apache.lucene.store.NativeFSLockFactory@348d99),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1034516 T3022 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1034519 T3022 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1034519 T3022 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1034520 T3022 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1034522 T3022 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1034522 T3022 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1034523 T3022 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1034523 T3022 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1034523 T3022 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1034524 T3022 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1034524 T2991 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1034535 T3008 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:61851___nodes_used_collection_shard2_replica2, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1034536 T3022 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1034542 T3008 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:61851___nodes_used_collection_shard2_replica2&state=recovering&nodeName=127.0.0.1:61851__&action=PREPRECOVERY&checkLive=true&core=nodes_used_collection_shard2_replica1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2534
[junit4:junit4] 2> 1034550 T3022 oass.SolrIndexSearcher.<init> Opening Searcher@291231b9 main
[junit4:junit4] 2> 1034550 T3022 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1369724773679\awholynewcollection_0_shard1_replica1\data\tlog
[junit4:junit4] 2> 1034551 T3022 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1034552 T3022 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1034553 T3050 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@74e8488f lockFactory=org.apache.lucene.store.NativeFSLockFactory@77ae0b1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1034557 T3050 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1034557 T2991 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1034557 T2991 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1034558 T2991 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1034560 T3050 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1034562 T3050 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1034563 T3050 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1034563 T3050 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1034564 T3050 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1034564 T3050 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1034564 T3050 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1034565 T3050 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1034566 T3050 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1034569 T2991 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1034569 T2991 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1034570 T2991 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1034570 T2991 oasc.SolrCore.<init> [awholynewcollection_0_shard1_replica2] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\awholynewcollection_0_shard1_replica2\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\awholynewcollection_0_shard1_replica2\data\
[junit4:junit4] 2> 1034570 T2991 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3041876
[junit4:junit4] 2> 1034571 T2991 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1034571 T2991 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\awholynewcollection_0_shard1_replica2\data\
[junit4:junit4] 2> 1034573 T2991 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\awholynewcollection_0_shard1_replica2\data\index/
[junit4:junit4] 2> 1034573 T2991 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard1_replica2] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\awholynewcollection_0_shard1_replica2\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1034574 T2991 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\awholynewcollection_0_shard1_replica2\data\index
[junit4:junit4] 2> 1034580 T2991 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@982dc86 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6710c0e9),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1034580 T2991 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1034585 T2991 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1034585 T2991 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1034586 T2991 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1034586 T2991 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1034587 T2991 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1034587 T2991 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1034587 T2991 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1034598 T2991 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1034599 T2991 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1034602 T3050 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1034606 T3050 oass.SolrIndexSearcher.<init> Opening Searcher@5b4491f0 main
[junit4:junit4] 2> 1034608 T3050 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\awholynewcollection_0_shard2_replica2\data\tlog
[junit4:junit4] 2> 1034609 T3050 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1034610 T3050 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1034616 T2991 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1034621 T2991 oass.SolrIndexSearcher.<init> Opening Searcher@fc8e913 main
[junit4:junit4] 2> 1034621 T2991 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1369724769798\awholynewcollection_0_shard1_replica2\data\tlog
[junit4:junit4] 2> 1034628 T2991 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1034628 T2991 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1034636 T2991 oasc.ZkController.publish publishing core=awholynewcollection_0_shard1_replica2 state=down
[junit4:junit4] 2> 1034638 T3022 oasc.ZkController.publish publishing core=awholynewcollection_0_shard1_replica1 state=down
[junit4:junit4] 2> 1034640 T3078 oasc.SolrCore.registerSearcher [awholynewcollection_0_shard1_replica2] Registered new searcher Searcher@fc8e913 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1034640 T3076 oasc.SolrCore.registerSearcher [awholynewcollection_0_shard1_replica1] Registered new searcher Searcher@291231b9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1034645 T3050 oasc.ZkController.publish publishing core=awholynewcollection_0_shard2_replica2 state=down
[junit4:junit4] 2> 1034648 T3077 oasc.SolrCore.registerSearcher [awholynewcollection_0_shard2_replica2] Registered new searcher Searcher@5b4491f0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1034713 T3037 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1034726 T3037 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1034742 T3037 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1034765 T3037 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1034777 T3037 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1034785 T3037 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1034787 T3037 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1034787 T3037 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1034788 T3037 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1034789 T3037 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1034789 T3037 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1034789 T3037 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1034791 T3037 oasc.SolrCore.<init> [awholynewcollection_0_shard2_replica1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\awholynewcollection_0_shard2_replica1\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\awholynewcollection_0_shard2_replica1\data\
[junit4:junit4] 2> 1034791 T3037 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3041876
[junit4:junit4] 2> 1034792 T3037 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1034792 T3037 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\awholynewcollection_0_shard2_replica1\data\
[junit4:junit4] 2> 1034793 T3037 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\awholynewcollection_0_shard2_replica1\data\index/
[junit4:junit4] 2> 1034793 T3037 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard2_replica1] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\awholynewcollection_0_shard2_replica1\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1034794 T3037 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\awholynewcollection_0_shard2_replica1\data\index
[junit4:junit4] 2> 1034799 T3037 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3b871ad1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73ebe6d0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1034799 T3037 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1034805 T3037 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1034805 T3037 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1034806 T3037 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1034806 T3037 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1034808 T3037 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1034808 T3037 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1034808 T3037 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1034809 T3037 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1034809 T3037 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1034818 T3037 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1034829 T3037 oass.SolrIndexSearcher.<init> Opening Searcher@27f92920 main
[junit4:junit4] 2> 1034829 T3037 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\awholynewcollection_0_shard2_replica1\data\tlog
[junit4:junit4] 2> 1034832 T3037 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1034832 T3037 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1034838 T3079 oasc.SolrCore.registerSearcher [awholynewcollection_0_shard2_replica1] Registered new searcher Searcher@27f92920 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1034838 T3037 oasc.ZkController.publish publishing core=awholynewcollection_0_shard2_replica1 state=down
[junit4:junit4] 2> 1035814 T2993 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:61842___nodes_used_collection_shard1_replica2, state: recovering, checkLive: true, onlyIfLeader: true for: 3 seconds.
[junit4:junit4] 2> 1035814 T2993 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:61842___nodes_used_collection_shard1_replica2&state=recovering&nodeName=127.0.0.1:61842__&action=PREPRECOVERY&checkLive=true&core=nodes_used_collection_shard1_replica1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=3750
[junit4:junit4] 2> 1036516 T2999 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1036517 T2999 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":"awholynewcollection_0_shard1_replica2",
[junit4:junit4] 2> "collection":"awholynewcollection_0",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:61812__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61812/_"}
[junit4:junit4] 2> 1036517 T2999 oasc.Overseer$ClusterStateUpdater.createCollection Create collection awholynewcollection_0 with numShards 2
[junit4:junit4] 2> 1036532 T2999 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":"awholynewcollection_0_shard1_replica1",
[junit4:junit4] 2> "collection":"awholynewcollection_0",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:61833__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61833/_"}
[junit4:junit4] 2> 1036540 T2999 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":"awholynewcollection_0_shard2_replica2",
[junit4:junit4] 2> "collection":"awholynewcollection_0",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:61851__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61851/_"}
[junit4:junit4] 2> 1036549 T2999 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":"awholynewcollection_0_shard2_replica1",
[junit4:junit4] 2> "collection":"awholynewcollection_0",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:61842__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61842/_"}
[junit4:junit4] 2> 1036558 T3058 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> 1036559 T3016 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> 1036559 T3030 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> 1036561 T3075 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> 1036561 T2998 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> 1036561 T3003 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> 1036562 T3044 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> 1036561 T3073 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> ASYNC NEW_CORE C6323 name=nodes_used_collection_shard2_replica2 org.apache.solr.core.SolrCore@17bf619a url=http://127.0.0.1:61851/_/nodes_used_collection_shard2_replica2 node=127.0.0.1:61851__ C6323_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica2 props:{shard=shard2, state=recovering, core=nodes_used_collection_shard2_replica2, collection=nodes_used_collection, node_name=127.0.0.1:61851__, base_url=http://127.0.0.1:61851/_}
[junit4:junit4] 2> 1037023 T3070 C6323 P61851 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:61824/_/nodes_used_collection_shard2_replica1/ core=nodes_used_collection_shard2_replica2 - recoveringAfterStartup=true
[junit4:junit4] 2> 1037023 T3070 C6323 P61851 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard2_replica2 url=http://127.0.0.1:61851/_ START replicas=[http://127.0.0.1:61824/_/nodes_used_collection_shard2_replica1/] nUpdates=100
[junit4:junit4] 2> 1037025 T3070 C6323 P61851 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1037025 T3070 C6323 P61851 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 1037025 T3070 C6323 P61851 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 1037025 T3070 C6323 P61851 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 1037025 T3070 C6323 P61851 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1037026 T3070 C6323 P61851 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:61824/_/nodes_used_collection_shard2_replica1/. core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 1037026 T3070 C6323 P61851 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C6324 name=nodes_used_collection_shard2_replica1 org.apache.solr.core.SolrCore@463a7db0 url=http://127.0.0.1:61824/_/nodes_used_collection_shard2_replica1 node=127.0.0.1:61824__ C6324_STATE=coll:nodes_used_collection core:nodes_used_collection_shard2_replica1 props:{shard=shard2, state=active, core=nodes_used_collection_shard2_replica1, collection=nodes_used_collection, node_name=127.0.0.1:61824__, base_url=http://127.0.0.1:61824/_, leader=true}
[junit4:junit4] 2> 1037038 T3012 C6324 P61824 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> 1037039 T3009 C6324 P61824 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1037044 T3009 C6324 P61824 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e3a9fc5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3c26ee7b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1037045 T3009 C6324 P61824 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1037045 T3009 C6324 P61824 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e3a9fc5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3c26ee7b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e3a9fc5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3c26ee7b),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1037045 T3009 C6324 P61824 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1037046 T3009 C6324 P61824 oass.SolrIndexSearcher.<init> Opening Searcher@4c2a67cc realtime
[junit4:junit4] 2> 1037046 T3009 C6324 P61824 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1037046 T3009 C6324 P61824 oasup.LogUpdateProcessor.finish [nodes_used_collection_shard2_replica1] webapp=/_ path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 1037049 T3070 C6323 P61851 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1037049 T3070 C6323 P61851 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1037054 T3011 C6324 P61824 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1037054 T3011 C6324 P61824 oasc.SolrCore.execute [nodes_used_collection_shard2_replica1] webapp=/_ path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 1037055 T3070 C6323 P61851 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1037055 T3070 C6323 P61851 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1037055 T3070 C6323 P61851 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1037057 T3007 C6324 P61824 oasc.SolrCore.execute [nodes_used_collection_shard2_replica1] webapp=/_ path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 1037057 T3070 C6323 P61851 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1037059 T3070 C6323 P61851 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\nodes_used_collection_shard2_replica2\data\index.20130528090632489
[junit4:junit4] 2> 1037059 T3070 C6323 P61851 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@6cfa2a40 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7a88d0c1) fullCopy=false
[junit4:junit4] 2> 1037065 T3008 C6324 P61824 oasc.SolrCore.execute [nodes_used_collection_shard2_replica1] webapp=/_ path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1037066 T3070 C6323 P61851 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1037068 T3070 C6323 P61851 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1037068 T3070 C6323 P61851 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 1037073 T3070 C6323 P61851 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2d708739 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b5184f9),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2d708739 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b5184f9),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1037074 T3070 C6323 P61851 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1037074 T3070 C6323 P61851 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1037076 T3070 C6323 P61851 oass.SolrIndexSearcher.<init> Opening Searcher@592dd228 main
[junit4:junit4] 2> 1037078 T3065 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica2] Registered new searcher Searcher@592dd228 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1037078 T3070 C6323 P61851 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\nodes_used_collection_shard2_replica2\data\index.20130528090632489 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\nodes_used_collection_shard2_replica2\data\index.20130528090632489;done=true>>]
[junit4:junit4] 2> 1037078 T3070 C6323 P61851 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\nodes_used_collection_shard2_replica2\data\index.20130528090632489
[junit4:junit4] 2> 1037078 T3070 C6323 P61851 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1369724778728\nodes_used_collection_shard2_replica2\data\index.20130528090632489
[junit4:junit4] 2> 1037078 T3070 C6323 P61851 oasc.RecoveryStrategy.replay No replay needed. core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 1037078 T3070 C6323 P61851 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 1037079 T3070 C6323 P61851 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica2 state=active
[junit4:junit4] 2> 1037083 T3070 C6323 P61851 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 1037131 T3022 oasc.CoreContainer.registerCore registering core: awholynewcollection_0_shard1_replica1
[junit4:junit4] 2> 1037131 T3022 oasc.ZkController.register Register replica - core:awholynewcollection_0_shard1_replica1 address:http://127.0.0.1:61833/_ collection:awholynewcollection_0 shard:shard1
[junit4:junit4] 2> 1037132 T3050 oasc.CoreContainer.registerCore registering core: awholynewcollection_0_shard2_replica2
[junit4:junit4] 2> 1037131 T2991 oasc.CoreContainer.registerCore registering core: awholynewcollection_0_shard1_replica2
[junit4:junit4] 2> 1037133 T2991 oasc.ZkController.register Register replica - core:awholynewcollection_0_shard1_replica2 address:http://127.0.0.1:61812/_ collection:awholynewcollection_0 shard:shard1
[junit4:junit4] 2> 1037133 T3022 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0/leader_elect/shard1/election
[junit4:junit4] 2> 1037135 T2991 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0/leader_elect/shard1/election
[junit4:junit4] 2> 1037133 T3050 oasc.ZkController.register Register replica - core:awholynewcollection_0_shard2_replica2 address:http://127.0.0.1:61851/_ collection:awholynewcollection_0 shard:shard2
[junit4:junit4] 2> 1037137 T3050 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0/leader_elect/shard2/election
[junit4:junit4] 2> 1037159 T2991 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1037166 T3050 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1037170 T2991 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1037170 T2991 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1037170 T2991 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:61812/_/awholynewcollection_0_shard1_replica2/
[junit4:junit4] 2> 1037171 T2991 oasu.PeerSync.sync PeerSync: core=awholynewcollection_0_shard1_replica2 url=http://127.0.0.1:61812/_ START replicas=[http://127.0.0.1:61833/_/awholynewcollection_0_shard1_replica1/] nUpdates=100
[junit4:junit4] 2> 1037171 T2991 oasu.PeerSync.sync PeerSync: core=awholynewcollection_0_shard1_replica2 url=http://127.0.0.1:61812/_ DONE. We have no versions. sync failed.
[junit4:junit4] 2> 1037171 T2991 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4] 2> 1037172 T2991 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> 1037172 T2991 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:61812/_/awholynewcollection_0_shard1_replica2/
[junit4:junit4] 2> 1037172 T2991 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0/leaders/shard1
[junit4:junit4] 2> 1037176 T3050 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Waiting until we see more replicas up: total=2 found=1 timeoutin=179998
[junit4:junit4] 2> ASYNC NEW_CORE C6325 name=awholynewcollection_0_shard1_replica1 org.apache.solr.core.SolrCore@43a3c3fd url=http://127.0.0.1:61833/_/awholynewcollection_0_shard1_replica1 node=127.0.0.1:61833__ C6325_STATE=coll:awholynewcollection_0 core:awholynewcollection_0_shard1_replica1 props:{shard=shard1, state=down, core=awholynewcollection_0_shard1_replica1, collection=awholynewcollection_0, node_name=127.0.0.1:61833__, base_url=http://127.0.0.1:61833/_}
[junit4:junit4] 2> 1037188 T3021 C6325 P61833 oasc.SolrCore.execute [awholynewcollection_0_shard1_replica1] webapp=/_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=2
[junit4:junit4] 2> 1037306 T3037 oasc.CoreContainer.registerCore registering core: awholynewcollection_0_shard2_replica1
[junit4:junit4] 2> 1037306 T3037 oasc.ZkController.register Register replica - core:awholynewcollection_0_shard2_replica1 address:http://127.0.0.1:61842/_ collection:awholynewcollection_0 shard:shard2
[junit4:junit4] 2> 1037735 T3050 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1037736 T3050 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1037736 T3050 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:61851/_/awholynewcollection_0_shard2_replica2/
[junit4:junit4] 2> 1037736 T3050 oasu.PeerSync.sync PeerSync: core=awholynewcollection_0_shard2_replica2 url=http://127.0.0.1:61851/_ START replicas=[http://127.0.0.1:61842/_/awholynewcollection_0_shard2_replica1/] nUpdates=100
[junit4:junit4] 2> 1037739 T3050 oasu.PeerSync.sync PeerSync: core=awholynewcollection_0_shard2_replica2 url=http://127.0.0.1:61851/_ DONE. We have no versions. sync failed.
[junit4:junit4] 2> 1037739 T3050 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4] 2> 1037739 T3050 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> 1037740 T3050 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:61851/_/awholynewcollection_0_shard2_replica2/
[junit4:junit4] 2> 1037740 T3050 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0/leaders/shard2
[junit4:junit4] 2> ASYNC NEW_CORE C6326 name=awholynewcollection_0_shard2_replica1 org.apache.solr.core.SolrCore@39c239ac url=http://127.0.0.1:61842/_/awholynewcollection_0_shard2_replica1 node=127.0.0.1:61842__ C6326_STATE=coll:awholynewcollection_0 core:awholynewcollection_0_shard2_replica1 props:{shard=shard2, state=down, core=awholynewcollection_0_shard2_replica1, collection=awholynewcollection_0, node_name=127.0.0.1:61842__, base_url=http://127.0.0.1:61842/_}
[junit4:junit4] 2> 1037759 T3038 C6326 P61842 oasc.SolrCore.execute [awholynewcollection_0_shard2_replica1] webapp=/_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> ASYNC NEW_CORE C6327 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@49f6eb98 url=http://127.0.0.1:61842/_/nodes_used_collection_shard1_replica2 node=127.0.0.1:61842__ C6327_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:61842__, base_url=http://127.0.0.1:61842/_}
[junit4:junit4] 2> 1038180 T3071 C6327 P61842 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:61812/_/nodes_used_collection_shard1_replica1/ core=nodes_used_collection_shard1_replica2 - recoveringAfterStartup=true
[junit4:junit4] 2> 1038180 T3071 C6327 P61842 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard1_replica2 url=http://127.0.0.1:61842/_ START replicas=[http://127.0.0.1:61812/_/nodes_used_collection_shard1_replica1/] nUpdates=100
[junit4:junit4] 2> 1038181 T3071 C6327 P61842 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1038181 T3071 C6327 P61842 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 1038181 T3071 C6327 P61842 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 1038181 T3071 C6327 P61842 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 1038181 T3071 C6327 P61842 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1038182 T3071 C6327 P61842 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:61812/_/nodes_used_collection_shard1_replica1/. core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 1038182 T3071 C6327 P61842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C6328 name=nodes_used_collection_shard1_replica1 org.apache.solr.core.SolrCore@21ecd801 url=http://127.0.0.1:61812/_/nodes_used_collection_shard1_replica1 node=127.0.0.1:61812__ C6328_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:61812__, base_url=http://127.0.0.1:61812/_, leader=true}
[junit4:junit4] 2> 1038192 T2992 C6328 P61812 oasc.SolrCore.execute [nodes_used_collection_shard1_replica1] webapp=/_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 1038197 T2993 C6328 P61812 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1038202 T2993 C6328 P61812 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@646d3b1e lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ef6a5b6),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1038203 T2993 C6328 P61812 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1038203 T2993 C6328 P61812 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@646d3b1e lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ef6a5b6),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@646d3b1e lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ef6a5b6),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1038203 T2993 C6328 P61812 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1038204 T2993 C6328 P61812 oass.SolrIndexSearcher.<init> Opening Searcher@1e4f9758 realtime
[junit4:junit4] 2> 1038204 T2993 C6328 P61812 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1038205 T2993 C6328 P61812 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 8
[junit4:junit4] 2> 1038206 T3071 C6327 P61842 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1038206 T3071 C6327 P61842 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1038208 T2994 C6328 P61812 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1038208 T2994 C6328 P61812 oasc.SolrCore.execute [nodes_used_collection_shard1_replica1] webapp=/_ path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 1038209 T3071 C6327 P61842 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1038209 T3071 C6327 P61842 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1038209 T3071 C6327 P61842 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1038211 T2992 C6328 P61812 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> 1038212 T3071 C6327 P61842 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1038215 T3071 C6327 P61842 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\nodes_used_collection_shard1_replica2\data\index.20130528090633646
[junit4:junit4] 2> 1038215 T3071 C6327 P61842 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@3f3f8e47 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5502bb2a) fullCopy=false
[junit4:junit4] 2> 1038217 T2993 C6328 P61812 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> 1038218 T3071 C6327 P61842 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1038219 T3071 C6327 P61842 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1038219 T3071 C6327 P61842 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 1038222 T3071 C6327 P61842 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@43497848 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1466fd25),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@43497848 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1466fd25),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1038223 T3071 C6327 P61842 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1038223 T3071 C6327 P61842 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1038224 T3071 C6327 P61842 oass.SolrIndexSearcher.<init> Opening Searcher@64b91efd main
[junit4:junit4] 2> 1038236 T3067 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica2] Registered new searcher Searcher@64b91efd main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> ASYNC NEW_CORE C6329 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@49f6eb98 url=http://127.0.0.1:61842/_/nodes_used_collection_shard1_replica2 node=127.0.0.1:61842__ C6329_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:61842__, base_url=http://127.0.0.1:61842/_}
[junit4:junit4] 2> 1038238 T3071 C6329 P61842 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\nodes_used_collection_shard1_replica2\data\index.20130528090633646 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\nodes_used_collection_shard1_replica2\data\index.20130528090633646;done=true>>]
[junit4:junit4] 2> 1038238 T3071 C6329 P61842 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\nodes_used_collection_shard1_replica2\data\index.20130528090633646
[junit4:junit4] 2> 1038239 T3071 C6329 P61842 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1369724776265\nodes_used_collection_shard1_replica2\data\index.20130528090633646
[junit4:junit4] 2> 1038239 T3071 C6329 P61842 oasc.RecoveryStrategy.replay No replay needed. core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 1038239 T3071 C6329 P61842 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 1038239 T3071 C6329 P61842 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica2 state=active
[junit4:junit4] 2> 1038245 T3071 C6329 P61842 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 1038319 T2999 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1038320 T2999 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:61851___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:61851__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61851/_"}
[junit4:junit4] 2> 1038356 T2999 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:61842___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:61842__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:61842/_"}
[junit4:junit4] 2> 1038365 T3058 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> 1038366 T3016 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> 1038366 T3030 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> 1038367 T2998 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> 1038367 T3075 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> 1038367 T3073 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> 1038367 T3044 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> 1038367 T3003 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> 1038381 T3050 oasc.ZkController.register We are http://127.0.0.1:61851/_/awholynewcollection_0_shard2_replica2/ and leader is http://127.0.0.1:61851/_/awholynewcollection_0_shard2_replica2/
[junit4:junit4] 2> 1038381 T3050 oasc.ZkController.register No LogReplay needed for core=awholynewcollection_0_shard2_replica2 baseURL=http://127.0.0.1:61851/_
[junit4:junit4] 2> 1038383 T3050 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1038383 T3050 oasc.ZkController.publish publishing core=awholynewcollection_0_shard2_replica2 state=active
[junit4:junit4] 2> 1038386 T3050 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1038388 T3050 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={numShards=2&shard=shard2&name=awholynewcollection_0_shard2_replica2&action=CREATE&collection=awholynewcollection_0&wt=javabin&qt=/admin/cores&version=2} status=0 QTime=6234
[junit4:junit4] 2> 1038396 T3022 oasc.ZkController.register We are http://127.0.0.1:61833/_/awholynewcollection_0_shard1_replica1/ and leader is http://127.0.0.1:61812/_/awholynewcollection_0_shard1_replica2/
[junit4:junit4] 2> 1038396 T3022 oasc.ZkController.register No LogReplay needed for core=awholynewcollection_0_shard1_replica1 baseURL=http://127.0.0.1:61833/_
[junit4:junit4] 2> 1038396 T3022 oasc.ZkController.checkRecovery Core needs to recover:awholynewcollection_0_shard1_replica1
[junit4:junit4] 2> 1038397 T3022 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C6330 name=awholynewcollection_0_shard1_replica1 org.apache.solr.core.SolrCore@43a3c3fd url=http://127.0.0.1:61833/_/awholynewcollection_0_shard1_replica1 node=127.0.0.1:61833__ C6330_STATE=coll:awholynewcollection_0 core:awholynewcollection_0_shard1_replica1 props:{shard=shard1, state=down, core=awholynewcollection_0_shard1_replica1, collection=awholynewcollection_0, node_name=127.0.0.1:61833__, base_url=http://127.0.0.1:61833/_}
[junit4:junit4] 2> 1038398 T3086 C6330 P61833 oasc.RecoveryStrategy.run Starting recovery process. core=awholynewcollection_0_shard1_replica1 recoveringAfterStartup=true
[junit4:junit4] 2> 1038398 T3086 C6330 P61833 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1038399 T3086 C6330 P61833 oasc.ZkController.publish publishing core=awholynewcollection_0_shard1_replica1 state=recovering
[junit4:junit4] 2> 1038400 T3022 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1038401 T3086 C6330 P61833 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1038402 T3022 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={numShards=2&shard=shard1&name=awholynewcollection_0_shard1_replica1&action=CREATE&collection=awholynewcollection_0&wt=javabin&qt=/admin/cores&version=2} status=0 QTime=6250
[junit4:junit4] 2> 1038409 T2990 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:61833___awholynewcollection_0_shard1_replica1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1038433 T3037 oasc.ZkController.register We are http://127.0.0.1:61842/_/awholynewcollection_0_shard2_replica1/ and leader is http://127.0.0.1:61851/_/awholynewcollection_0_shard2_replica2/
[junit4:junit4] 2> 1038434 T3037 oasc.ZkController.register No LogReplay needed for core=awholynewcollection_0_shard2_replica1 baseURL=http://127.0.0.1:61842/_
[junit4:junit4] 2> 1038434 T3037 oasc.ZkController.checkRecovery Core needs to recover:awholynewcollection_0_shard2_replica1
[junit4:junit4] 2> 1038434 T3037 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C6331 name=awholynewcollection_0_shard2_replica1 org.apache.solr.core.SolrCore@39c239ac url=http://127.0.0.1:61842/_/awholynewcollection_0_shard2_replica1 node=127.0.0.1:61842__ C6331_STATE=coll:awholynewcollection_0 core:awholynewcollection_0_shard2_replica1 props:{shard=shard2, state=down, core=awholynewcollection_0_shard2_replica1, collection=awholynewcollection_0, node_name=127.0.0.1:61842__, base_url=http://127.0.0.1:61842/_}
[junit4:junit4] 2> 1038435 T3087 C6331 P61842 oasc.RecoveryStrategy.run Starting recovery process. core=awholynewcollection_0_shard2_replica1 recoveringAfterStartup=true
[junit4:junit4] 2> 1038435 T3087 C6331 P61842 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1038436 T3087 C6331 P61842 oasc.ZkController.publish publishing core=awholynewcollection_0_shard2_replica1 state=recovering
[junit4:junit4] 2> 1038436 T3037 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1038438 T2991 oasc.ZkController.register We are http://127.0.0.1:61812/_/awholynewcollection_0_shard1_replica2/ and leader is http://127.0.0.1:61812/_/awholynewcollection_0_shard1_replica2/
[junit4:junit4] 2> 1038438 T2991 oasc.ZkController.register No LogReplay needed for core=awholynewcollection_0_shard1_replica2 baseURL=http://127.0.0.1:61812/_
[junit4:junit4] 2> 1038438 T2991 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1038438 T2991 oasc.ZkController.publish publishing core=awholynewcollection_0_shard1_replica2 state=active
[junit4:junit4] 2> 1038439 T3087 C6331 P61842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1038439 T3037 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={numShards=2&shard=shard2&name=awholynewcollection_0_shard2_replica1&action=CREATE&collection=awholynewcollection_0&wt=javabin&qt=/admin/cores&version=2} status=0 QTime=6285
[junit4:junit4] 2> 1038444 T2991 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1038445 T2991 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={numShards=2&shard=shard1&name=awholynewcollection_0_shard1_replica2&action=CREATE&collection=awholynewcollection_0&wt=javabin&qt=/admin/cores&version=2} status=0 QTime=6293
[junit4:junit4] 2> 1038446 T3000 oasc.OverseerCollectionProcessor.createCollection Finished create command on all shards for collection: awholynewcollection_0
[junit4:junit4] 2> 1038447 T3054 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:61842___awholynewcollection_0_shard2_replica1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1038449 T2998 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work/qnr-0000000002 state: SyncConnected type NodeDataChanged
[junit4:junit4] 2> 1038454 T2998 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4] 2> 1038454 T3000 oasc.OverseerCollectionProcessor.run Overseer Collection Processor: Message id:/overseer/collection-queue-work/qn-0000000002 complete, response:{success={null={responseHeader={status=0,QTime=6234},core=awholynewcollection_0_shard2_replica2},null={responseHeader={status=0,QTime=6250},core=awholynewcollection_0_shard1_replica1},null={responseHeader={status=0,QTime=6285},core=awholynewcollection_0_shard2_replica1},null={responseHeader={status=0,QTime=6293},core=awholynewcollection_0_shard1_replica2}}}
[junit4:junit4] 2> 1038457 T2989 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/collections params={numShards=2&maxShardsPerNode=1&name=awholynewcollection_0&replicationFactor=2&action=CREATE&wt=javabin&version=2} status=0 QTime=6323
[junit4:junit4] 2> 1038462 T2976 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1038462 T2978 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13ee9f554e8000e, 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:662)
[junit4:junit4] 2>
[junit4:junit4] 2> 1038464 T2976 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1038469 T3089 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@337caeab name:ZooKeeperConnection Watcher:127.0.0.1:61805/solr got event WatchedEvent state:SyncCo
[...truncated too long message...]
s/awholynewcollection_1/leader_elect/shard2/election/89766282494738444-127.0.0.1:61851___awholynewcollection_1_shard2_replica5-n_0000000002 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard2/election/89766282494738440-127.0.0.1:61833___awholynewcollection_1_shard2_replica3-n_0000000001 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard2/election/89766282494738438-127.0.0.1:61824___awholynewcollection_1_shard2_replica2-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard2/election/89766282494738442-127.0.0.1:61842___awholynewcollection_1_shard2_replica4-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard3 (1)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard3/election (5)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard3/election/89766282494738444-127.0.0.1:61851___awholynewcollection_1_shard3_replica5-n_0000000004 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard3/election/89766282494738442-127.0.0.1:61842___awholynewcollection_1_shard3_replica4-n_0000000001 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard3/election/89766282494738438-127.0.0.1:61824___awholynewcollection_1_shard3_replica2-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard3/election/89766282494738435-127.0.0.1:61812___awholynewcollection_1_shard3_replica1-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard3/election/89766282494738440-127.0.0.1:61833___awholynewcollection_1_shard3_replica3-n_0000000002 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leaders (4)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"awholynewcollection_1_shard1_replica4",
[junit4:junit4] 1> "node_name":"127.0.0.1:61842__",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:61842/_"}
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leaders/shard4 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"awholynewcollection_1_shard4_replica3",
[junit4:junit4] 1> "node_name":"127.0.0.1:61833__",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:61833/_"}
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leaders/shard2 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"awholynewcollection_1_shard2_replica4",
[junit4:junit4] 1> "node_name":"127.0.0.1:61842__",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:61842/_"}
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leaders/shard3 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"awholynewcollection_1_shard3_replica2",
[junit4:junit4] 1> "node_name":"127.0.0.1:61824__",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:61824/_"}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (5)
[junit4:junit4] 1> /solr/overseer_elect/election/89766282494738438-127.0.0.1:61824__-n_0000000001 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89766282494738444-127.0.0.1:61851__-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89766282494738435-127.0.0.1:61812__-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89766282494738442-127.0.0.1:61842__-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89766282494738440-127.0.0.1:61833__-n_0000000002 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89766282494738435-127.0.0.1:61812__-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=188F903AD8C8D850 -Dtests.slow=true -Dtests.locale=fr_LU -Dtests.timezone=Europe/Warsaw -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 310s | CollectionsAPIDistributedZkTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: There are still nodes recoverying - waited for 230 seconds
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([188F903AD8C8D850:99691E22AF97B86C]: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:662)
[junit4:junit4] 2> 1323673 T2976 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 309620 T2975 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> NOTE: test params are: codec=Lucene40, sim=DefaultSimilarity, locale=fr_LU, timezone=Europe/Warsaw
[junit4:junit4] 2> NOTE: Windows 7 6.1 amd64/Sun Microsystems Inc. 1.6.0_45 (64-bit)/cpus=2,threads=1,free=48445784,total=144396288
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestRangeQuery, HighlighterConfigTest, TestSolrQueryParserResource, BadComponentTest, SliceStateUpdateTest, TestPseudoReturnFields, ShardRoutingCustomTest, TestSolrXMLSerializer, TermVectorComponentDistributedTest, TestDefaultSimilarityFactory, TestSolrXml, QueryElevationComponentTest, LoggingHandlerTest, IndexSchemaTest, LeaderElectionIntegrationTest, TestStressReorder, TestDistributedSearch, TestBinaryField, XmlUpdateRequestHandlerTest, CSVRequestHandlerTest, TestFuzzyAnalyzedSuggestions, SortByFunctionTest, TestPropInjectDefaults, OverseerTest, TestManagedSchemaFieldResource, BinaryUpdateRequestHandlerTest, TestBadConfig, TestSchemaNameResource, ChaosMonkeySafeLeaderTest, SolrPluginUtilsTest, TestFastLRUCache, PeerSyncTest, LukeRequestHandlerTest, TestPluginEnable, TestPerFieldSimilarity, TestSolrJ, TestCloudManagedSchemaAddField, TestUniqueKeyFieldResource, TestShardHandlerFactory, TestSolrQueryParserDefaultOperatorResource, TestCodecSupport, TestArbitraryIndexDir, FileUtilsTest, CachingDirectoryFactoryTest, TestCollationKeyRangeQueries, TestFieldTypeResource, TestFieldCollectionResource, TestSolrIndexConfig, SolrRequestParserTest, TestElisionMultitermQuery, TestRemoteStreaming, UnloadDistributedZkTest, TestJmxIntegration, PrimUtilsTest, RegexBoostProcessorTest, ZkControllerTest, SolrIndexSplitterTest, DocValuesTest, SpellCheckComponentTest, TestSearchPerf, TestWordDelimiterFilterFactory, StandardRequestHandlerTest, OpenCloseCoreStressTest, FastVectorHighlighterTest, DateFieldTest, SolrInfoMBeanTest, SOLR749Test, EchoParamsTest, TestFiltering, TestCSVLoader, PreAnalyzedUpdateProcessorTest, ResponseLogComponentTest, TestSchemaResource, SliceStateTest, BadIndexSchemaTest, RAMDirectoryFactoryTest, UpdateParamsTest, TestFastWriter, UUIDFieldTest, ShowFileRequestHandlerTest, TestSolrCoreProperties, TestUtils, TestLazyCores, TestPartialUpdateDeduplication, TestSchemaVersionResource, URLClassifyProcessorTest, TestFieldTypeCollectionResource, TestCoreContainer, SolrCmdDistributorTest, ExternalFileFieldSortTest, TestCollationField, DirectSolrSpellCheckerTest, TestSort, AutoCommitTest, TestRTGBase, ZkSolrClientTest, SuggesterFSTTest, TestTrie, TestPropInject, PolyFieldTest, BasicZkTest, TestFoldingMultitermQuery, TestAtomicUpdateErrorCases, CollectionsAPIDistributedZkTest]
[junit4:junit4] Completed in 310.24s, 1 test, 1 failure <<< FAILURES!
[...truncated 594 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:386: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:366: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build.xml:181: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\common-build.xml:437: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\lucene\common-build.xml:1243: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\lucene\common-build.xml:887: There were test failures: 296 suites, 1234 tests, 1 failure, 20 ignored (14 assumptions)
Total time: 70 minutes 2 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.6.0_45 -XX:+UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure