You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/04 21:40:47 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/ibm-j9-jdk7) - Build # 5920
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/5920/
Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
3 tests failed.
REGRESSION: org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearch
Error Message:
Server at http://127.0.0.1:39703/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:39703/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
at __randomizedtesting.SeedInfo.seed([98680BD6ECD54C6C:198E85CE9B8A2C50]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:198)
at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:90)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:613)
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:780)
REGRESSION: org.apache.solr.core.TestJmxIntegration.testJmxRegistration
Error Message:
No SolrDynamicMBeans found
Stack Trace:
java.lang.AssertionError: No SolrDynamicMBeans found
at __randomizedtesting.SeedInfo.seed([98680BD6ECD54C6C:16B96FEC81941409]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.apache.solr.core.TestJmxIntegration.testJmxRegistration(TestJmxIntegration.java:94)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:613)
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:780)
REGRESSION: org.apache.solr.update.HardAutoCommitTest.testCommitWithin
Error Message:
Exception during query
Stack Trace:
java.lang.RuntimeException: Exception during query
at __randomizedtesting.SeedInfo.seed([98680BD6ECD54C6C:22BA64AE6FFBA279]:0)
at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:527)
at org.apache.solr.update.HardAutoCommitTest.testCommitWithin(HardAutoCommitTest.java:79)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:613)
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:780)
Caused by: java.lang.RuntimeException: REQUEST FAILED: xpath=//result[@numFound=0]
xml response was: <?xml version="1.0" encoding="UTF-8"?>
<response>
<lst name="responseHeader"><int name="status">0</int><int name="QTime">3499</int></lst><result name="response" numFound="1" start="0"><doc><int name="id">529</int><int name="range_facet_si">529</int><arr name="range_facet_l"><long>529</long></arr><arr name="range_facet_sl"><long>529</long></arr><arr name="field_t"><str>what's inside?</str></arr><arr name="subject"><str>info</str></arr><long name="_version_">1436941322610016256</long><int name="intDefault">42</int><date name="timestamp">2013-06-04T19:27:13.556Z</date><arr name="multiDefault"><str>muLti-Default</str></arr></doc></result>
</response>
request was:q=id:529&start=0&qt=standard&version=2.2&rows=20
at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:520)
... 41 more
Build Log:
[...truncated 9296 lines...]
[junit4:junit4] Suite: org.apache.solr.core.TestJmxIntegration
[junit4:junit4] 2> 5268 T30 oas.SolrTestCaseJ4.initCore ####initCore
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-TestJmxIntegration-1370373519381
[junit4:junit4] 2> 5270 T30 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/'
[junit4:junit4] 2> 5271 T30 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/lib/README' to classloader
[junit4:junit4] 2> 5272 T30 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 5361 T30 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 5465 T30 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 5465 T30 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 5508 T30 oass.IndexSchema.readSchema [null] Schema name=test
[junit4:junit4] 2> 6061 T30 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 6075 T30 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 6078 T30 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 6113 T30 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 6121 T30 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 6133 T30 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 6137 T30 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 6138 T30 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 6138 T30 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 6139 T30 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 6140 T30 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 6140 T30 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 6141 T30 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr
[junit4:junit4] 2> 6142 T30 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/'
[junit4:junit4] 2> 6154 T30 oasc.CoreContainer.<init> New CoreContainer 749473223
[junit4:junit4] 2> 6189 T30 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 6190 T30 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-TestJmxIntegration-1370373519381/
[junit4:junit4] 2> 6191 T30 oasc.JmxMonitoredMap.<init> No JMX servers found, not exposing Solr information with JMX.
[junit4:junit4] 2> 6192 T30 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 6194 T30 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-TestJmxIntegration-1370373519381
[junit4:junit4] 2> 6195 T30 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-TestJmxIntegration-1370373519381/index/
[junit4:junit4] 2> 6196 T30 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-TestJmxIntegration-1370373519381/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 6197 T30 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-TestJmxIntegration-1370373519381/index
[junit4:junit4] 2> 6202 T30 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(MockDirWrapper(org.apache.lucene.store.RAMDirectory@bbbbc6f lockFactory=org.apache.lucene.store.NativeFSLockFactory@de3be64c)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 6203 T30 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 6204 T30 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 6220 T30 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 6230 T30 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 6231 T30 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 6233 T30 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 6236 T30 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 6238 T30 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 6239 T30 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 6243 T30 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 6244 T30 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 6253 T30 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 6264 T30 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 6265 T30 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 6266 T30 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 6267 T30 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 6268 T30 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 6270 T30 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 6279 T30 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 6281 T30 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 6283 T30 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 6284 T30 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 6286 T30 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 6287 T30 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 6288 T30 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 6289 T30 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 6302 T30 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 6311 T30 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 6314 T30 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 6317 T30 oasc.SolrCore.initDeprecatedSupport WARN solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 6321 T30 oasc.SolrCore.initDeprecatedSupport WARN adding ShowFileRequestHandler with hidden files: [SOLRCONFIG-MANAGED-SCHEMA.XML, BAD-SCHEMA-NOT-INDEXED-BUT-TF.XML, SCHEMA-REQUIRED-FIELDS.XML, BAD-SOLRCONFIG-MANAGED-SCHEMA-NAMED-SCHEMA.XML.XML, SOLRCONFIG-MASTER1-KEEPONEBACKUP.XML, SOLRCONFIG-PROPINJECT.XML, BAD-SCHEMA-NONTEXT-ANALYZER.XML, SCHEMA-BEHAVIOR.XML, SOLRCONFIG-PROPINJECT-INDEXDEFAULT.XML, STOP-2.TXT, SCHEMA11.XML, BAD-SCHEMA-UNIQUEKEY-USES-DEFAULT.XML, SCHEMA15.XML, BAD-SOLRCONFIG-UNEXPECTED-SCHEMA-ATTRIBUTE.XML, SOLRCONFIG-NATIVELOCK.XML, SCHEMA-SIM.XML, CONDITIONAL.UPDATEPROCESSOR.JS, SCHEMA-DOCVALUES.XML, SCHEMA-ID-AND-VERSION-FIELDS-ONLY.XML, BAD-SOLRCONFIG-MISSING-SCRIPTFILE.XML, SOLRCONFIG-SCRIPT-UPDATEPROCESSOR.XML, SOLRCONFIG-REPEATER.XML, BAD-SCHEMA-DOCVALUES-NOT-REQUIRED-NO-DEFAULT.XML, SOLRCONFIG-SPELLCHECKER.XML, SOLRCONFIG-NOCACHE.XML, SCHEMA-CHARFILTERS.XML, SOLRCONFIG-SOLCOREPROPERTIES.XML, SCHEMA-EFF.XML, SOLRCONFIG_CODEC.XML, SOLRCONFIG-MUTABLE-MANAGED-SCHEMA.XML, BAD-SCHEMA-EXTERNAL-FILEFIELD.XML, HYPHENATION.DTD, TRIVIAL.UPDATEPROCESSOR1.JS, SOLRCONFIG-MERGEPOLICY.XML, SOLRCONFIG-PHRASESUGGEST.XML, SOLRCONFIG-SLAVE1.XML, SOLRCONFIG-BASIC.XML, SCHEMA-LMJELINEKMERCER.XML, BAD-MP-SOLRCONFIG.XML, JASUGGEST.TXT, BAD-SCHEMA-DUP-FIELD.XML, BAD-SCHEMA-UNIQUEKEY-MULTIVALUED.XML, SOLRCONFIG-MASTER.XML, SOLRCONFIG-HIGHLIGHT.XML, SCHEMA-TFIDF.XML, SCHEMA-REPLICATION1.XML, STOPWITHBOM.TXT, SOLRCONFIG-ELEVATE.XML, SYNONYMS.TXT, SOLRCONFIG-QUERYSENDER.XML, SOLRCONFIG-COMPONENTS-NAME.XML, SOLRCONFIG-SNIPPET-PROCESSOR.XML, WDFTYPES.TXT, BAD-SCHEMA-CURRENCY-FT-OER-NORATES.XML, SOLRCONFIG-DELPOLICY1.XML, BAD_SOLRCONFIG.XML, BAD-SCHEMA-UNSUPPORTED-DOCVALUES.XML, HUNSPELL-TEST.DIC, SCHEMA-NUMERIC.XML, SCHEMA-LUCENEMATCHVERSION.XML, KEEP-2.TXT, SCHEMA-STOP-KEEP.XML, SCHEMA-IB.XML, STOP-SNOWBALL.TXT, SCHEMA-ONE-FIELD-NO-DYNAMIC-FIELD.XML, BAD-SCHEMA-MULTIPLE-ASTERISK-COPYFIELD-DEST-SHOULD-FAIL-TEST.XML, SCHEMA-DOCVALUESMULTI.XML, SOLRCONFIG-INDEXCONFIG.XML, SOLRCONFIG-SLAVE.XML, SCHEMA-CLASS-NAME-SHORTENING-ON-SERIALIZATION.XML, BAD-SCHEMA-NOT-INDEXED-BUT-NORMS.XML, STOPWORDSWRONGENCODING.TXT, BAD-SCHEMA-MISPLACED-ASTERISK-COPYFIELD-SOURCE-SHOULD-FAIL-TEST.XML, THROW.ERROR.ON.ADD.UPDATEPROCESSOR.JS, STOPTYPES-1.TXT, SOLRCONFIG-SPELLCHECKCOMPONENT.XML, REGEX-BOOST-PROCESSOR-TEST.TXT, SOLRCONFIG-MINIMAL.XML, SCHEMA-DOCVALUESFACETING.XML, SOLRCONFIG-TLOG.XML, COMPOUNDDICTIONARY.TXT, SOLRCONFIG-POSTINGSHIGHLIGHT.XML, DA_COMPOUNDDICTIONARY.TXT, SOLRCONFIG-TERMINDEX.XML, BAD-SOLRCONFIG-INVALID-SCRIPTFILE.XML, BAD-SCHEMA-NON-GLOB-COPYFIELD-SOURCE-MATCHING-NOTHING-SHOULD-FAIL-TEST.XML, SCHEMASURROUND.XML, OPEN-EXCHANGE-RATES.JSON, BAD-SCHEMA-DUP-FIELDTYPE.XML, PHRASESUGGEST.TXT, BAD-SCHEMA-CURRENCY-FT-MULTIVALUED.XML, SOLRCONFIG-MASTER2.XML, OLD_SYNONYMS.TXT, BAD-SCHEMA-UNIQUEKEY-IS-COPYFIELD-DEST.XML, SCHEMA-NOT-REQUIRED-UNIQUE-KEY.XML, BAD-SCHEMA-CODEC-GLOBAL-VS-FT-MISMATCH.XML, SCHEMA-LMDIRICHLET.XML, BAD-SCHEMA-NOT-INDEXED-BUT-POS.XML, SCHEMA-REVERSED.XML, BAD-SCHEMA-CURRENCY-MULTIVALUED.XML, SCHEMA-FOLDING.XML, SOLRCONFIG-CACHING.XML, MAPPING-ISOLATIN1ACCENT.TXT, BAD-CURRENCY.XML, ADDFIELDS.UPDATEPROCESSOR.JS, SCHEMA-BM25.XML, SOLRCONFIG-ENABLEPLUGIN.XML, STOP-1.TXT, BAD-SCHEMA-SWEETSPOT-BOTH-TF.XML, SCHEMA-REST.XML, MISSING.FUNCTIONS.UPDATEPROCESSOR.JS, SCHEMA12.XML, SOLRCONFIG-TRANSFORMERS.XML, SCHEMA-COPYFIELD-TEST.XML, SOLRCONFIG-BASIC-LUCENEVERSION31.XML, BAD-SCHEMA-DUP-DYNAMICFIELD.XML, BAD-SCHEMA-SWEETSPOT-PARTIAL-BASELINE.XML, CURRENCY.XML, DA_UTF8.XML, FUZZYSUGGEST.TXT, SCHEMA-POSTINGSHIGHLIGHT.XML, MISSLEADING.EXTENSION.UPDATEPROCESSOR.JS.TXT, SOLRCONFIG-SOLR-749.XML, STOPWORDS.TXT, BAD-SCHEMA-BOGUS-ANALYSIS-PARAMETERS.XML, HUNSPELL-TEST.AFF, SOLRCONFIG-TLOG-MANAGED-SCHEMA.XML, SOLRCONFIG_PERF.XML, SCHEMA-SWEETSPOT.XML, SOLRCONFIG-SIMPLELOCK.XML, BAD-SCHEMA-MISPLACED-ASTERISK-COPYFIELD-DEST-SHOULD-FAIL-TEST.XML, SCHEMA-TINY.XML, BAD-SCHEMA-SWEETSPOT-PARTIAL-NORMS.XML, FRENCHARTICLES.TXT, SOLRCONFIG-LAZYWRITER.XML, SOLRCONFIG-RESPONSE-LOG-COMPONENT.XML, SCHEMA-REPLICATION2.XML, SCHEMA-SNIPPET-TYPE.XML, SCHEMA-SPATIAL.XML, BAD-SCHEMA-SWEETSPOT-PARTIAL-HYPERBOLIC.XML, SCHEMA-SPELLCHECKER.XML, SOLRCONFIG-XINCLUDE.XML, XSLT, SOLRCONFIG-WARMER.XML, SOLRCONFIG-DELPOLICY2.XML, KEEP-1.TXT, TRIVIAL.UPDATEPROCESSOR0.JS, BAD-SCHEMA-CURRENCY-DYNAMIC-MULTIVALUED.XML, SCHEMA-TRIE.XML, SOLRCONFIG-TLOG-MUTABLE-MANAGED-SCHEMA.XML, SCHEMA-BINARYFIELD.XML, SCHEMA-REST-LUCENE-MATCH-VERSION.XML, SCHEMA-COLLATEFILTER.XML, BAD-SCHEMA-OMIT-TF-BUT-NOT-POS.XML, BAD-SCHEMA-CURRENCY-FT-BOGUS-CODE-IN-XML.XML, SCHEMA-MINIMAL.XML, STOPTYPES-2.TXT, SCHEMA_CODEC.XML, STEMDICT.TXT, SCHEMA-SYNONYM-TOKENIZER.XML, ELEVATE.XML, SCHEMA-COLLATE.XML, PROTWORDS.TXT, SCHEMA-XINCLUDE.XML, SCHEMA-SNIPPET-FIELD.XML, SOLRCONFIG-REQHANDLER.INCL, SCHEMA-PHRASESUGGEST.XML, SCHEMA-DFR.XML, BAD-SCHEMA-ANALYZER-CLASS-AND-NESTED.XML, SOLRCONFIG-MASTER1.XML, SOLRCONFIG-FUNCTIONQUERY.XML, BAD-SOLRCONFIG-SCHEMA-MUTABLE-BUT-NOT-MANAGED.XML, SOLRCONFIG-MASTER3.XML, SOLRCONFIG-UPDATE-PROCESSOR-CHAINS.XML, SOLRCONFIG-ALTDIRECTORY.XML, BAD-SCHEMA-SIM-GLOBAL-VS-FT-MISMATCH.XML, SOLRCONFIG-QUERYSENDER-NOQUERY.XML, BAD-SCHEMA-MULTIPLE-ASTERISK-COPYFIELD-SOURCE-SHOULD-FAIL-TEST.XML, BAD-SOLRCONFIG-BOGUS-SCRIPTENGINE-NAME.XML, BAD-SCHEMA-CURRENCY-FT-BOGUS-DEFAULT-CODE.XML, BAD-SCHEMA-BOGUS-FIELD-PARAMETERS.XML]
[junit4:junit4] 2> 6327 T30 oass.SolrIndexSearcher.<init> Opening Searcher@13ec6ab main
[junit4:junit4] 2> 6330 T30 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-TestJmxIntegration-1370373519381/tlog
[junit4:junit4] 2> 6331 T30 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 6332 T30 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 6333 T30 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 6428 T30 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 6520 T31 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@13ec6ab main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 6520 T30 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 6523 T30 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4:junit4] 2> 6617 T30 oas.SolrTestCaseJ4.setUp ###Starting testJmxUpdate
[junit4:junit4] 2> 6621 T30 oas.SolrTestCaseJ4.tearDown ###Ending testJmxUpdate
[junit4:junit4] IGNOR/A 0.19s J1 | TestJmxIntegration.testJmxUpdate
[junit4:junit4] > Assumption #1: got: <false>, expected: is <true>
[junit4:junit4] 2> 6731 T30 oas.SolrTestCaseJ4.setUp ###Starting testJmxRegistration
[junit4:junit4] 2> 6732 T30 oasc.TestJmxIntegration.testJmxRegistration Servers in testJmxRegistration: [com.sun.jmx.mbeanserver.JmxMBeanServer@9a1f7c5c]
[junit4:junit4] 2> 6737 T30 oas.SolrTestCaseJ4.tearDown ###Ending testJmxRegistration
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestJmxIntegration -Dtests.method=testJmxRegistration -Dtests.seed=98680BD6ECD54C6C -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=zh_SG -Dtests.timezone=Pacific/Pitcairn -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 0.05s J1 | TestJmxIntegration.testJmxRegistration <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: No SolrDynamicMBeans found
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([98680BD6ECD54C6C:16B96FEC81941409]:0)
[junit4:junit4] > at org.apache.solr.core.TestJmxIntegration.testJmxRegistration(TestJmxIntegration.java:94)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:780)
[junit4:junit4] 2> 6765 T30 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 6767 T30 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=749473223
[junit4:junit4] 2> 6768 T30 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@f89d663d
[junit4:junit4] 2> 6770 T30 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 6772 T30 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 6773 T30 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 6774 T30 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 6778 T30 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 6779 T30 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 6781 T30 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-TestJmxIntegration-1370373519381 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-TestJmxIntegration-1370373519381;done=false>>]
[junit4:junit4] 2> 6782 T30 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-TestJmxIntegration-1370373519381
[junit4:junit4] 2> 6784 T30 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-TestJmxIntegration-1370373519381/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-TestJmxIntegration-1370373519381/index;done=false>>]
[junit4:junit4] 2> 6785 T30 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-TestJmxIntegration-1370373519381/index
[junit4:junit4] 2> NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=zh_SG, timezone=Pacific/Pitcairn
[junit4:junit4] 2> NOTE: Linux 3.2.0-45-generic x86/IBM Corporation 1.7.0 (32-bit)/cpus=8,threads=2,free=7525496,total=31784960
[junit4:junit4] 2> NOTE: All tests run in this JVM: [OutputWriterTest, TestPartialUpdateDeduplication, TestJmxIntegration]
[junit4:junit4] Completed on J1 in 1.57s, 3 tests, 1 failure, 2 skipped <<< FAILURES!
[...truncated 270 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4] 2> 318300 T1187 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 318303 T1187 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370373832416
[junit4:junit4] 2> 318304 T1187 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 318305 T1188 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 318405 T1187 oasc.ZkTestServer.run start zk server on port:48722
[junit4:junit4] 2> 318406 T1187 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 318444 T1194 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@da5cb595 name:ZooKeeperConnection Watcher:127.0.0.1:48722 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 318445 T1187 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 318445 T1187 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 318449 T1187 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 318450 T1196 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4e522ec2 name:ZooKeeperConnection Watcher:127.0.0.1:48722/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 318450 T1187 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 318451 T1187 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 318453 T1187 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 318455 T1187 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 318457 T1187 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 318459 T1187 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 318460 T1187 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 318464 T1187 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 318464 T1187 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 318467 T1187 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 318468 T1187 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 318470 T1187 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 318470 T1187 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 318472 T1187 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 318473 T1187 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 318475 T1187 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 318476 T1187 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 318478 T1187 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 318478 T1187 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 318481 T1187 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 318481 T1187 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 318483 T1187 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 318484 T1187 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 318561 T1187 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 318563 T1187 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:39171
[junit4:junit4] 2> 318564 T1187 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 318564 T1187 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 318565 T1187 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370373832599
[junit4:junit4] 2> 318566 T1187 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370373832599/solr.xml
[junit4:junit4] 2> 318566 T1187 oasc.CoreContainer.<init> New CoreContainer -1253800384
[junit4:junit4] 2> 318567 T1187 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370373832599/'
[junit4:junit4] 2> 318568 T1187 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370373832599/'
[junit4:junit4] 2> 318609 T1187 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 318609 T1187 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 318610 T1187 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 318611 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 318611 T1187 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 318612 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 318612 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 318613 T1187 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 318614 T1187 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 318614 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 318619 T1187 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 318620 T1187 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:48722/solr
[junit4:junit4] 2> 318621 T1187 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 318622 T1187 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 318624 T1207 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@40b5fee3 name:ZooKeeperConnection Watcher:127.0.0.1:48722 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 318624 T1187 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 318626 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 318630 T1187 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 318632 T1209 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b70d4860 name:ZooKeeperConnection Watcher:127.0.0.1:48722/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 318632 T1187 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 318634 T1187 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 318636 T1187 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 318639 T1187 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 318641 T1187 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39171_
[junit4:junit4] 2> 318642 T1187 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39171_
[junit4:junit4] 2> 318644 T1187 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 318649 T1187 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 318651 T1187 oasc.Overseer.start Overseer (id=89808819481411587-127.0.0.1:39171_-n_0000000000) starting
[junit4:junit4] 2> 318654 T1187 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 318656 T1211 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 318657 T1187 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 318659 T1187 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 318662 T1187 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 318664 T1210 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 318667 T1212 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370373832599/collection1
[junit4:junit4] 2> 318667 T1212 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 318668 T1212 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 318668 T1212 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 318669 T1212 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370373832599/collection1/'
[junit4:junit4] 2> 318670 T1212 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370373832599/collection1/lib/README' to classloader
[junit4:junit4] 2> 318670 T1212 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370373832599/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 318693 T1212 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 318721 T1212 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 318723 T1212 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 318727 T1212 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 319028 T1212 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 319033 T1212 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 319035 T1212 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 319045 T1212 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 319049 T1212 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 319052 T1212 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 319053 T1212 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 319054 T1212 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 319054 T1212 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 319055 T1212 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 319055 T1212 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 319056 T1212 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 319056 T1212 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1370373832599/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/control/data/
[junit4:junit4] 2> 319056 T1212 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@9a1f7c5c
[junit4:junit4] 2> 319057 T1212 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 319058 T1212 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/control/data
[junit4:junit4] 2> 319058 T1212 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/control/data/index/
[junit4:junit4] 2> 319058 T1212 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 319059 T1212 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/control/data/index
[junit4:junit4] 2> 319060 T1212 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2e3dfb64 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec6935e5),segFN=segments_1,generation=1}
[junit4:junit4] 2> 319061 T1212 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 319062 T1212 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 319063 T1212 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 319063 T1212 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 319064 T1212 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 319064 T1212 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 319064 T1212 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 319065 T1212 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 319065 T1212 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 319065 T1212 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 319067 T1212 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 319069 T1212 oass.SolrIndexSearcher.<init> Opening Searcher@75ea2a12 main
[junit4:junit4] 2> 319069 T1212 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/control/data/tlog
[junit4:junit4] 2> 319070 T1212 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 319070 T1212 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 319074 T1213 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@75ea2a12 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 319075 T1212 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 319075 T1212 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 320168 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 320169 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39171",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:39171_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 320169 T1210 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 320169 T1210 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 320172 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 321077 T1212 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 321077 T1212 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39171 collection:control_collection shard:shard1
[junit4:junit4] 2> 321078 T1212 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 321084 T1212 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 321087 T1212 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 321087 T1212 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 321087 T1212 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:39171/collection1/
[junit4:junit4] 2> 321088 T1212 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 321088 T1212 oasc.SyncStrategy.syncToMe http://127.0.0.1:39171/collection1/ has no replicas
[junit4:junit4] 2> 321088 T1212 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:39171/collection1/
[junit4:junit4] 2> 321089 T1212 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 321675 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 321691 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 321703 T1212 oasc.ZkController.register We are http://127.0.0.1:39171/collection1/ and leader is http://127.0.0.1:39171/collection1/
[junit4:junit4] 2> 321703 T1212 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39171
[junit4:junit4] 2> 321704 T1212 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 321704 T1212 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 321705 T1212 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 321706 T1212 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 321708 T1187 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 321709 T1187 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 321710 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 321715 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 321718 T1187 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 321724 T1216 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@36004608 name:ZooKeeperConnection Watcher:127.0.0.1:48722/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 321724 T1187 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 321727 T1187 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 321733 T1187 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 321873 T1187 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 321878 T1187 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:35786
[junit4:junit4] 2> 321879 T1187 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 321880 T1187 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 321881 T1187 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370373835846
[junit4:junit4] 2> 321882 T1187 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370373835846/solr.xml
[junit4:junit4] 2> 321883 T1187 oasc.CoreContainer.<init> New CoreContainer 1117037658
[junit4:junit4] 2> 321884 T1187 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370373835846/'
[junit4:junit4] 2> 321885 T1187 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370373835846/'
[junit4:junit4] 2> 321955 T1187 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 321955 T1187 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 321956 T1187 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 321957 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 321958 T1187 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 321959 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 321960 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 321961 T1187 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 321962 T1187 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 321964 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 321972 T1187 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 321974 T1187 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:48722/solr
[junit4:junit4] 2> 321975 T1187 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 321978 T1187 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 321984 T1227 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e8fcda6e name:ZooKeeperConnection Watcher:127.0.0.1:48722 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 321985 T1187 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 321989 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 321996 T1187 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 322002 T1229 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b202a939 name:ZooKeeperConnection Watcher:127.0.0.1:48722/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 322005 T1187 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 322012 T1187 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 323019 T1187 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35786_
[junit4:junit4] 2> 323020 T1187 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:35786_
[junit4:junit4] 2> 323023 T1216 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 323023 T1209 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 323023 T1229 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 323024 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 323028 T1230 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370373835846/collection1
[junit4:junit4] 2> 323028 T1230 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 323029 T1230 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 323029 T1230 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 323030 T1230 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370373835846/collection1/'
[junit4:junit4] 2> 323031 T1230 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370373835846/collection1/lib/README' to classloader
[junit4:junit4] 2> 323031 T1230 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370373835846/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 323054 T1230 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 323083 T1230 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 323084 T1230 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 323088 T1230 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 323195 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 323196 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39171",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:39171_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 323198 T1216 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 323199 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 323198 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 323407 T1230 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 323411 T1230 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 323414 T1230 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 323425 T1230 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 323429 T1230 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 323432 T1230 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 323434 T1230 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 323434 T1230 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 323434 T1230 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 323435 T1230 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 323436 T1230 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 323436 T1230 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 323436 T1230 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370373835846/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty1/
[junit4:junit4] 2> 323437 T1230 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@9a1f7c5c
[junit4:junit4] 2> 323437 T1230 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 323438 T1230 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty1
[junit4:junit4] 2> 323438 T1230 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty1/index/
[junit4:junit4] 2> 323439 T1230 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 323439 T1230 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty1/index
[junit4:junit4] 2> 323440 T1230 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@74a9a3d3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fb8614d5),segFN=segments_1,generation=1}
[junit4:junit4] 2> 323441 T1230 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 323442 T1230 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 323443 T1230 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 323443 T1230 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 323444 T1230 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 323444 T1230 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 323445 T1230 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 323445 T1230 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 323446 T1230 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 323446 T1230 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 323447 T1230 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 323449 T1230 oass.SolrIndexSearcher.<init> Opening Searcher@40b178bf main
[junit4:junit4] 2> 323450 T1230 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty1/tlog
[junit4:junit4] 2> 323450 T1230 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 323451 T1230 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 323454 T1231 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@40b178bf main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 323455 T1230 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 323455 T1230 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 324702 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 324703 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35786",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:35786_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 324703 T1210 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 324704 T1210 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 324707 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 324707 T1216 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 324707 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 325457 T1230 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 325457 T1230 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:35786 collection:collection1 shard:shard1
[junit4:junit4] 2> 325458 T1230 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 325464 T1230 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 325466 T1230 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 325466 T1230 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 325466 T1230 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:35786/collection1/
[junit4:junit4] 2> 325467 T1230 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 325467 T1230 oasc.SyncStrategy.syncToMe http://127.0.0.1:35786/collection1/ has no replicas
[junit4:junit4] 2> 325467 T1230 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:35786/collection1/
[junit4:junit4] 2> 325468 T1230 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 326212 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 326218 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 326218 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 326218 T1216 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 326224 T1230 oasc.ZkController.register We are http://127.0.0.1:35786/collection1/ and leader is http://127.0.0.1:35786/collection1/
[junit4:junit4] 2> 326224 T1230 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35786
[junit4:junit4] 2> 326224 T1230 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 326225 T1230 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 326225 T1230 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 326226 T1230 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 326228 T1187 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 326229 T1187 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 326230 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 326340 T1187 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 326342 T1187 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:39703
[junit4:junit4] 2> 326343 T1187 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 326343 T1187 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 326344 T1187 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370373840348
[junit4:junit4] 2> 326345 T1187 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370373840348/solr.xml
[junit4:junit4] 2> 326345 T1187 oasc.CoreContainer.<init> New CoreContainer -1303085897
[junit4:junit4] 2> 326346 T1187 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370373840348/'
[junit4:junit4] 2> 326347 T1187 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370373840348/'
[junit4:junit4] 2> 326386 T1187 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 326387 T1187 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 326388 T1187 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 326388 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 326389 T1187 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 326390 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 326390 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 326391 T1187 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 326392 T1187 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 326392 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 326397 T1187 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 326398 T1187 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:48722/solr
[junit4:junit4] 2> 326399 T1187 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 326400 T1187 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 326401 T1243 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6e8abff2 name:ZooKeeperConnection Watcher:127.0.0.1:48722 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 326402 T1187 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 326403 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 326407 T1187 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 326408 T1245 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@39ce7239 name:ZooKeeperConnection Watcher:127.0.0.1:48722/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 326409 T1187 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 326412 T1187 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 327414 T1187 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39703_
[junit4:junit4] 2> 327416 T1187 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39703_
[junit4:junit4] 2> 327418 T1245 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 327418 T1229 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 327418 T1216 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 327419 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 327418 T1209 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 327420 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 327419 T1216 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 327423 T1246 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370373840348/collection1
[junit4:junit4] 2> 327424 T1246 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 327424 T1246 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 327425 T1246 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 327426 T1246 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370373840348/collection1/'
[junit4:junit4] 2> 327426 T1246 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370373840348/collection1/lib/README' to classloader
[junit4:junit4] 2> 327427 T1246 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370373840348/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 327449 T1246 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 327478 T1246 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 327479 T1246 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 327483 T1246 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 327725 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 327726 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35786",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:35786_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 327729 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 327729 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 327729 T1216 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 327731 T1245 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 327790 T1246 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 327794 T1246 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 327797 T1246 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 327807 T1246 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 327811 T1246 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 327815 T1246 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 327815 T1246 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 327816 T1246 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 327816 T1246 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 327817 T1246 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 327817 T1246 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 327818 T1246 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 327818 T1246 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1370373840348/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty2/
[junit4:junit4] 2> 327818 T1246 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@9a1f7c5c
[junit4:junit4] 2> 327819 T1246 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 327820 T1246 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty2
[junit4:junit4] 2> 327820 T1246 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty2/index/
[junit4:junit4] 2> 327820 T1246 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 327821 T1246 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty2/index
[junit4:junit4] 2> 327822 T1246 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@dbc810c1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7d18fdd1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 327822 T1246 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 327824 T1246 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 327824 T1246 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 327825 T1246 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 327825 T1246 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 327826 T1246 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 327826 T1246 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 327827 T1246 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 327827 T1246 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 327827 T1246 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 327829 T1246 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 327831 T1246 oass.SolrIndexSearcher.<init> Opening Searcher@eb91c30a main
[junit4:junit4] 2> 327831 T1246 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty2/tlog
[junit4:junit4] 2> 327832 T1246 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 327832 T1246 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 327836 T1247 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@eb91c30a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 327837 T1246 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 327837 T1246 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 329233 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 329234 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39703",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:39703_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 329234 T1210 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 329234 T1210 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 329238 T1245 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 329238 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 329238 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 329238 T1216 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 329839 T1246 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 329839 T1246 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39703 collection:collection1 shard:shard2
[junit4:junit4] 2> 329840 T1246 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 329847 T1246 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 329849 T1246 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 329850 T1246 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 329850 T1246 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:39703/collection1/
[junit4:junit4] 2> 329850 T1246 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 329851 T1246 oasc.SyncStrategy.syncToMe http://127.0.0.1:39703/collection1/ has no replicas
[junit4:junit4] 2> 329851 T1246 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:39703/collection1/
[junit4:junit4] 2> 329851 T1246 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 330743 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 330749 T1245 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 330749 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 330749 T1216 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 330749 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 330758 T1246 oasc.ZkController.register We are http://127.0.0.1:39703/collection1/ and leader is http://127.0.0.1:39703/collection1/
[junit4:junit4] 2> 330758 T1246 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39703
[junit4:junit4] 2> 330758 T1246 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 330759 T1246 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 330759 T1246 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 330760 T1246 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 330761 T1187 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 330762 T1187 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 330763 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 330863 T1187 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 330866 T1187 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:44827
[junit4:junit4] 2> 330866 T1187 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 330867 T1187 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 330868 T1187 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370373844879
[junit4:junit4] 2> 330868 T1187 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370373844879/solr.xml
[junit4:junit4] 2> 330869 T1187 oasc.CoreContainer.<init> New CoreContainer -787608267
[junit4:junit4] 2> 330870 T1187 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370373844879/'
[junit4:junit4] 2> 330870 T1187 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370373844879/'
[junit4:junit4] 2> 330910 T1187 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 330910 T1187 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 330911 T1187 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 330912 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 330912 T1187 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 330913 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 330914 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 330914 T1187 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 330915 T1187 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 330916 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 330920 T1187 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 330921 T1187 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:48722/solr
[junit4:junit4] 2> 330922 T1187 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 330923 T1187 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 330925 T1259 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10c838ad name:ZooKeeperConnection Watcher:127.0.0.1:48722 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 330925 T1187 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 330927 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 330931 T1187 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 330932 T1261 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f8db56c4 name:ZooKeeperConnection Watcher:127.0.0.1:48722/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 330932 T1187 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 330935 T1187 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 331938 T1187 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44827_
[junit4:junit4] 2> 331940 T1187 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:44827_
[junit4:junit4] 2> 331942 T1245 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 331942 T1229 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 331943 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 331943 T1216 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 331943 T1209 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 331943 T1216 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 331944 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 331943 T1261 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 331944 T1245 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 331956 T1262 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370373844879/collection1
[junit4:junit4] 2> 331957 T1262 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 331957 T1262 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 331958 T1262 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 331959 T1262 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370373844879/collection1/'
[junit4:junit4] 2> 331960 T1262 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370373844879/collection1/lib/README' to classloader
[junit4:junit4] 2> 331961 T1262 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370373844879/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 331988 T1262 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 332016 T1262 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 332018 T1262 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 332022 T1262 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 332253 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 332254 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39703",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:39703_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 332258 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 332258 T1245 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 332258 T1261 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 332258 T1216 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 332260 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 332325 T1262 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 332330 T1262 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 332333 T1262 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 332341 T1262 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 332345 T1262 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 332348 T1262 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 332349 T1262 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 332349 T1262 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 332350 T1262 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 332351 T1262 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 332351 T1262 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 332351 T1262 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 332352 T1262 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1370373844879/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty3/
[junit4:junit4] 2> 332352 T1262 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@9a1f7c5c
[junit4:junit4] 2> 332352 T1262 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 332353 T1262 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty3
[junit4:junit4] 2> 332353 T1262 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty3/index/
[junit4:junit4] 2> 332354 T1262 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 332354 T1262 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty3/index
[junit4:junit4] 2> 332355 T1262 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@43c0b060 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c3fc737b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 332356 T1262 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 332357 T1262 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 332357 T1262 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 332358 T1262 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 332358 T1262 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 332359 T1262 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 332359 T1262 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 332360 T1262 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 332360 T1262 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 332361 T1262 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 332362 T1262 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 332364 T1262 oass.SolrIndexSearcher.<init> Opening Searcher@e2f0b132 main
[junit4:junit4] 2> 332364 T1262 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty3/tlog
[junit4:junit4] 2> 332365 T1262 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 332365 T1262 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 332368 T1263 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e2f0b132 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 332370 T1262 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 332370 T1262 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 333763 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 333764 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44827",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:44827_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 333764 T1210 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 333765 T1210 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 333770 T1245 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 333770 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 333770 T1261 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 333770 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 333770 T1216 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 334372 T1262 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 334372 T1262 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:44827 collection:collection1 shard:shard1
[junit4:junit4] 2> 334375 T1262 oasc.ZkController.register We are http://127.0.0.1:44827/collection1/ and leader is http://127.0.0.1:35786/collection1/
[junit4:junit4] 2> 334376 T1262 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44827
[junit4:junit4] 2> 334376 T1262 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 334376 T1262 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C300 name=collection1 org.apache.solr.core.SolrCore@a951e063 url=http://127.0.0.1:44827/collection1 node=127.0.0.1:44827_ C300_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:44827, state=down, node_name=127.0.0.1:44827_, collection=collection1, core=collection1}
[junit4:junit4] 2> 334377 T1264 C300 P44827 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 334377 T1262 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 334377 T1264 C300 P44827 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 334378 T1264 C300 P44827 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 334378 T1264 C300 P44827 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 334378 T1187 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 334379 T1187 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 334379 T1264 C300 P44827 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 334380 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 334385 T1221 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 334459 T1187 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 334461 T1187 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:48992
[junit4:junit4] 2> 334462 T1187 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 334463 T1187 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 334463 T1187 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370373848496
[junit4:junit4] 2> 334464 T1187 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370373848496/solr.xml
[junit4:junit4] 2> 334464 T1187 oasc.CoreContainer.<init> New CoreContainer 1153301731
[junit4:junit4] 2> 334465 T1187 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370373848496/'
[junit4:junit4] 2> 334466 T1187 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370373848496/'
[junit4:junit4] 2> 334502 T1187 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 334503 T1187 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 334504 T1187 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 334504 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 334505 T1187 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 334506 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 334506 T1187 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 334507 T1187 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 334507 T1187 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 334508 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 334512 T1187 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 334513 T1187 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:48722/solr
[junit4:junit4] 2> 334514 T1187 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 334515 T1187 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 334516 T1276 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2b0e3b73 name:ZooKeeperConnection Watcher:127.0.0.1:48722 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 334517 T1187 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 334518 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 334523 T1187 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 334524 T1278 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ca0b5c8c name:ZooKeeperConnection Watcher:127.0.0.1:48722/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 334525 T1187 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 334528 T1187 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 335274 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 335275 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44827",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:44827_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 335279 T1245 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 335279 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 335279 T1278 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 335280 T1261 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 335280 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 335280 T1216 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 335386 T1221 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 335386 T1221 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=4&wt=javabin&nodeName=127.0.0.1:44827_&core=collection1} status=0 QTime=1001
[junit4:junit4] 2> 335531 T1187 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:48992_
[junit4:junit4] 2> 335533 T1187 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:48992_
[junit4:junit4] 2> 335535 T1261 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 335535 T1245 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 335536 T1216 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 335536 T1209 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 335535 T1278 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 335536 T1229 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 335536 T1216 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 335537 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 335537 T1245 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 335537 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 335537 T1261 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 335540 T1278 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 335541 T1279 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370373848496/collection1
[junit4:junit4] 2> 335542 T1279 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 335543 T1279 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 335543 T1279 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 335544 T1279 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370373848496/collection1/'
[junit4:junit4] 2> 335545 T1279 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370373848496/collection1/lib/README' to classloader
[junit4:junit4] 2> 335545 T1279 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370373848496/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 335568 T1279 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 335596 T1279 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 335598 T1279 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 335602 T1279 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 335902 T1279 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 335915 T1279 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 335919 T1279 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 335930 T1279 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 335935 T1279 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 335940 T1279 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 335941 T1279 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 335942 T1279 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 335942 T1279 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 335943 T1279 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 335944 T1279 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 335944 T1279 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 335945 T1279 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1370373848496/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty4/
[junit4:junit4] 2> 335945 T1279 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@9a1f7c5c
[junit4:junit4] 2> 335946 T1279 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 335946 T1279 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty4
[junit4:junit4] 2> 335947 T1279 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty4/index/
[junit4:junit4] 2> 335947 T1279 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 335948 T1279 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty4/index
[junit4:junit4] 2> 335949 T1279 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@27b2d3ee lockFactory=org.apache.lucene.store.NativeFSLockFactory@a4b1f41a),segFN=segments_1,generation=1}
[junit4:junit4] 2> 335950 T1279 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 335951 T1279 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 335951 T1279 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 335952 T1279 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 335953 T1279 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 335953 T1279 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 335954 T1279 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 335954 T1279 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 335955 T1279 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 335955 T1279 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 335956 T1279 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 335958 T1279 oass.SolrIndexSearcher.<init> Opening Searcher@7924e315 main
[junit4:junit4] 2> 335959 T1279 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty4/tlog
[junit4:junit4] 2> 335960 T1279 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 335960 T1279 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 335966 T1280 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7924e315 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 335967 T1279 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 335968 T1279 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 336784 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 336784 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48992",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:48992_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 336785 T1210 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 336785 T1210 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 336788 T1245 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> 336788 T1278 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> 336788 T1261 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> 336788 T1229 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> 336788 T1216 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> 336788 T1209 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> 336969 T1279 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 336970 T1279 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:48992 collection:collection1 shard:shard2
[junit4:junit4] 2> 336972 T1279 oasc.ZkController.register We are http://127.0.0.1:48992/collection1/ and leader is http://127.0.0.1:39703/collection1/
[junit4:junit4] 2> 336973 T1279 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:48992
[junit4:junit4] 2> 336973 T1279 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 336974 T1279 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C301 name=collection1 org.apache.solr.core.SolrCore@a3155da1 url=http://127.0.0.1:48992/collection1 node=127.0.0.1:48992_ C301_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:48992, state=down, node_name=127.0.0.1:48992_, collection=collection1, core=collection1}
[junit4:junit4] 2> 336974 T1281 C301 P48992 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 336975 T1279 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 336975 T1281 C301 P48992 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 336976 T1281 C301 P48992 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 336976 T1281 C301 P48992 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 336976 T1187 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 336977 T1187 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 336977 T1281 C301 P48992 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 336978 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 336985 T1187 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 336986 T1238 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 336987 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 336993 T1218 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370373835846/onenodecollectioncore
[junit4:junit4] 2> 336994 T1218 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4] 2> 336995 T1218 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4] 2> 336996 T1218 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 336998 T1218 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 336999 T1218 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4] 2> 337001 T1218 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4] 2> 337002 T1218 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370373835846/onenodecollectioncore/'
[junit4:junit4] 2> 337038 T1218 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 337084 T1218 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 337086 T1218 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 337093 T1218 oass.IndexSchema.readSchema [onenodecollectioncore] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C302 name=collection1 org.apache.solr.core.SolrCore@a951e063 url=http://127.0.0.1:44827/collection1 node=127.0.0.1:44827_ C302_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:44827, state=recovering, node_name=127.0.0.1:44827_, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4] 2> 337387 T1264 C302 P44827 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:35786/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 337388 T1264 C302 P44827 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:44827 START replicas=[http://127.0.0.1:35786/collection1/] nUpdates=100
[junit4:junit4] 2> 337388 T1264 C302 P44827 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 337389 T1264 C302 P44827 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 337389 T1264 C302 P44827 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 337390 T1264 C302 P44827 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 337390 T1264 C302 P44827 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 337390 T1264 C302 P44827 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:35786/collection1/. core=collection1
[junit4:junit4] 2> 337391 T1264 C302 P44827 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C303 name=collection1 org.apache.solr.core.SolrCore@e6de72b8 url=http://127.0.0.1:35786/collection1 node=127.0.0.1:35786_ C303_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:35786, state=active, node_name=127.0.0.1:35786_, collection=collection1, shard=shard1, core=collection1, leader=true}
[junit4:junit4] 2> 337393 T1224 C303 P35786 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 337397 T1221 C303 P35786 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 337399 T1221 C303 P35786 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@74a9a3d3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fb8614d5),segFN=segments_1,generation=1}
[junit4:junit4] 2> 337399 T1221 C303 P35786 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 337400 T1221 C303 P35786 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@74a9a3d3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fb8614d5),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@74a9a3d3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fb8614d5),segFN=segments_2,generation=2}
[junit4:junit4] 2> 337401 T1221 C303 P35786 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 337402 T1221 C303 P35786 oass.SolrIndexSearcher.<init> Opening Searcher@76de0a2 realtime
[junit4:junit4] 2> 337402 T1221 C303 P35786 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 337403 T1221 C303 P35786 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 6
[junit4:junit4] 2> 337404 T1264 C302 P44827 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 337404 T1264 C302 P44827 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 337406 T1224 C303 P35786 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 337406 T1224 C303 P35786 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 337407 T1264 C302 P44827 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 337407 T1264 C302 P44827 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 337408 T1264 C302 P44827 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 337410 T1221 C303 P35786 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 337410 T1264 C302 P44827 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 337411 T1264 C302 P44827 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty3/index.20130604235411523
[junit4:junit4] 2> 337412 T1264 C302 P44827 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@86c8bb69 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5543839c) fullCopy=false
[junit4:junit4] 2> 337414 T1225 C303 P35786 oasc.SolrCore.execute [collection1] webapp= path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=0
[junit4:junit4] 2> 337415 T1264 C302 P44827 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 337416 T1264 C302 P44827 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 337416 T1264 C302 P44827 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 337417 T1264 C302 P44827 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@43c0b060 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c3fc737b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@43c0b060 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c3fc737b),segFN=segments_2,generation=2}
[junit4:junit4] 2> 337418 T1264 C302 P44827 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 337419 T1264 C302 P44827 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 337419 T1264 C302 P44827 oass.SolrIndexSearcher.<init> Opening Searcher@53a9de18 main
[junit4:junit4] 2> 337420 T1263 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@53a9de18 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 337421 T1264 C302 P44827 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty3/index.20130604235411523 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty3/index.20130604235411523;done=true>>]
[junit4:junit4] 2> 337421 T1264 C302 P44827 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty3/index.20130604235411523
[junit4:junit4] 2> 337422 T1264 C302 P44827 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty3/index.20130604235411523
[junit4:junit4] 2> 337422 T1264 C302 P44827 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 337422 T1264 C302 P44827 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 337423 T1264 C302 P44827 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 337423 T1264 C302 P44827 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 337425 T1264 C302 P44827 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 337468 T1218 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 337473 T1218 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 337476 T1218 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 337485 T1218 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 337489 T1218 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 337493 T1218 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 337494 T1218 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 337495 T1218 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 337496 T1218 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 337497 T1218 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 337498 T1218 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 337498 T1218 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 337499 T1218 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1370373835846/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370373832416/onenodecollection/
[junit4:junit4] 2> 337500 T1218 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@9a1f7c5c
[junit4:junit4] 2> 337500 T1218 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 337502 T1218 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370373832416/onenodecollection
[junit4:junit4] 2> 337502 T1218 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370373832416/onenodecollection/index/
[junit4:junit4] 2> 337503 T1218 oasc.SolrCore.initIndex WARN [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370373832416/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 337504 T1218 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370373832416/onenodecollection/index
[junit4:junit4] 2> 337506 T1218 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3c4fe9e9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3276396c),segFN=segments_1,generation=1}
[junit4:junit4] 2> 337506 T1218 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 337508 T1218 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 337509 T1218 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 337510 T1218 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 337511 T1218 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 337511 T1218 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 337512 T1218 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 337513 T1218 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 337513 T1218 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 337514 T1218 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 337516 T1218 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 337518 T1218 oass.SolrIndexSearcher.<init> Opening Searcher@db31dfad main
[junit4:junit4] 2> 337519 T1218 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370373832416/onenodecollection/tlog
[junit4:junit4] 2> 337520 T1218 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 337520 T1218 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 337524 T1285 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@db31dfad main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 337525 T1218 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4] 2> 338293 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 338294 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48992",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:48992_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 338297 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44827",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:44827_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 338299 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35786",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:35786_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 338299 T1210 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4] 2> 338299 T1210 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 338303 T1245 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> 338303 T1261 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> 338303 T1278 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> 338303 T1229 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> 338303 T1216 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> 338303 T1209 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> 338527 T1218 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4] 2> 338528 T1218 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:35786 collection:onenodecollection shard:shard1
[junit4:junit4] 2> 338529 T1218 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4] 2> 338535 T1218 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 338538 T1218 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 338539 T1218 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 338540 T1218 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:35786/onenodecollectioncore/
[junit4:junit4] 2> 338541 T1218 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 338542 T1218 oasc.SyncStrategy.syncToMe http://127.0.0.1:35786/onenodecollectioncore/ has no replicas
[junit4:junit4] 2> 338543 T1218 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:35786/onenodecollectioncore/
[junit4:junit4] 2> 338544 T1218 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4] 2> 338988 T1238 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 338989 T1238 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=5&wt=javabin&nodeName=127.0.0.1:48992_&core=collection1} status=0 QTime=2003
[junit4:junit4] 2> 339809 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 339816 T1245 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> 339816 T1209 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> 339816 T1278 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> 339816 T1229 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> 339816 T1216 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> 339816 T1261 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> 339854 T1218 oasc.ZkController.register We are http://127.0.0.1:35786/onenodecollectioncore/ and leader is http://127.0.0.1:35786/onenodecollectioncore/
[junit4:junit4] 2> 339855 T1218 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:35786
[junit4:junit4] 2> 339855 T1218 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 339856 T1218 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4] 2> 339858 T1218 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 339859 T1218 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370373832416/onenodecollection&action=CREATE&version=2&numShards=1&name=onenodecollectioncore&wt=javabin&roles=none&collection=onenodecollection} status=0 QTime=2866
[junit4:junit4] 2> 339859 T1187 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 339861 T1187 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 340863 T1187 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C304 name=collection1 org.apache.solr.core.SolrCore@a3155da1 url=http://127.0.0.1:48992/collection1 node=127.0.0.1:48992_ C304_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:48992, state=recovering, node_name=127.0.0.1:48992_, collection=collection1, shard=shard2, core=collection1}
[junit4:junit4] 2> 340990 T1281 C304 P48992 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:39703/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 340990 T1281 C304 P48992 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:48992 START replicas=[http://127.0.0.1:39703/collection1/] nUpdates=100
[junit4:junit4] 2> 340991 T1281 C304 P48992 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 340991 T1281 C304 P48992 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 340991 T1281 C304 P48992 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 340991 T1281 C304 P48992 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 340991 T1281 C304 P48992 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 340992 T1281 C304 P48992 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:39703/collection1/. core=collection1
[junit4:junit4] 2> 340992 T1281 C304 P48992 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C305 name=collection1 org.apache.solr.core.SolrCore@8497069f url=http://127.0.0.1:39703/collection1 node=127.0.0.1:39703_ C305_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:39703, state=active, node_name=127.0.0.1:39703_, collection=collection1, shard=shard2, core=collection1, leader=true}
[junit4:junit4] 2> 341001 T1240 C305 P39703 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 341002 T1238 C305 P39703 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 341004 T1240 C305 P39703 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@dbc810c1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7d18fdd1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 341005 T1240 C305 P39703 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 341006 T1240 C305 P39703 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@dbc810c1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7d18fdd1),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@dbc810c1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7d18fdd1),segFN=segments_2,generation=2}
[junit4:junit4] 2> 341007 T1240 C305 P39703 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 341008 T1240 C305 P39703 oass.SolrIndexSearcher.<init> Opening Searcher@2c1bfa16 realtime
[junit4:junit4] 2> 341009 T1240 C305 P39703 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 341010 T1240 C305 P39703 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 9
[junit4:junit4] 2> 341011 T1281 C304 P48992 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 341012 T1281 C304 P48992 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 341013 T1239 C305 P39703 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 341014 T1239 C305 P39703 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 341014 T1281 C304 P48992 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 341015 T1281 C304 P48992 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 341015 T1281 C304 P48992 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 341016 T1238 C305 P39703 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 341017 T1281 C304 P48992 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 341018 T1281 C304 P48992 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty4/index.20130604235415130
[junit4:junit4] 2> 341018 T1281 C304 P48992 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@24039c9e lockFactory=org.apache.lucene.store.NativeFSLockFactory@c4ffb6a5) fullCopy=false
[junit4:junit4] 2> 341020 T1240 C305 P39703 oasc.SolrCore.execute [collection1] webapp= path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=0
[junit4:junit4] 2> 341021 T1281 C304 P48992 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 341022 T1281 C304 P48992 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 341022 T1281 C304 P48992 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 341023 T1281 C304 P48992 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@27b2d3ee lockFactory=org.apache.lucene.store.NativeFSLockFactory@a4b1f41a),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@27b2d3ee lockFactory=org.apache.lucene.store.NativeFSLockFactory@a4b1f41a),segFN=segments_2,generation=2}
[junit4:junit4] 2> 341023 T1281 C304 P48992 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 341024 T1281 C304 P48992 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 341024 T1281 C304 P48992 oass.SolrIndexSearcher.<init> Opening Searcher@ccc7bb42 main
[junit4:junit4] 2> 341025 T1280 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ccc7bb42 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 341026 T1281 C304 P48992 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty4/index.20130604235415130 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty4/index.20130604235415130;done=true>>]
[junit4:junit4] 2> 341026 T1281 C304 P48992 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty4/index.20130604235415130
[junit4:junit4] 2> 341027 T1281 C304 P48992 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty4/index.20130604235415130
[junit4:junit4] 2> 341027 T1281 C304 P48992 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 341027 T1281 C304 P48992 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 341027 T1281 C304 P48992 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 341028 T1281 C304 P48992 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 341029 T1281 C304 P48992 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 341321 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 341322 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35786",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:35786__onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:35786_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 341326 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48992",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:48992_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 341329 T1278 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> 341329 T1209 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> 341329 T1261 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> 341329 T1216 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> 341329 T1245 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> 341329 T1229 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> 341865 T1187 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 341866 T1187 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4] 2> 341867 T1187 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 341876 T1187 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 341878 T1289 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e6d5f13d name:ZooKeeperConnection Watcher:127.0.0.1:48722 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 341878 T1187 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 341911 T1187 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 39171
[junit4:junit4] 2> 341912 T1187 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-1253800384
[junit4:junit4] 2> 342835 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 342836 T1210 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39171",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:39171_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 342840 T1245 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> 342840 T1261 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> 342840 T1229 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> 342840 T1209 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> 342840 T1278 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> 343914 T1187 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 343914 T1187 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 343916 T1187 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@c8198606
[junit4:junit4] 2> 343919 T1187 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 343920 T1187 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 343920 T1187 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 343921 T1187 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 343922 T1187 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 343922 T1187 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 343923 T1187 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/control/data [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/control/data;done=false>>]
[junit4:junit4] 2> 343923 T1187 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/control/data
[junit4:junit4] 2> 343924 T1187 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/control/data/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/control/data/index;done=false>>]
[junit4:junit4] 2> 343925 T1187 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/control/data/index
[junit4:junit4] 2> 343925 T1210 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89808819481411587-127.0.0.1:39171_-n_0000000000) am no longer a leader.
[junit4:junit4] 2> 343926 T1245 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 343927 T1278 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 343926 T1261 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 343927 T1229 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 343927 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 343928 T1245 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 343928 T1278 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 343929 T1261 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 343930 T1229 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 343931 T1229 oasc.Overseer.start Overseer (id=89808819481411590-127.0.0.1:35786_-n_0000000001) starting
[junit4:junit4] 2> 343934 T1291 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 343934 T1290 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 343936 T1290 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 343936 T1290 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39171",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:39171_",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 343939 T1278 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 343939 T1261 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 343939 T1245 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 343939 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 343947 T1187 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 343999 T1187 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 35786
[junit4:junit4] 2> 343999 T1187 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1117037658
[junit4:junit4] 2> 345226 T1209 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 345227 T1209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 345227 T1209 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 345443 T1290 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 345444 T1290 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35786",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:35786__onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:35786_",
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 345447 T1290 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35786",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:35786_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 345453 T1245 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 345453 T1278 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 345453 T1261 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 345454 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 347002 T1187 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 347003 T1187 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 347004 T1187 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4] 2> 347006 T1187 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@e6de72b8
[junit4:junit4] 2> 347010 T1187 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 347010 T1187 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 347011 T1187 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 347011 T1187 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 347012 T1187 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 347013 T1187 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 347014 T1187 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty1 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty1;done=false>>]
[junit4:junit4] 2> 347014 T1187 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty1
[junit4:junit4] 2> 347015 T1187 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty1/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty1/index;done=false>>]
[junit4:junit4] 2> 347015 T1187 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1370373832416/jetty1/index
[junit4:junit4] 2> 347016 T1187 oasc.SolrCore.close [onenodecollectioncore] CLOSING SolrCore org.apache.solr.core.SolrCore@b3cf6471
[junit4:junit4] 2> 347020 T1187 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 347021 T1187 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 347021 T1187 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 347022 T1187 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 347023 T1187 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4] 2> 347023 T1187 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 347024 T1187 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370373832416/onenodecollection/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370373832416/onenodecollection/index;done=false>>]
[junit4:junit4] 2> 347024 T1187 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370373832416/onenodecollection/index
[junit4:junit4] 2> 347025 T1187 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370373832416/onenodecollection [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370373832416/onenodecollection;done=false>>]
[junit4:junit4] 2> 347026 T1187 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1370373832416/onenodecollection
[junit4:junit4] 2> 347027 T1290 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89808819481411590-127.0.0.1:35786_-n_0000000001) am no longer a leader.
[junit4:junit4] 2> 347027 T1278 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 347028 T1229 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 347028 T1229 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 347028 T1229 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 347028 T1245 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 347030 T1261 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 347030 T1278 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 347031 T1245 oasc.Overseer.start Overseer (id=89808819481411592-127.0.0.1:39703_-n_0000000002) starting
[junit4:junit4] 2> 347031 T1261 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4] 2> 347032 T1261 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4] 2> 347032 T1261 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 347032 T1261 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:44827/collec
[...truncated too long message...]
rrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4] 2> at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:780)
[junit4:junit4] 2>
[junit4:junit4] 2> 522982 T1807 oas.SolrTestCaseJ4.tearDown ###Ending testCommitWithin
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=HardAutoCommitTest -Dtests.method=testCommitWithin -Dtests.seed=98680BD6ECD54C6C -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_US -Dtests.timezone=Europe/Prague -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR 4.51s J1 | HardAutoCommitTest.testCommitWithin <<<
[junit4:junit4] > Throwable #1: java.lang.RuntimeException: Exception during query
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([98680BD6ECD54C6C:22BA64AE6FFBA279]:0)
[junit4:junit4] > at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:527)
[junit4:junit4] > at org.apache.solr.update.HardAutoCommitTest.testCommitWithin(HardAutoCommitTest.java:79)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:780)
[junit4:junit4] > Caused by: java.lang.RuntimeException: REQUEST FAILED: xpath=//result[@numFound=0]
[junit4:junit4] > xml response was: <?xml version="1.0" encoding="UTF-8"?>
[junit4:junit4] > <response>
[junit4:junit4] > <lst name="responseHeader"><int name="status">0</int><int name="QTime">3499</int></lst><result name="response" numFound="1" start="0"><doc><int name="id">529</int><int name="range_facet_si">529</int><arr name="range_facet_l"><long>529</long></arr><arr name="range_facet_sl"><long>529</long></arr><arr name="field_t"><str>what's inside?</str></arr><arr name="subject"><str>info</str></arr><long name="_version_">1436941322610016256</long><int name="intDefault">42</int><date name="timestamp">2013-06-04T19:27:13.556Z</date><arr name="multiDefault"><str>muLti-Default</str></arr></doc></result>
[junit4:junit4] > </response>
[junit4:junit4] > request was:q=id:529&start=0&qt=standard&version=2.2&rows=20
[junit4:junit4] > at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:520)
[junit4:junit4] > ... 41 more
[junit4:junit4] 2> 522991 T1807 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 522992 T1807 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-183084572
[junit4:junit4] 2> 522992 T1807 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@bb8f792b
[junit4:junit4] 2> 522999 T1807 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=1,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=1,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 523000 T1807 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 523000 T1807 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 523000 T1807 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 523001 T1807 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 523002 T1807 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 523002 T1807 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-HardAutoCommitTest-1370374032003 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-HardAutoCommitTest-1370374032003;done=false>>]
[junit4:junit4] 2> 523003 T1807 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-HardAutoCommitTest-1370374032003
[junit4:junit4] 2> 523003 T1807 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-HardAutoCommitTest-1370374032003/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-HardAutoCommitTest-1370374032003/index;done=false>>]
[junit4:junit4] 2> 523004 T1807 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-HardAutoCommitTest-1370374032003/index
[junit4:junit4] 2> NOTE: test params are: codec=Lucene41, sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=es_US, timezone=Europe/Prague
[junit4:junit4] 2> NOTE: Linux 3.2.0-45-generic x86/IBM Corporation 1.7.0 (32-bit)/cpus=8,threads=1,free=42129152,total=182583296
[junit4:junit4] 2> NOTE: All tests run in this JVM: [OutputWriterTest, TestPartialUpdateDeduplication, TestJmxIntegration, TestLazyCores, LeaderElectionIntegrationTest, BadIndexSchemaTest, TestReload, TestFoldingMultitermQuery, TestDistributedGrouping, TestIndexingPerformance, TestNumberUtils, TestUpdate, DirectUpdateHandlerTest, TestFieldTypeResource, ZkSolrClientTest, SolrCmdDistributorTest, NoCacheHeaderTest, TestReloadAndDeleteDocs, JSONWriterTest, SolrIndexConfigTest, RequiredFieldsTest, DistanceFunctionTest, SpellCheckCollatorTest, StandardRequestHandlerTest, TestAnalyzedSuggestions, TestCollationField, DocValuesMultiTest, StatsComponentTest, TestCSVResponseWriter, TestCoreDiscovery, TestMergePolicyConfig, IndexBasedSpellCheckerTest, TestCodecSupport, TestSolrJ, TestFieldTypeCollectionResource, XmlUpdateRequestHandlerTest, DirectSolrSpellCheckerTest, HighlighterTest, MultiTermTest, DefaultValueUpdateProcessorTest, TestArbitraryIndexDir, TestZkChroot, TestManagedSchema, TestUtils, TestDistributedSearch, SpellPossibilityIteratorTest, TestJmxMonitoredMap, XsltUpdateRequestHandlerTest, HighlighterConfigTest, TestStressLucene, AliasIntegrationTest, DateMathParserTest, SuggesterTSTTest, ZkNodePropsTest, TestSchemaNameResource, DOMUtilTest, TestDefaultSimilarityFactory, RequestHandlersTest, TestRangeQuery, BasicDistributedZk2Test, TestSchemaSimilarityResource, TestStressReorder, DisMaxRequestHandlerTest, CurrencyFieldXmlFileTest, TestFieldCollectionResource, QueryResultKeyTest, TestOmitPositions, TestRandomFaceting, TestIndexSearcher, SolrPluginUtilsTest, SolrRequestParserTest, HardAutoCommitTest]
[junit4:junit4] Completed on J1 in 5.13s, 1 test, 1 error <<< FAILURES!
[...truncated 532 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:386: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:379: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1243: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:887: There were test failures: 297 suites, 1238 tests, 2 errors, 1 failure, 14 ignored (8 assumptions)
Total time: 44 minutes 22 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure