You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/07 14:20:56 UTC
[JENKINS] Lucene-Solr-4.x-MacOSX (64bit/jdk1.6.0) - Build # 526 -
Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-MacOSX/526/
Java: 64bit/jdk1.6.0 -XX:+UseCompressedOops -XX:+UseSerialGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testDistribSearch
Error Message:
There are still nodes recoverying - waited for 230 seconds
Stack Trace:
java.lang.AssertionError: There are still nodes recoverying - waited for 230 seconds
at __randomizedtesting.SeedInfo.seed([E60367ED123D8B46:67E5E9F56562EB7A]: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.GeneratedMethodAccessor40.invoke(Unknown Source)
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:680)
Build Log:
[...truncated 9015 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.CollectionsAPIDistributedZkTest
[junit4:junit4] 2> 2514613 T5150 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 2514620 T5150 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./solrtest-CollectionsAPIDistributedZkTest-1370605972888
[junit4:junit4] 2> 2514623 T5150 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 2514624 T5151 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 2514725 T5150 oasc.ZkTestServer.run start zk server on port:53140
[junit4:junit4] 2> 2514732 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2514747 T5157 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@34ac178b name:ZooKeeperConnection Watcher:127.0.0.1:53140 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2514748 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2514748 T5150 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 2514767 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2514769 T5159 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5486de21 name:ZooKeeperConnection Watcher:127.0.0.1:53140/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2514770 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2514770 T5150 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 2514777 T5150 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 2514785 T5150 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 2514791 T5150 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 2514806 T5150 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 2514808 T5150 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 2514819 T5150 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 2514820 T5150 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 2514829 T5150 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 2514830 T5150 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 2514840 T5150 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 2514841 T5150 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 2514850 T5150 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 2514851 T5150 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 2514859 T5150 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 2514860 T5150 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 2514879 T5150 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 2514881 T5150 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 2514898 T5150 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 2514899 T5150 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 2514907 T5150 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 2514908 T5150 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 2515609 T5150 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2515626 T5150 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53143
[junit4:junit4] 2> 2515627 T5150 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2515628 T5150 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2515628 T5150 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183
[junit4:junit4] 2> 2515629 T5150 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/solr.xml
[junit4:junit4] 2> 2515630 T5150 oasc.CoreContainer.<init> New CoreContainer 746093802
[junit4:junit4] 2> 2515630 T5150 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/'
[junit4:junit4] 2> 2515631 T5150 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/'
[junit4:junit4] 2> 2515808 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183
[junit4:junit4] 2> 2515810 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/collection1
[junit4:junit4] 2> 2515814 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/collection1/conf
[junit4:junit4] 2> 2516004 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/collection1/conf/xslt
[junit4:junit4] 2> 2516010 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/collection1/lib
[junit4:junit4] 2> 2516011 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/collection1/lib/classes
[junit4:junit4] 2> 2516014 T5150 oasc.SolrCoreDiscoverer.addCore Discovered properties file /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/conf/core.properties, adding to cores
[junit4:junit4] 2> 2516033 T5150 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 2516034 T5150 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2516034 T5150 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 2516035 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2516035 T5150 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2516036 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2516036 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2516037 T5150 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2516038 T5150 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2516038 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 2516089 T5150 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2516090 T5150 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53140/solr
[junit4:junit4] 2> 2516091 T5150 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2516092 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2516099 T5170 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@52ef4859 name:ZooKeeperConnection Watcher:127.0.0.1:53140 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2516100 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2516105 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2516153 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2516158 T5172 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6db99bc9 name:ZooKeeperConnection Watcher:127.0.0.1:53140/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2516158 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2516162 T5150 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 2516172 T5150 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 2516182 T5150 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 2516187 T5150 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53143_
[junit4:junit4] 2> 2516190 T5150 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53143_
[junit4:junit4] 2> 2516204 T5150 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 2516220 T5150 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 2516227 T5150 oasc.Overseer.start Overseer (id=89824033040171011-127.0.0.1:53143_-n_0000000000) starting
[junit4:junit4] 2> 2516240 T5150 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 2516251 T5174 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 2516254 T5150 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 2516263 T5150 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 2516274 T5150 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2516283 T5173 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 2516288 T5150 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 2516289 T5150 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2516290 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2516335 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 2516340 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2516345 T5177 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7f7718f0 name:ZooKeeperConnection Watcher:127.0.0.1:53140/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2516346 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2516349 T5150 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2516356 T5150 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 2516930 T5150 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2516946 T5150 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53147
[junit4:junit4] 2> 2516957 T5150 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2516958 T5150 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2516958 T5150 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622
[junit4:junit4] 2> 2516959 T5150 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/solr.xml
[junit4:junit4] 2> 2516959 T5150 oasc.CoreContainer.<init> New CoreContainer 1908067630
[junit4:junit4] 2> 2516960 T5150 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/'
[junit4:junit4] 2> 2516960 T5150 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/'
[junit4:junit4] 2> 2517149 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622
[junit4:junit4] 2> 2517151 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/collection1
[junit4:junit4] 2> 2517155 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/collection1/conf
[junit4:junit4] 2> 2517344 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/collection1/conf/xslt
[junit4:junit4] 2> 2517349 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/collection1/lib
[junit4:junit4] 2> 2517351 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/collection1/lib/classes
[junit4:junit4] 2> 2517354 T5150 oasc.SolrCoreDiscoverer.addCore Discovered properties file /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/conf/core.properties, adding to cores
[junit4:junit4] 2> 2517371 T5150 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 2517372 T5150 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2517373 T5150 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 2517373 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2517374 T5150 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2517374 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2517375 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2517375 T5150 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2517376 T5150 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2517376 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 2517432 T5150 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2517433 T5150 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53140/solr
[junit4:junit4] 2> 2517434 T5150 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2517438 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2517444 T5188 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2b042086 name:ZooKeeperConnection Watcher:127.0.0.1:53140 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2517446 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2517451 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2517517 T5190 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4779ca4 name:ZooKeeperConnection Watcher:127.0.0.1:53140/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2517517 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2517518 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2517532 T5150 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2518546 T5150 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53147_
[junit4:junit4] 2> 2518552 T5150 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53147_
[junit4:junit4] 2> 2518559 T5177 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2518560 T5190 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2518560 T5172 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2518570 T5150 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 2518571 T5150 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2518572 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2519201 T5150 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2519215 T5150 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53150
[junit4:junit4] 2> 2519229 T5150 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2519230 T5150 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2519231 T5150 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885
[junit4:junit4] 2> 2519231 T5150 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/solr.xml
[junit4:junit4] 2> 2519232 T5150 oasc.CoreContainer.<init> New CoreContainer 2073243910
[junit4:junit4] 2> 2519233 T5150 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/'
[junit4:junit4] 2> 2519233 T5150 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/'
[junit4:junit4] 2> 2519397 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885
[junit4:junit4] 2> 2519403 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/collection1
[junit4:junit4] 2> 2519407 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/collection1/conf
[junit4:junit4] 2> 2519583 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/collection1/conf/xslt
[junit4:junit4] 2> 2519587 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/collection1/lib
[junit4:junit4] 2> 2519589 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/collection1/lib/classes
[junit4:junit4] 2> 2519592 T5150 oasc.SolrCoreDiscoverer.addCore Discovered properties file /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/conf/core.properties, adding to cores
[junit4:junit4] 2> 2519613 T5150 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 2519614 T5150 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2519615 T5150 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 2519615 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2519616 T5150 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2519616 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2519617 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2519617 T5150 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2519618 T5150 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2519619 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 2519677 T5150 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2519678 T5150 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53140/solr
[junit4:junit4] 2> 2519678 T5150 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2519680 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2519688 T5202 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19f1bbc4 name:ZooKeeperConnection Watcher:127.0.0.1:53140 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2519689 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2519694 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2519739 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2519745 T5204 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5068d4f2 name:ZooKeeperConnection Watcher:127.0.0.1:53140/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2519745 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2519759 T5150 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2520768 T5150 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53150_
[junit4:junit4] 2> 2520771 T5150 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53150_
[junit4:junit4] 2> 2520778 T5190 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2520783 T5204 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2520791 T5177 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2520791 T5172 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2520822 T5150 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 2520825 T5150 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2520828 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2521491 T5150 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2521513 T5150 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53153
[junit4:junit4] 2> 2521516 T5150 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2521516 T5150 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2521517 T5150 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138
[junit4:junit4] 2> 2521517 T5150 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/solr.xml
[junit4:junit4] 2> 2521518 T5150 oasc.CoreContainer.<init> New CoreContainer 223879315
[junit4:junit4] 2> 2521519 T5150 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/'
[junit4:junit4] 2> 2521519 T5150 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/'
[junit4:junit4] 2> 2521687 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138
[junit4:junit4] 2> 2521689 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/collection1
[junit4:junit4] 2> 2521690 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/collection1/conf
[junit4:junit4] 2> 2521870 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/collection1/conf/xslt
[junit4:junit4] 2> 2521876 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/collection1/lib
[junit4:junit4] 2> 2521879 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/collection1/lib/classes
[junit4:junit4] 2> 2521883 T5150 oasc.SolrCoreDiscoverer.addCore Discovered properties file /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/conf/core.properties, adding to cores
[junit4:junit4] 2> 2521900 T5150 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 2521901 T5150 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2521903 T5150 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 2521905 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2521908 T5150 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2521909 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2521910 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2521911 T5150 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2521911 T5150 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2521912 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 2521961 T5150 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2521962 T5150 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53140/solr
[junit4:junit4] 2> 2521962 T5150 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2521965 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2521975 T5216 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@73fb51f0 name:ZooKeeperConnection Watcher:127.0.0.1:53140 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2521979 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2521985 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2522038 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2522050 T5218 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@346ab6ce name:ZooKeeperConnection Watcher:127.0.0.1:53140/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2522051 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2522061 T5150 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2523072 T5150 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53153_
[junit4:junit4] 2> 2523080 T5150 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53153_
[junit4:junit4] 2> 2523093 T5218 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2523094 T5190 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2523107 T5150 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 2523111 T5150 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2523114 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2523115 T5204 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2523119 T5177 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2523119 T5172 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2524227 T5150 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2524261 T5150 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53156
[junit4:junit4] 2> 2524264 T5150 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2524264 T5150 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2524268 T5150 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430
[junit4:junit4] 2> 2524269 T5150 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/solr.xml
[junit4:junit4] 2> 2524269 T5150 oasc.CoreContainer.<init> New CoreContainer 741018778
[junit4:junit4] 2> 2524270 T5150 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/'
[junit4:junit4] 2> 2524271 T5150 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/'
[junit4:junit4] 2> 2524483 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430
[junit4:junit4] 2> 2524484 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/collection1
[junit4:junit4] 2> 2524486 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/collection1/conf
[junit4:junit4] 2> 2524704 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/collection1/conf/xslt
[junit4:junit4] 2> 2524709 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/collection1/lib
[junit4:junit4] 2> 2524711 T5150 oasc.SolrCoreDiscoverer.walkFromHere Looking for cores in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/collection1/lib/classes
[junit4:junit4] 2> 2524714 T5150 oasc.SolrCoreDiscoverer.addCore Discovered properties file /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/conf/core.properties, adding to cores
[junit4:junit4] 2> 2524733 T5150 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4] 2> 2524733 T5150 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2524734 T5150 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4] 2> 2524734 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2524735 T5150 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2524736 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2524736 T5150 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2524737 T5150 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2524737 T5150 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2524738 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4] 2> 2524797 T5150 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2524798 T5150 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53140/solr
[junit4:junit4] 2> 2524799 T5150 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2524805 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2524853 T5230 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@406ad12e name:ZooKeeperConnection Watcher:127.0.0.1:53140 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2524855 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2524870 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2524920 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2524925 T5232 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@26c85827 name:ZooKeeperConnection Watcher:127.0.0.1:53140/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2524925 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2524943 T5150 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2525953 T5150 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53156_
[junit4:junit4] 2> 2525956 T5150 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53156_
[junit4:junit4] 2> 2525968 T5204 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2525969 T5177 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2525970 T5232 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2525970 T5172 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2525971 T5218 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2525971 T5190 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2525984 T5150 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 2525985 T5150 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2525985 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2526046 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2526110 T5185 oasha.CollectionsHandler.handleCreateAction Creating Collection : numShards=2&name=nodes_used_collection&replicationFactor=2&action=CREATE&wt=javabin&version=2
[junit4:junit4] 2> 2526113 T5172 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4] 2> 2526118 T5174 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> 2526118 T5174 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:53153_
[junit4:junit4] 2> 2526121 T5174 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:53150_
[junit4:junit4] 2> 2526124 T5174 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:53156_
[junit4:junit4] 2> 2526129 T5174 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:53143_
[junit4:junit4] 2> 2526149 T5199 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard1_replica2' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 2526151 T5199 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4] 2> 2526152 T5227 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard2_replica1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 2526153 T5227 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4] 2> 2526152 T5164 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard2_replica2' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 2526154 T5164 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4] 2> 2526153 T5214 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard1_replica1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 2526155 T5214 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4:junit4] 2> 2526158 T5227 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4] 2> 2526158 T5164 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4] 2> 2526161 T5164 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 2526159 T5214 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4] 2> 2526162 T5214 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 2526158 T5199 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4:junit4] 2> 2526173 T5199 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 2526158 T5227 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 2526176 T5164 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 2526177 T5164 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4] 2> 2526177 T5214 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 2526178 T5214 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4] 2> 2526180 T5199 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 2526181 T5199 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4] 2> 2526181 T5227 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 2526182 T5227 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4:junit4] 2> 2526189 T5164 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4] 2> 2526192 T5227 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4] 2> 2526193 T5214 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4] 2> 2526194 T5199 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4:junit4] 2> 2526198 T5164 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/nodes_used_collection_shard2_replica2/'
[junit4:junit4] 2> 2526199 T5227 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/nodes_used_collection_shard2_replica1/'
[junit4:junit4] 2> 2526210 T5214 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/nodes_used_collection_shard1_replica1/'
[junit4:junit4] 2> 2526218 T5199 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/nodes_used_collection_shard1_replica2/'
[junit4:junit4] 2> 2526487 T5227 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2526567 T5164 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2526571 T5214 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2526625 T5199 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2526899 T5227 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2526918 T5227 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2526942 T5164 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2526952 T5227 oass.IndexSchema.readSchema [nodes_used_collection_shard2_replica1] Schema name=test
[junit4:junit4] 2> 2526953 T5214 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2526963 T5164 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2526998 T5164 oass.IndexSchema.readSchema [nodes_used_collection_shard2_replica2] Schema name=test
[junit4:junit4] 2> 2527005 T5214 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2527040 T5214 oass.IndexSchema.readSchema [nodes_used_collection_shard1_replica1] Schema name=test
[junit4:junit4] 2> 2527111 T5199 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2527129 T5199 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2527140 T5199 oass.IndexSchema.readSchema [nodes_used_collection_shard1_replica2] Schema name=test
[junit4:junit4] 2> 2531273 T5214 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2531382 T5214 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2531399 T5214 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2531446 T5164 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2531478 T5164 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2531507 T5214 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2531517 T5164 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2531528 T5214 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2531551 T5227 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2531561 T5214 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2531565 T5227 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2531569 T5199 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2531571 T5214 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2531571 T5214 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2531572 T5214 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2531575 T5214 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2531575 T5214 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2531576 T5214 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2531576 T5214 oasc.SolrCore.<init> [nodes_used_collection_shard1_replica1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/nodes_used_collection_shard1_replica1/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/nodes_used_collection_shard1_replica1/data/
[junit4:junit4] 2> 2531577 T5214 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bf47ae8
[junit4:junit4] 2> 2531578 T5214 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2531584 T5214 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/nodes_used_collection_shard1_replica1/data
[junit4:junit4] 2> 2531587 T5214 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/nodes_used_collection_shard1_replica1/data/index/
[junit4:junit4] 2> 2531588 T5214 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard1_replica1] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/nodes_used_collection_shard1_replica1/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2531590 T5227 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2531590 T5214 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/nodes_used_collection_shard1_replica1/data/index
[junit4:junit4] 2> 2531616 T5199 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2531622 T5214 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@201ce579 lockFactory=org.apache.lucene.store.NativeFSLockFactory@246e9059),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2531623 T5214 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2531623 T5199 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2531628 T5164 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2531638 T5214 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2531645 T5214 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2531646 T5214 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2531648 T5214 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2531648 T5214 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2531649 T5214 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2531649 T5214 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2531651 T5214 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2531652 T5214 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2531660 T5164 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2531675 T5214 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2531688 T5164 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2531695 T5164 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2531714 T5164 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2531717 T5164 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2531722 T5214 oass.SolrIndexSearcher.<init> Opening Searcher@316233ff main
[junit4:junit4] 2> 2531723 T5214 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/nodes_used_collection_shard1_replica1/data/tlog
[junit4:junit4] 2> 2531727 T5214 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2531727 T5214 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2531732 T5164 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2531732 T5164 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2531733 T5164 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2531734 T5164 oasc.SolrCore.<init> [nodes_used_collection_shard2_replica2] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/nodes_used_collection_shard2_replica2/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/nodes_used_collection_shard2_replica2/data/
[junit4:junit4] 2> 2531734 T5164 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bf47ae8
[junit4:junit4] 2> 2531759 T5238 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica1] Registered new searcher Searcher@316233ff main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2531761 T5164 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2531763 T5164 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/nodes_used_collection_shard2_replica2/data
[junit4:junit4] 2> 2531763 T5164 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/nodes_used_collection_shard2_replica2/data/index/
[junit4:junit4] 2> 2531764 T5164 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard2_replica2] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/nodes_used_collection_shard2_replica2/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2531765 T5214 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica1 state=down
[junit4:junit4] 2> 2531769 T5164 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/nodes_used_collection_shard2_replica2/data/index
[junit4:junit4] 2> 2531787 T5164 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@38a34175 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7cbcf28),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2531788 T5164 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2531788 T5227 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2531795 T5164 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2531795 T5164 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2531796 T5164 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2531802 T5164 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2531803 T5164 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2531803 T5164 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2531804 T5164 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2531805 T5164 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2531806 T5164 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2531824 T5164 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2531829 T5227 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2531832 T5199 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2531841 T5227 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2531842 T5199 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2531846 T5227 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2531846 T5227 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2531847 T5227 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2531853 T5199 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2531859 T5199 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2531859 T5199 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2531860 T5199 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2531859 T5227 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2531862 T5227 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2531863 T5227 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2531864 T5227 oasc.SolrCore.<init> [nodes_used_collection_shard2_replica1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/nodes_used_collection_shard2_replica1/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/nodes_used_collection_shard2_replica1/data/
[junit4:junit4] 2> 2531866 T5227 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bf47ae8
[junit4:junit4] 2> 2531866 T5199 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2531868 T5199 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2531868 T5199 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2531869 T5199 oasc.SolrCore.<init> [nodes_used_collection_shard1_replica2] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/nodes_used_collection_shard1_replica2/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/nodes_used_collection_shard1_replica2/data/
[junit4:junit4] 2> 2531869 T5199 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bf47ae8
[junit4:junit4] 2> 2531871 T5199 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2531872 T5199 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/nodes_used_collection_shard1_replica2/data
[junit4:junit4] 2> 2531873 T5199 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/nodes_used_collection_shard1_replica2/data/index/
[junit4:junit4] 2> 2531873 T5199 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard1_replica2] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/nodes_used_collection_shard1_replica2/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2531874 T5164 oass.SolrIndexSearcher.<init> Opening Searcher@5075cf64 main
[junit4:junit4] 2> 2531875 T5164 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/nodes_used_collection_shard2_replica2/data/tlog
[junit4:junit4] 2> 2531867 T5227 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2531886 T5227 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/nodes_used_collection_shard2_replica1/data
[junit4:junit4] 2> 2531888 T5227 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/nodes_used_collection_shard2_replica1/data/index/
[junit4:junit4] 2> 2531888 T5227 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard2_replica1] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/nodes_used_collection_shard2_replica1/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2531890 T5227 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/nodes_used_collection_shard2_replica1/data/index
[junit4:junit4] 2> 2531877 T5164 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2531892 T5164 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2531876 T5199 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/nodes_used_collection_shard1_replica2/data/index
[junit4:junit4] 2> 2531905 T5239 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica2] Registered new searcher Searcher@5075cf64 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2531908 T5199 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6ac3b137 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6682d780),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2531909 T5199 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2531912 T5164 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica2 state=down
[junit4:junit4] 2> 2531912 T5227 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c41699c lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e89d0ef),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2531913 T5227 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2531917 T5199 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2531917 T5199 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2531919 T5199 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2531921 T5199 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2531922 T5199 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2531923 T5199 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2531923 T5199 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2531924 T5199 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2531925 T5199 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2531925 T5227 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2531939 T5227 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2531940 T5227 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2531941 T5227 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2531941 T5227 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2531942 T5227 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2531943 T5227 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2531944 T5227 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2531944 T5227 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2531953 T5227 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2531962 T5199 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2531982 T5227 oass.SolrIndexSearcher.<init> Opening Searcher@31ded166 main
[junit4:junit4] 2> 2531984 T5227 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/nodes_used_collection_shard2_replica1/data/tlog
[junit4:junit4] 2> 2531987 T5227 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2531998 T5227 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2532003 T5199 oass.SolrIndexSearcher.<init> Opening Searcher@84fe79 main
[junit4:junit4] 2> 2532004 T5199 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/nodes_used_collection_shard1_replica2/data/tlog
[junit4:junit4] 2> 2532007 T5199 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2532008 T5199 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2532009 T5240 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica1] Registered new searcher Searcher@31ded166 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2532018 T5227 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica1 state=down
[junit4:junit4] 2> 2532035 T5241 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica2] Registered new searcher Searcher@84fe79 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2532039 T5199 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica2 state=down
[junit4:junit4] 2> 2532910 T5173 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2532912 T5173 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:53153_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53153"}
[junit4:junit4] 2> 2532912 T5173 oasc.Overseer$ClusterStateUpdater.createCollection Create collection nodes_used_collection with numShards 2
[junit4:junit4] 2> 2532922 T5173 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:53143_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53143"}
[junit4:junit4] 2> 2532932 T5173 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:53156_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53156"}
[junit4:junit4] 2> 2532949 T5173 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:53150_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53150"}
[junit4:junit4] 2> 2532964 T5232 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> 2532964 T5190 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> 2532969 T5204 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> 2532972 T5177 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> 2532973 T5172 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> 2532975 T5218 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> 2533039 T5227 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard2_replica1
[junit4:junit4] 2> 2533040 T5227 oasc.ZkController.register Register replica - core:nodes_used_collection_shard2_replica1 address:http://127.0.0.1:53156 collection:nodes_used_collection shard:shard2
[junit4:junit4] 2> 2533041 T5227 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leader_elect/shard2/election
[junit4:junit4] 2> 2533052 T5199 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard1_replica2
[junit4:junit4] 2> 2533053 T5199 oasc.ZkController.register Register replica - core:nodes_used_collection_shard1_replica2 address:http://127.0.0.1:53150 collection:nodes_used_collection shard:shard1
[junit4:junit4] 2> 2533057 T5199 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2533067 T5227 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2533081 T5227 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Waiting until we see more replicas up: total=2 found=1 timeoutin=179999
[junit4:junit4] 2> 2533088 T5199 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2533096 T5199 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Waiting until we see more replicas up: total=2 found=1 timeoutin=179999
[junit4:junit4] 2> 2533771 T5214 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 2533772 T5214 oasc.ZkController.register Register replica - core:nodes_used_collection_shard1_replica1 address:http://127.0.0.1:53153 collection:nodes_used_collection shard:shard1
[junit4:junit4] 2> 2533930 T5164 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 2533931 T5164 oasc.ZkController.register Register replica - core:nodes_used_collection_shard2_replica2 address:http://127.0.0.1:53143 collection:nodes_used_collection shard:shard2
[junit4:junit4] 2> 2534090 T5227 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2534091 T5227 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2534091 T5227 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53156/nodes_used_collection_shard2_replica1/
[junit4:junit4] 2> 2534092 T5227 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard2_replica1 url=http://127.0.0.1:53156 START replicas=[http://127.0.0.1:53143/nodes_used_collection_shard2_replica2/] nUpdates=100
[junit4:junit4] 2> 2534093 T5227 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard2_replica1 url=http://127.0.0.1:53156 DONE. We have no versions. sync failed.
[junit4:junit4] 2> 2534094 T5227 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4] 2> 2534094 T5227 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> 2534095 T5227 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53156/nodes_used_collection_shard2_replica1/
[junit4:junit4] 2> 2534095 T5227 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leaders/shard2
[junit4:junit4] 2> 2534116 T5199 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2534117 T5199 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2534117 T5199 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53150/nodes_used_collection_shard1_replica2/
[junit4:junit4] 2> 2534118 T5199 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard1_replica2 url=http://127.0.0.1:53150 START replicas=[http://127.0.0.1:53153/nodes_used_collection_shard1_replica1/] nUpdates=100
[junit4:junit4] 2> 2534119 T5199 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard1_replica2 url=http://127.0.0.1:53150 DONE. We have no versions. sync failed.
[junit4:junit4] 2> 2534119 T5199 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4] 2> 2534120 T5199 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> 2534121 T5199 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53150/nodes_used_collection_shard1_replica2/
[junit4:junit4] 2> 2534121 T5199 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leaders/shard1
[junit4:junit4] 2> ASYNC NEW_CORE C3190 name=nodes_used_collection_shard2_replica2 org.apache.solr.core.SolrCore@41e4e67d url=http://127.0.0.1:53143/nodes_used_collection_shard2_replica2 node=127.0.0.1:53143_ C3190_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:53143_, base_url=http://127.0.0.1:53143}
[junit4:junit4] 2> 2534140 T5165 C3190 P53143 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=11
[junit4:junit4] 2> ASYNC NEW_CORE C3191 name=nodes_used_collection_shard1_replica1 org.apache.solr.core.SolrCore@5c441feb url=http://127.0.0.1:53153/nodes_used_collection_shard1_replica1 node=127.0.0.1:53153_ C3191_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica1 props:{shard=shard1, state=down, core=nodes_used_collection_shard1_replica1, collection=nodes_used_collection, node_name=127.0.0.1:53153_, base_url=http://127.0.0.1:53153}
[junit4:junit4] 2> 2534148 T5211 C3191 P53153 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> 2534510 T5173 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2534554 T5232 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> 2534554 T5172 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> 2534561 T5190 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> 2534562 T5218 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> 2534562 T5204 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> 2534563 T5177 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> 2534586 T5227 oasc.ZkController.register We are http://127.0.0.1:53156/nodes_used_collection_shard2_replica1/ and leader is http://127.0.0.1:53156/nodes_used_collection_shard2_replica1/
[junit4:junit4] 2> 2534586 T5227 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard2_replica1 baseURL=http://127.0.0.1:53156
[junit4:junit4] 2> 2534587 T5227 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2534588 T5227 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica1 state=active
[junit4:junit4] 2> 2534592 T5227 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2534599 T5227 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=8447
[junit4:junit4] 2> 2534633 T5199 oasc.ZkController.register We are http://127.0.0.1:53150/nodes_used_collection_shard1_replica2/ and leader is http://127.0.0.1:53150/nodes_used_collection_shard1_replica2/
[junit4:junit4] 2> 2534636 T5199 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard1_replica2 baseURL=http://127.0.0.1:53150
[junit4:junit4] 2> 2534637 T5199 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2534639 T5199 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica2 state=active
[junit4:junit4] 2> 2534644 T5199 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2534647 T5199 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=8498
[junit4:junit4] 2> 2534784 T5214 oasc.ZkController.register We are http://127.0.0.1:53153/nodes_used_collection_shard1_replica1/ and leader is http://127.0.0.1:53150/nodes_used_collection_shard1_replica2/
[junit4:junit4] 2> 2534785 T5214 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard1_replica1 baseURL=http://127.0.0.1:53153
[junit4:junit4] 2> 2534786 T5214 oasc.ZkController.checkRecovery Core needs to recover:nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 2534786 T5214 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> 2534787 T5244 C3191 P53153 oasc.RecoveryStrategy.run Starting recovery process. core=nodes_used_collection_shard1_replica1 recoveringAfterStartup=true
[junit4:junit4] 2> 2534788 T5244 C3191 P53153 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 2534788 T5214 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2534791 T5244 C3191 P53153 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica1 state=recovering
[junit4:junit4] 2> 2534792 T5214 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=8639
[junit4:junit4] 2> 2534794 T5244 C3191 P53153 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2534848 T5200 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:53153__nodes_used_collection_shard1_replica1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 2534941 T5164 oasc.ZkController.register We are http://127.0.0.1:53143/nodes_used_collection_shard2_replica2/ and leader is http://127.0.0.1:53156/nodes_used_collection_shard2_replica1/
[junit4:junit4] 2> 2534942 T5164 oasc.ZkController.register No LogReplay needed for core=nodes_used_collection_shard2_replica2 baseURL=http://127.0.0.1:53143
[junit4:junit4] 2> 2534943 T5164 oasc.ZkController.checkRecovery Core needs to recover:nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 2534943 T5164 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> 2534970 T5245 C3190 P53143 oasc.RecoveryStrategy.run Starting recovery process. core=nodes_used_collection_shard2_replica2 recoveringAfterStartup=true
[junit4:junit4] 2> 2534972 T5245 C3190 P53143 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 2534975 T5245 C3190 P53143 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica2 state=recovering
[junit4:junit4] 2> 2534980 T5245 C3190 P53143 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2534982 T5164 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2534984 T5164 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=8832
[junit4:junit4] 2> 2534987 T5174 oasc.OverseerCollectionProcessor.createCollection Finished create command on all shards for collection: nodes_used_collection
[junit4:junit4] 2> 2535023 T5190 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work/qnr-0000000000 state: SyncConnected type NodeDataChanged
[junit4:junit4] 2> 2535035 T5185 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=8926
[junit4:junit4] 2> 2535042 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 2535045 T5228 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:53143__nodes_used_collection_shard2_replica2, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 2535045 T5172 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4] 2> 2535055 T5174 oasc.OverseerCollectionProcessor.run Overseer Collection Processor: Message id:/overseer/collection-queue-work/qn-0000000000 complete, response:{success={null={responseHeader={status=0,QTime=8447},core=nodes_used_collection_shard2_replica1},null={responseHeader={status=0,QTime=8498},core=nodes_used_collection_shard1_replica2},null={responseHeader={status=0,QTime=8639},core=nodes_used_collection_shard1_replica1},null={responseHeader={status=0,QTime=8832},core=nodes_used_collection_shard2_replica2}}}
[junit4:junit4] 2> 2535055 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2535063 T5247 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7da6dcca name:ZooKeeperConnection Watcher:127.0.0.1:53140/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2535063 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2535066 T5150 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2535074 T5150 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 2535081 T5150 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2535085 T5249 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b42a5ca name:ZooKeeperConnection Watcher:127.0.0.1:53140/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2535086 T5150 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2535089 T5150 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2535146 T5210 oasha.CollectionsHandler.handleCreateAction Creating Collection : numShards=2&maxShardsPerNode=3&name=awholynewcollection_0&replicationFactor=5&action=CREATE&wt=javabin&version=2
[junit4:junit4] 2> 2535153 T5172 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4] 2> 2535156 T5174 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":"3",
[junit4:junit4] 2> "createNodeSet":null,
[junit4:junit4] 2> "name":"awholynewcollection_0",
[junit4:junit4] 2> "replicationFactor":"5"}
[junit4:junit4] 2> 2535156 T5174 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica1 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:53156_
[junit4:junit4] 2> 2535156 T5174 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica2 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:53150_
[junit4:junit4] 2> 2535156 T5174 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica3 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:53147_
[junit4:junit4] 2> 2535157 T5174 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica4 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:53153_
[junit4:junit4] 2> 2535160 T5174 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard1_replica5 as part of slice shard1 of collection awholynewcollection_0 on 127.0.0.1:53143_
[junit4:junit4] 2> 2535164 T5211 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard1_replica4' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/awholynewcollection_0_shard1_replica4
[junit4:junit4] 2> 2535166 T5211 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 2535162 T5195 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard1_replica2' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/awholynewcollection_0_shard1_replica2
[junit4:junit4] 2> 2535167 T5195 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 2535169 T5223 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard1_replica1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/awholynewcollection_0_shard1_replica1
[junit4:junit4] 2> 2535169 T5223 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 2535171 T5223 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 2535186 T5223 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 2535185 T5186 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard1_replica3' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard1_replica3
[junit4:junit4] 2> 2535187 T5186 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 2535185 T5168 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard1_replica5' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard1_replica5
[junit4:junit4] 2> 2535188 T5168 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 2535174 T5174 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard2_replica1 as part of slice shard2 of collection awholynewcollection_0 on 127.0.0.1:53156_
[junit4:junit4] 2> 2535190 T5186 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 2535190 T5186 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 2535187 T5211 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 2535191 T5211 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 2535186 T5195 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 2535192 T5195 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 2535192 T5168 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 2535193 T5168 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 2535193 T5223 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 2535195 T5223 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 2535195 T5174 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard2_replica2 as part of slice shard2 of collection awholynewcollection_0 on 127.0.0.1:53150_
[junit4:junit4] 2> 2535206 T5224 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard2_replica1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/awholynewcollection_0_shard2_replica1
[junit4:junit4] 2> 2535208 T5224 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 2535203 T5186 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 2535209 T5186 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 2535211 T5211 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 2535211 T5211 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 2535218 T5186 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 2535222 T5186 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard1_replica3/'
[junit4:junit4] 2> 2535231 T5174 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard2_replica3 as part of slice shard2 of collection awholynewcollection_0 on 127.0.0.1:53147_
[junit4:junit4] 2> 2535246 T5224 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:awholynewcollection_0
[junit4:junit4] 2> 2535246 T5224 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 2535258 T5195 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 2535267 T5195 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 2535252 T5174 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard2_replica4 as part of slice shard2 of collection awholynewcollection_0 on 127.0.0.1:53153_
[junit4:junit4] 2> 2535267 T5168 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 2535272 T5168 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 2535266 T5181 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard2_replica3' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard2_replica3
[junit4:junit4] 2> 2535274 T5181 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 2535285 T5212 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard2_replica4' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/awholynewcollection_0_shard2_replica4
[junit4:junit4] 2> 2535286 T5212 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 2535287 T5174 oasc.OverseerCollectionProcessor.createCollection Creating shard awholynewcollection_0_shard2_replica5 as part of slice shard2 of collection awholynewcollection_0 on 127.0.0.1:53143_
[junit4:junit4] 2> 2535304 T5163 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard2_replica5' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard2_replica5
[junit4:junit4] 2> 2535305 T5163 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 2535306 T5197 oasc.CoreContainer.create Creating SolrCore 'awholynewcollection_0_shard2_replica2' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/awholynewcollection_0_shard2_replica2
[junit4:junit4] 2> 2535307 T5197 oasc.ZkController.createCollectionZkNode Check for collection zkNode:awholynewcollection_0
[junit4:junit4] 2> 2535324 T5181 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2535326 T5181 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 2535332 T5212 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2535333 T5212 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 2535333 T5197 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2535335 T5197 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 2535337 T5223 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 2535342 T5163 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2535343 T5163 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 2535343 T5224 oascc.SolrZkClient.makePath makePath: /collections/awholynewcollection_0
[junit4:junit4] 2> 2535348 T5211 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 2535351 T5195 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 2535352 T5212 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/awholynewcollection_0_shard2_replica4/'
[junit4:junit4] 2> 2535354 T5223 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/awholynewcollection_0_shard1_replica1/'
[junit4:junit4] 2> 2535365 T5168 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 2535368 T5197 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/awholynewcollection_0_shard2_replica2/'
[junit4:junit4] 2> 2535369 T5181 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard2_replica3/'
[junit4:junit4] 2> 2535371 T5163 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard2_replica5/'
[junit4:junit4] 2> 2535376 T5195 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/awholynewcollection_0_shard1_replica2/'
[junit4:junit4] 2> 2535378 T5211 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/awholynewcollection_0_shard1_replica4/'
[junit4:junit4] 2> 2535392 T5224 oasc.ZkController.readConfigName Load collection config from:/collections/awholynewcollection_0
[junit4:junit4] 2> 2535418 T5168 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard1_replica5/'
[junit4:junit4] 2> 2535427 T5224 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1370605981430/awholynewcollection_0_shard2_replica1/'
[junit4:junit4] 2> 2536008 T5163 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2536038 T5186 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2536054 T5168 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2536063 T5195 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2536104 T5173 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2536106 T5173 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53156__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:53156_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53156"}
[junit4:junit4] 2> 2536117 T5173 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53150__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:53150_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53150"}
[junit4:junit4] 2> 2536130 T5173 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53153__nodes_used_collection_shard1_replica1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"nodes_used_collection_shard1_replica1",
[junit4:junit4] 2> "collection":"nodes_used_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53153_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53153"}
[junit4:junit4] 2> 2536149 T5173 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53143__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:53143_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53143"}
[junit4:junit4] 2> 2536161 T5177 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> 2536161 T5218 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> 2536161 T5232 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> 2536162 T5190 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> 2536162 T5249 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> 2536162 T5247 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> 2536161 T5204 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> 2536168 T5172 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> 2536175 T5197 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2536203 T5212 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2536232 T5223 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2536247 T5181 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2536272 T5224 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2536305 T5211 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2536852 T5197 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2536853 T5200 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:53153__nodes_used_collection_shard1_replica1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 2536854 T5200 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:53153__nodes_used_collection_shard1_replica1&state=recovering&nodeName=127.0.0.1:53153_&action=PREPRECOVERY&checkLive=true&core=nodes_used_collection_shard1_replica2&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2006
[junit4:junit4] 2> 2536858 T5197 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2536885 T5197 oass.IndexSchema.readSchema [awholynewcollection_0_shard2_replica2] Schema name=test
[junit4:junit4] 2> 2536886 T5168 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2536890 T5168 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2536932 T5186 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2537011 T5186 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2537019 T5195 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2537021 T5223 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2537027 T5195 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2537040 T5168 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica5] Schema name=test
[junit4:junit4] 2> 2537047 T5228 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:53143__nodes_used_collection_shard2_replica2, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 2537048 T5228 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:53143__nodes_used_collection_shard2_replica2&state=recovering&nodeName=127.0.0.1:53143_&action=PREPRECOVERY&checkLive=true&core=nodes_used_collection_shard2_replica1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 2537062 T5195 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica2] Schema name=test
[junit4:junit4] 2> 2537068 T5223 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2537070 T5224 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2537083 T5223 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica1] Schema name=test
[junit4:junit4] 2> 2537087 T5224 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2537100 T5224 oass.IndexSchema.readSchema [awholynewcollection_0_shard2_replica1] Schema name=test
[junit4:junit4] 2> 2537185 T5186 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica3] Schema name=test
[junit4:junit4] 2> 2537191 T5163 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2537201 T5163 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2537324 T5163 oass.IndexSchema.readSchema [awholynewcollection_0_shard2_replica5] Schema name=test
[junit4:junit4] 2> 2537352 T5212 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2537368 T5212 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2537379 T5181 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2537378 T5211 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2537388 T5211 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2537389 T5181 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2537449 T5212 oass.IndexSchema.readSchema [awholynewcollection_0_shard2_replica4] Schema name=test
[junit4:junit4] 2> 2537484 T5211 oass.IndexSchema.readSchema [awholynewcollection_0_shard1_replica4] Schema name=test
[junit4:junit4] 2> 2537521 T5181 oass.IndexSchema.readSchema [awholynewcollection_0_shard2_replica3] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C3192 name=nodes_used_collection_shard1_replica1 org.apache.solr.core.SolrCore@5c441feb url=http://127.0.0.1:53153/nodes_used_collection_shard1_replica1 node=127.0.0.1:53153_ C3192_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica1 props:{shard=shard1, state=recovering, core=nodes_used_collection_shard1_replica1, collection=nodes_used_collection, node_name=127.0.0.1:53153_, base_url=http://127.0.0.1:53153}
[junit4:junit4] 2> 2538868 T5244 C3192 P53153 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:53150/nodes_used_collection_shard1_replica2/ core=nodes_used_collection_shard1_replica1 - recoveringAfterStartup=true
[junit4:junit4] 2> 2538873 T5244 C3192 P53153 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard1_replica1 url=http://127.0.0.1:53153 START replicas=[http://127.0.0.1:53150/nodes_used_collection_shard1_replica2/] nUpdates=100
[junit4:junit4] 2> 2538885 T5244 C3192 P53153 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 2538885 T5244 C3192 P53153 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 2538885 T5244 C3192 P53153 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 2538886 T5244 C3192 P53153 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 2538886 T5244 C3192 P53153 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 2538886 T5244 C3192 P53153 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:53150/nodes_used_collection_shard1_replica2/. core=nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 2538887 T5244 C3192 P53153 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C3193 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@70088ca2 url=http://127.0.0.1:53150/nodes_used_collection_shard1_replica2 node=127.0.0.1:53150_ C3193_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica2 props:{shard=shard1, state=active, core=nodes_used_collection_shard1_replica2, collection=nodes_used_collection, node_name=127.0.0.1:53150_, base_url=http://127.0.0.1:53150, leader=true}
[junit4:junit4] 2> 2538969 T5196 C3193 P53150 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=7
[junit4:junit4] 2> 2539036 T5198 C3193 P53150 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2539044 T5198 C3193 P53150 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6ac3b137 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6682d780),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2539045 T5198 C3193 P53150 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2539050 T5198 C3193 P53150 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6ac3b137 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6682d780),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6ac3b137 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6682d780),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2539050 T5198 C3193 P53150 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> ASYNC NEW_CORE C3194 name=nodes_used_collection_shard2_replica2 org.apache.solr.core.SolrCore@41e4e67d url=http://127.0.0.1:53143/nodes_used_collection_shard2_replica2 node=127.0.0.1:53143_ C3194_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:53143_, base_url=http://127.0.0.1:53143}
[junit4:junit4] 2> 2539053 T5245 C3194 P53143 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:53156/nodes_used_collection_shard2_replica1/ core=nodes_used_collection_shard2_replica2 - recoveringAfterStartup=true
[junit4:junit4] 2> 2539053 T5245 C3194 P53143 oasu.PeerSync.sync PeerSync: core=nodes_used_collection_shard2_replica2 url=http://127.0.0.1:53143 START replicas=[http://127.0.0.1:53156/nodes_used_collection_shard2_replica1/] nUpdates=100
[junit4:junit4] 2> 2539053 T5198 C3193 P53150 oass.SolrIndexSearcher.<init> Opening Searcher@5b32ef01 realtime
[junit4:junit4] 2> 2539054 T5198 C3193 P53150 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2539055 T5198 C3193 P53150 oasup.LogUpdateProcessor.finish [nodes_used_collection_shard1_replica2] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 19
[junit4:junit4] 2> 2539057 T5244 C3192 P53153 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2539058 T5244 C3192 P53153 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 2539064 T5245 C3194 P53143 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 2539064 T5245 C3194 P53143 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 2539064 T5245 C3194 P53143 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 2539064 T5245 C3194 P53143 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 2539067 T5245 C3194 P53143 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 2539068 T5245 C3194 P53143 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:53156/nodes_used_collection_shard2_replica1/. core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 2539069 T5245 C3194 P53143 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2539066 T5196 C3193 P53150 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2539079 T5196 C3193 P53150 oasc.SolrCore.execute [nodes_used_collection_shard1_replica2] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=14
[junit4:junit4] 2> 2539083 T5244 C3192 P53153 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 2539083 T5244 C3192 P53153 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 2539084 T5244 C3192 P53153 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 2539110 T5200 C3193 P53150 oasc.SolrCore.execute [nodes_used_collection_shard1_replica2] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=2
[junit4:junit4] 2> 2539114 T5244 C3192 P53153 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> ASYNC NEW_CORE C3195 name=nodes_used_collection_shard1_replica1 org.apache.solr.core.SolrCore@5c441feb url=http://127.0.0.1:53153/nodes_used_collection_shard1_replica1 node=127.0.0.1:53153_ C3195_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica1 props:{shard=shard1, state=recovering, core=nodes_used_collection_shard1_replica1, collection=nodes_used_collection, node_name=127.0.0.1:53153_, base_url=http://127.0.0.1:53153}
[junit4:junit4] 2> 2539192 T5244 C3195 P53153 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/nodes_used_collection_shard1_replica1/data/index.20130607085317380
[junit4:junit4] 2> ASYNC NEW_CORE C3196 name=nodes_used_collection_shard2_replica1 org.apache.solr.core.SolrCore@6a5d036 url=http://127.0.0.1:53156/nodes_used_collection_shard2_replica1 node=127.0.0.1:53156_ C3196_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:53156_, base_url=http://127.0.0.1:53156, leader=true}
[junit4:junit4] 2> 2539196 T5225 C3196 P53156 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=3
[junit4:junit4] 2> 2539197 T5244 C3195 P53153 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@42c0dab3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@50cf139e) fullCopy=false
[junit4:junit4] 2> 2539199 T5228 C3196 P53156 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2539208 T5228 C3196 P53156 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c41699c lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e89d0ef),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2539209 T5228 C3196 P53156 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2539211 T5228 C3196 P53156 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c41699c lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e89d0ef),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c41699c lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e89d0ef),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2539211 T5228 C3196 P53156 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2539212 T5228 C3196 P53156 oass.SolrIndexSearcher.<init> Opening Searcher@20f955a2 realtime
[junit4:junit4] 2> 2539212 T5228 C3196 P53156 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2539213 T5228 C3196 P53156 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 14
[junit4:junit4] 2> ASYNC NEW_CORE C3197 name=nodes_used_collection_shard1_replica2 org.apache.solr.core.SolrCore@70088ca2 url=http://127.0.0.1:53150/nodes_used_collection_shard1_replica2 node=127.0.0.1:53150_ C3197_STATE=coll:nodes_used_collection core:nodes_used_collection_shard1_replica2 props:{shard=shard1, state=active, core=nodes_used_collection_shard1_replica2, collection=nodes_used_collection, node_name=127.0.0.1:53150_, base_url=http://127.0.0.1:53150, leader=true}
[junit4:junit4] 2> 2539215 T5198 C3197 P53150 oasc.SolrCore.execute [nodes_used_collection_shard1_replica2] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> ASYNC NEW_CORE C3198 name=nodes_used_collection_shard2_replica2 org.apache.solr.core.SolrCore@41e4e67d url=http://127.0.0.1:53143/nodes_used_collection_shard2_replica2 node=127.0.0.1:53143_ C3198_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:53143_, base_url=http://127.0.0.1:53143}
[junit4:junit4] 2> 2539227 T5245 C3198 P53143 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2539227 T5245 C3198 P53143 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 2539228 T5244 C3195 P53153 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 2539233 T5226 C3196 P53156 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2539258 T5226 C3196 P53156 oasc.SolrCore.execute [nodes_used_collection_shard2_replica1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=26
[junit4:junit4] 2> 2539267 T5245 C3198 P53143 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 2539267 T5245 C3198 P53143 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 2539268 T5245 C3198 P53143 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 2539269 T5244 C3195 P53153 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 2539269 T5244 C3195 P53153 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 2539273 T5225 C3196 P53156 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=2
[junit4:junit4] 2> 2539276 T5245 C3198 P53143 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 2539281 T5244 C3195 P53153 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@201ce579 lockFactory=org.apache.lucene.store.NativeFSLockFactory@246e9059),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@201ce579 lockFactory=org.apache.lucene.store.NativeFSLockFactory@246e9059),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2539283 T5244 C3195 P53153 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2539286 T5245 C3198 P53143 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/nodes_used_collection_shard2_replica2/data/index.20130607085317550
[junit4:junit4] 2> 2539287 T5245 C3198 P53143 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@7569290b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7d4b8800) fullCopy=false
[junit4:junit4] 2> 2539287 T5244 C3195 P53153 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 2539288 T5244 C3195 P53153 oass.SolrIndexSearcher.<init> Opening Searcher@b12b92f main
[junit4:junit4] 2> 2539290 T5238 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica1] Registered new searcher Searcher@b12b92f main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2539292 T5244 C3195 P53153 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/nodes_used_collection_shard1_replica1/data/index.20130607085317380 [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/nodes_used_collection_shard1_replica1/data/index.20130607085317380;done=true>>]
[junit4:junit4] 2> 2539292 T5244 C3195 P53153 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/nodes_used_collection_shard1_replica1/data/index.20130607085317380
[junit4:junit4] 2> 2539293 T5244 C3195 P53153 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/nodes_used_collection_shard1_replica1/data/index.20130607085317380
[junit4:junit4] 2> 2539293 T5244 C3195 P53153 oasc.RecoveryStrategy.replay No replay needed. core=nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 2539294 T5244 C3195 P53153 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 2539294 T5244 C3195 P53153 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica1 state=active
[junit4:junit4] 2> 2539299 T5228 C3196 P53156 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> 2539300 T5244 C3195 P53153 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=nodes_used_collection_shard1_replica1
[junit4:junit4] 2> 2539319 T5245 C3198 P53143 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 2539320 T5245 C3198 P53143 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 2539320 T5245 C3198 P53143 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 2539327 T5245 C3198 P53143 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@38a34175 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7cbcf28),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@38a34175 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7cbcf28),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2539328 T5245 C3198 P53143 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2539338 T5245 C3198 P53143 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 2539339 T5245 C3198 P53143 oass.SolrIndexSearcher.<init> Opening Searcher@24892244 main
[junit4:junit4] 2> 2539342 T5239 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica2] Registered new searcher Searcher@24892244 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2539343 T5245 C3198 P53143 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/nodes_used_collection_shard2_replica2/data/index.20130607085317550 [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/nodes_used_collection_shard2_replica2/data/index.20130607085317550;done=true>>]
[junit4:junit4] 2> 2539343 T5245 C3198 P53143 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/nodes_used_collection_shard2_replica2/data/index.20130607085317550
[junit4:junit4] 2> 2539344 T5245 C3198 P53143 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/nodes_used_collection_shard2_replica2/data/index.20130607085317550
[junit4:junit4] 2> 2539344 T5245 C3198 P53143 oasc.RecoveryStrategy.replay No replay needed. core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 2539345 T5245 C3198 P53143 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 2539345 T5245 C3198 P53143 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica2 state=active
[junit4:junit4] 2> 2539356 T5245 C3198 P53143 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=nodes_used_collection_shard2_replica2
[junit4:junit4] 2> 2540733 T5173 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2540735 T5173 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53153__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:53153_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53153"}
[junit4:junit4] 2> 2540745 T5173 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53143__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:53143_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53143"}
[junit4:junit4] 2> 2540764 T5204 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> 2540764 T5172 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> 2540765 T5190 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> 2540765 T5232 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> 2540764 T5247 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> 2540765 T5177 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> 2540765 T5249 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> 2540765 T5218 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> 2546184 T5186 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2546286 T5186 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2546371 T5186 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2546550 T5186 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2546590 T5186 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2546645 T5186 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2546649 T5186 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2546649 T5186 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2546650 T5186 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2546657 T5212 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2546660 T5186 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2546661 T5186 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2546661 T5186 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2546662 T5186 oasc.SolrCore.<init> [awholynewcollection_0_shard1_replica3] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard1_replica3/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard1_replica3/data/
[junit4:junit4] 2> 2546663 T5186 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bf47ae8
[junit4:junit4] 2> 2546664 T5186 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2546665 T5186 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard1_replica3/data
[junit4:junit4] 2> 2546665 T5186 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard1_replica3/data/index/
[junit4:junit4] 2> 2546666 T5186 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard1_replica3] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard1_replica3/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2546675 T5186 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard1_replica3/data/index
[junit4:junit4] 2> 2546710 T5186 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@51c46d61 lockFactory=org.apache.lucene.store.NativeFSLockFactory@171d8a81),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2546710 T5186 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2546711 T5163 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2546724 T5181 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2546728 T5186 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2546729 T5186 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2546730 T5186 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2546735 T5186 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2546736 T5186 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2546737 T5186 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2546737 T5186 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2546742 T5186 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2546743 T5186 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2546745 T5212 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2546809 T5197 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2546821 T5163 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2546833 T5163 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2546836 T5181 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2546841 T5181 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2546856 T5186 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2546879 T5186 oass.SolrIndexSearcher.<init> Opening Searcher@10e9b86b main
[junit4:junit4] 2> 2546884 T5186 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard1_replica3/data/tlog
[junit4:junit4] 2> 2546887 T5186 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2546887 T5186 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2546896 T5197 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2546897 T5212 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2546914 T5197 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2546921 T5168 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2546923 T5195 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2546936 T5260 oasc.SolrCore.registerSearcher [awholynewcollection_0_shard1_replica3] Registered new searcher Searcher@10e9b86b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2546956 T5186 oasc.ZkController.publish publishing core=awholynewcollection_0_shard1_replica3 state=down
[junit4:junit4] 2> 2546969 T5223 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2546982 T5195 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2546987 T5181 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2546996 T5212 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547008 T5195 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2547019 T5168 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2547025 T5168 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2547033 T5223 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2547057 T5223 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2547083 T5211 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2547083 T5212 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547097 T5163 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547102 T5197 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547104 T5181 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547107 T5212 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2547115 T5212 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2547116 T5212 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2547117 T5212 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2547116 T5197 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547121 T5181 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2547127 T5163 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547128 T5211 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2547143 T5212 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2547143 T5212 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2547144 T5212 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2547145 T5212 oasc.SolrCore.<init> [awholynewcollection_0_shard2_replica4] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/awholynewcollection_0_shard2_replica4/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/awholynewcollection_0_shard2_replica4/data/
[junit4:junit4] 2> 2547145 T5212 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bf47ae8
[junit4:junit4] 2> 2547146 T5212 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2547147 T5212 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/awholynewcollection_0_shard2_replica4/data
[junit4:junit4] 2> 2547148 T5212 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/awholynewcollection_0_shard2_replica4/data/index/
[junit4:junit4] 2> 2547148 T5212 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard2_replica4] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/awholynewcollection_0_shard2_replica4/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2547150 T5181 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2547150 T5181 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2547150 T5181 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2547154 T5163 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2547157 T5197 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2547159 T5212 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1370605979138/awholynewcollection_0_shard2_replica4/data/index
[junit4:junit4] 2> 2547166 T5181 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2547167 T5181 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2547170 T5181 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2547171 T5181 oasc.SolrCore.<init> [awholynewcollection_0_shard2_replica3] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard2_replica3/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard2_replica3/data/
[junit4:junit4] 2> 2547171 T5181 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bf47ae8
[junit4:junit4] 2> 2547154 T5211 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2547173 T5212 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@56c26e9b lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f7b377a),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2547178 T5212 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2547173 T5181 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2547169 T5197 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2547183 T5197 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2547183 T5197 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2547169 T5163 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2547187 T5163 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2547187 T5163 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2547182 T5181 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard2_replica3/data
[junit4:junit4] 2> 2547189 T5181 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard2_replica3/data/index/
[junit4:junit4] 2> 2547189 T5181 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard2_replica3] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard2_replica3/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2547192 T5181 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1370605974622/awholynewcollection_0_shard2_replica3/data/index
[junit4:junit4] 2> 2547200 T5163 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2547201 T5163 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2547201 T5163 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2547202 T5163 oasc.SolrCore.<init> [awholynewcollection_0_shard2_replica5] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard2_replica5/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard2_replica5/data/
[junit4:junit4] 2> 2547203 T5163 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bf47ae8
[junit4:junit4] 2> 2547203 T5163 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2547204 T5163 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard2_replica5/data
[junit4:junit4] 2> 2547205 T5163 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard2_replica5/data/index/
[junit4:junit4] 2> 2547205 T5163 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard2_replica5] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard2_replica5/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2547208 T5163 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard2_replica5/data/index
[junit4:junit4] 2> 2547217 T5212 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2547218 T5212 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2547219 T5197 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2547226 T5197 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2547226 T5197 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2547227 T5197 oasc.SolrCore.<init> [awholynewcollection_0_shard2_replica2] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/awholynewcollection_0_shard2_replica2/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/awholynewcollection_0_shard2_replica2/data/
[junit4:junit4] 2> 2547228 T5197 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bf47ae8
[junit4:junit4] 2> 2547229 T5197 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2547230 T5197 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/awholynewcollection_0_shard2_replica2/data
[junit4:junit4] 2> 2547231 T5197 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/awholynewcollection_0_shard2_replica2/data/index/
[junit4:junit4] 2> 2547231 T5197 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard2_replica2] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/awholynewcollection_0_shard2_replica2/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2547225 T5212 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2547233 T5212 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2547228 T5181 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4a81a62 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3caf77b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2547235 T5181 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2547227 T5163 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1baf06bb lockFactory=org.apache.lucene.store.NativeFSLockFactory@147a572d),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2547238 T5163 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2547239 T5168 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547235 T5197 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/awholynewcollection_0_shard2_replica2/data/index
[junit4:junit4] 2> 2547262 T5195 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547273 T5181 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2547274 T5181 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2547276 T5181 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2547277 T5181 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2547278 T5181 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2547278 T5181 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2547234 T5212 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2547285 T5212 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2547286 T5212 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2547287 T5212 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2547288 T5212 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2547285 T5181 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2547293 T5181 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2547285 T5197 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@577c730f lockFactory=org.apache.lucene.store.NativeFSLockFactory@13ed3ecf),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2547295 T5197 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2547297 T5163 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2547298 T5163 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2547299 T5163 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2547300 T5181 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2547300 T5163 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2547306 T5163 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2547306 T5163 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2547307 T5163 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2547308 T5163 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2547308 T5163 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2547313 T5168 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547325 T5197 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2547326 T5197 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2547329 T5197 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2547332 T5197 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2547333 T5197 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2547333 T5197 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2547334 T5197 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2547335 T5197 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2547348 T5197 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2547349 T5195 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547351 T5181 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2547348 T5223 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547363 T5163 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2547374 T5212 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2547382 T5223 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547387 T5168 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2547392 T5197 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2547395 T5168 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2547396 T5168 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2547396 T5168 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2547405 T5211 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547409 T5163 oass.SolrIndexSearcher.<init> Opening Searcher@d72230a main
[junit4:junit4] 2> 2547410 T5163 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard2_replica5/data/tlog
[junit4:junit4] 2> 2547416 T5168 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2547416 T5168 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2547417 T5168 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2547417 T5168 oasc.SolrCore.<init> [awholynewcollection_0_shard1_replica5] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard1_replica5/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard1_replica5/data/
[junit4:junit4] 2> 2547419 T5168 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bf47ae8
[junit4:junit4] 2> 2547420 T5168 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2547419 T5195 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2547421 T5168 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard1_replica5/data
[junit4:junit4] 2> 2547422 T5168 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard1_replica5/data/index/
[junit4:junit4] 2> 2547423 T5168 oasc.SolrCore.initIndex WARN [awholynewcollection_0_shard1_replica5] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard1_replica5/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2547425 T5195 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2547425 T5195 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2547426 T5195 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2547427 T5168 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1370605973183/awholynewcollection_0_shard1_replica5/data/index
[junit4:junit4] 2> 2547428 T5211 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2547430 T5223 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2547424 T5197 oass.SolrIndexSearcher.<init> Opening Searcher@736b7d52 main
[junit4:junit4] 2> 2547434 T5197 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/awholynewcollection_0_shard2_replica2/data/tlog
[junit4:junit4] 2> 2547424 T5163 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2547438 T5163 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2547436 T5195 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2547444 T5195 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2547445 T5195 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2547446 T5195 oasc.SolrCore.<init> [awholynewcollection_0_shard1_replica2] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/awholynewcollection_0_shard1_replica2/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1370605976885/awholynewcollection_0_shard1_replica2/data/
[junit4:junit4] 2> 2547447 T5195 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bf47ae8
[junit4:junit4] 2> 2547448 T5195 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2547450 T5195 oasc.CachingDirec
[...truncated too long message...]
der_elect (2)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard1/election (3)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard1/election/89824033040171020-127.0.0.1:53156__awholynewcollection_1_shard1_replica1-n_0000000001 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard1/election/89824033040171014-127.0.0.1:53147__awholynewcollection_1_shard1_replica2-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard1/election/89824033040171016-127.0.0.1:53150__awholynewcollection_1_shard1_replica3-n_0000000002 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard2 (1)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard2/election (3)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard2/election/89824033040171011-127.0.0.1:53143__awholynewcollection_1_shard2_replica2-n_0000000002 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard2/election/89824033040171020-127.0.0.1:53156__awholynewcollection_1_shard2_replica3-n_0000000001 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leader_elect/shard2/election/89824033040171018-127.0.0.1:53153__awholynewcollection_1_shard2_replica1-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leaders (2)
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"awholynewcollection_1_shard1_replica2",
[junit4:junit4] 1> "node_name":"127.0.0.1:53147_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:53147"}
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leaders/shard2 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"awholynewcollection_1_shard2_replica1",
[junit4:junit4] 1> "node_name":"127.0.0.1:53153_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:53153"}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (5)
[junit4:junit4] 1> /solr/overseer_elect/election/89824033040171016-127.0.0.1:53150_-n_0000000002 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89824033040171011-127.0.0.1:53143_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89824033040171020-127.0.0.1:53156_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89824033040171018-127.0.0.1:53153_-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89824033040171014-127.0.0.1:53147_-n_0000000001 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89824033040171011-127.0.0.1:53143_-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=E60367ED123D8B46 -Dtests.slow=true -Dtests.locale=sr_BA -Dtests.timezone=America/Argentina/Buenos_Aires -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] FAILURE 349s | CollectionsAPIDistributedZkTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: There are still nodes recoverying - waited for 230 seconds
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([E60367ED123D8B46:67E5E9F56562EB7A]: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:680)
[junit4:junit4] 2> 2863371 T5150 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 348770 T5149 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> NOTE: test params are: codec=Appending, sim=DefaultSimilarity, locale=sr_BA, timezone=America/Argentina/Buenos_Aires
[junit4:junit4] 2> NOTE: Mac OS X 10.8.3 x86_64/Apple Inc. 1.6.0_45 (64-bit)/cpus=2,threads=1,free=72423632,total=204369920
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestPropInject, TestNumberUtils, ShardRoutingCustomTest, TestSolrXMLSerializer, SyncSliceTest, TestSolrIndexConfig, PeerSyncTest, HighlighterConfigTest, SolrCoreCheckLockOnStartupTest, TestDistributedSearch, TestXIncludeConfig, RegexBoostProcessorTest, ChaosMonkeySafeLeaderTest, ReturnFieldsTest, WordBreakSolrSpellCheckerTest, TestLuceneMatchVersion, ResponseLogComponentTest, TestDistributedGrouping, TestClassNameShortening, TestShardHandlerFactory, TestFieldCollectionResource, CacheHeaderTest, CurrencyFieldOpenExchangeTest, TestSuggestSpellingConverter, PreAnalyzedUpdateProcessorTest, SoftAutoCommitTest, ZkCLITest, TestPseudoReturnFields, SampleTest, SuggesterTest, TestJoin, TestCSVResponseWriter, TestWriterPerf, TestIndexSearcher, AliasIntegrationTest, TestCoreDiscovery, SpellPossibilityIteratorTest, SliceStateTest, TestCodecSupport, TestReloadAndDeleteDocs, TestManagedSchema, TestFoldingMultitermQuery, TestJmxMonitoredMap, IndexReaderFactoryTest, PolyFieldTest, TestQueryUtils, TestSchemaResource, ExternalFileFieldSortTest, TestReplicationHandler, TestRecovery, OverseerTest, StatelessScriptUpdateProcessorFactoryTest, BadIndexSchemaTest, TestConfig, SignatureUpdateProcessorFactoryTest, TestFuzzyAnalyzedSuggestions, JSONWriterTest, TestElisionMultitermQuery, LeaderElectionIntegrationTest, TestManagedSchemaFieldResource, SortByFunctionTest, TestSolrQueryParser, DocumentBuilderTest, TestHashPartitioner, SolrIndexSplitterTest, NoCacheHeaderTest, AutoCommitTest, TestDefaultSimilarityFactory, ShardRoutingTest, TimeZoneUtilsTest, DateFieldTest, TestQueryTypes, TestPHPSerializedResponseWriter, LukeRequestHandlerTest, TestFunctionQuery, HighlighterTest, OverseerCollectionProcessorTest, TestArbitraryIndexDir, TestRandomFaceting, TestQuerySenderListener, DistributedTermsComponentTest, TestRealTimeGet, TestTrie, TestRTGBase, SolrCmdDistributorTest, DistributedSpellCheckComponentTest, TestCloudManagedSchema, RequestHandlersTest, TestExtendedDismaxParser, TestLFUCache, ClusterStateUpdateTest, PluginInfoTest, ClusterStateTest, LeaderElectionTest, TestMaxScoreQueryParser, FastVectorHighlighterTest, TestSolrXml, FileUtilsTest, CopyFieldTest, DebugComponentTest, SimplePostToolTest, DefaultValueUpdateProcessorTest, TestBinaryResponseWriter, TestWordDelimiterFilterFactory, LegacyHTMLStripCharFilterTest, NumericFieldsTest, ShowFileRequestHandlerTest, ResourceLoaderTest, TestBinaryField, DistanceFunctionTest, TestSolrJ, TestAnalyzedSuggestions, TestSurroundQueryParser, TestRangeQuery, TestReversedWildcardFilterFactory, DirectSolrSpellCheckerTest, TestFaceting, TermVectorComponentTest, JsonLoaderTest, TestComponentsName, TestSchemaVersionResource, CurrencyFieldXmlFileTest, IndexSchemaRuntimeFieldTest, UpdateRequestProcessorFactoryTest, TermVectorComponentDistributedTest, TestCollationField, SpellCheckCollatorTest, TestLMDirichletSimilarityFactory, TestLazyCores, TestRemoteStreaming, TestFastLRUCache, TestSolrDeletionPolicy2, SuggesterWFSTTest, BasicFunctionalityTest, DirectUpdateHandlerOptimizeTest, FullSolrCloudDistribCmdsTest, TestCopyFieldCollectionResource, SimpleFacetsTest, TestPartialUpdateDeduplication, TestSolrQueryParserResource, OutputWriterTest, TestSystemIdResolver, SolrPluginUtilsTest, TestZkChroot, PingRequestHandlerTest, BasicDistributedZkTest, BasicDistributedZk2Test, UnloadDistributedZkTest, CollectionsAPIDistributedZkTest]
[junit4:junit4] Completed in 349.34s, 1 test, 1 failure <<< FAILURES!
[...truncated 460 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:386: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:366: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build.xml:181: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/common-build.xml:437: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:1243: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:887: There were test failures: 297 suites, 1246 tests, 1 failure, 18 ignored (6 assumptions)
Total time: 124 minutes 0 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.6.0 -XX:+UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure