Return-Path: X-Original-To: apmail-lucene-dev-archive@www.apache.org Delivered-To: apmail-lucene-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id F354BF593 for ; Sun, 28 Apr 2013 03:45:04 +0000 (UTC) Received: (qmail 18493 invoked by uid 500); 28 Apr 2013 03:45:02 -0000 Delivered-To: apmail-lucene-dev-archive@lucene.apache.org Received: (qmail 18016 invoked by uid 500); 28 Apr 2013 03:44:57 -0000 Mailing-List: contact dev-help@lucene.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@lucene.apache.org Delivered-To: mailing list dev@lucene.apache.org Received: (qmail 17801 invoked by uid 99); 28 Apr 2013 03:44:47 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 28 Apr 2013 03:44:47 +0000 X-ASF-Spam-Status: No, hits=0.0 required=5.0 tests=NORMAL_HTTP_TO_IP,SPF_PASS,WEIRD_PORT X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of jenkins@thetaphi.de designates 188.138.97.18 as permitted sender) Received: from [188.138.97.18] (HELO mail.sd-datasolutions.de) (188.138.97.18) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 28 Apr 2013 03:44:37 +0000 Received: from serv1 (localhost.localdomain [127.0.0.1]) by mail.sd-datasolutions.de (Postfix) with ESMTP id 9BB3514AA011 for ; Sun, 28 Apr 2013 03:44:15 +0000 (UTC) Date: Sun, 28 Apr 2013 03:43:55 +0000 (UTC) From: Policeman Jenkins Server To: dev@lucene.apache.org Message-ID: <1932128778.117.1367120655035.JavaMail.jenkins@serv1.sd-datasolutions.de> In-Reply-To: <1621168096.103.1367094972166.JavaMail.jenkins@serv1.sd-datasolutions.de> References: <1621168096.103.1367094972166.JavaMail.jenkins@serv1.sd-datasolutions.de> Subject: [JENKINS] Lucene-Solr-trunk-MacOSX (64bit/jdk1.7.0) - Build # 426 - Still Failing! MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----=_Part_116_1450143248.1367120635399" X-Jenkins-Job: Lucene-Solr-trunk-MacOSX X-Jenkins-Result: FAILURE X-Virus-Checked: Checked by ClamAV on apache.org ------=_Part_116_1450143248.1367120635399 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-MacOSX/426/ Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC 2 tests failed. REGRESSION: org.apache.solr.cloud.BasicDistributedZkTest.testDistribSearch Error Message: Server at http://127.0.0.1:50249/collection1 returned non ok status:500, me= ssage:Server Error Stack Trace: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Serve= r at http://127.0.0.1:50249/collection1 returned non ok status:500, message= :Server Error =09at __randomizedtesting.SeedInfo.seed([36C481287727D9FB:B7220F300078B9C7]= :0) =09at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServ= er.java:385) =09at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServ= er.java:180) =09at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(Ab= stractUpdateRequest.java:117) =09at org.apache.solr.BaseDistributedSearchTestCase.add(BaseDistributedSear= chTestCase.java:441) =09at org.apache.solr.cloud.BasicDistributedZkTest.testUpdateProcessorsRunO= nlyOnce(BasicDistributedZkTest.java:580) =09at org.apache.solr.cloud.BasicDistributedZkTest.doTest(BasicDistributedZ= kTest.java:332) =09at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseD= istributedSearchTestCase.java:815) =09at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) =09at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.= java:57) =09at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces= sorImpl.java:43) =09at java.lang.reflect.Method.invoke(Method.java:601) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(Randomized= Runner.java:1559) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(Random= izedRunner.java:79) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(Random= izedRunner.java:737) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(Random= izedRunner.java:773) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(Random= izedRunner.java:787) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$= 1.evaluate(SystemPropertiesRestoreRule.java:53) =09at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRu= leSetupTeardownChained.java:50) =09at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFi= eldCacheSanity.java:51) =09at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBef= oreAfterRule.java:46) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRul= e$1.evaluate(SystemPropertiesInvariantRule.java:55) =09at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleT= hreadAndTestName.java:49) =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(Test= RuleIgnoreAfterMaxFailures.java:70) =09at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFai= lure.java:48) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.= run(ThreadLeakControl.java:358) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTa= sk(ThreadLeakControl.java:782) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(Threa= dLeakControl.java:442) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(Ran= domizedRunner.java:746) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(Random= izedRunner.java:648) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(Random= izedRunner.java:682) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(Random= izedRunner.java:693) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$= 1.evaluate(SystemPropertiesRestoreRule.java:53) =09at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBef= oreAfterRule.java:46) =09at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStor= eClassName.java:42) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRul= e$1.evaluate(SystemPropertiesInvariantRule.java:55) =09at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMeth= odsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39) =09at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMeth= odsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRule= AssertionsRequired.java:43) =09at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFai= lure.java:48) =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(Test= RuleIgnoreAfterMaxFailures.java:70) =09at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIg= noreTestSuites.java:55) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.= run(ThreadLeakControl.java:358) =09at java.lang.Thread.run(Thread.java:722) FAILED: org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testDistribS= earch Error Message: There are still nodes recoverying - waited for 230 seconds Stack Trace: java.lang.AssertionError: There are still nodes recoverying - waited for 23= 0 seconds =09at __randomizedtesting.SeedInfo.seed([36C481287727D9FB:B7220F300078B9C7]= :0) =09at org.junit.Assert.fail(Assert.java:93) =09at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFi= nish(AbstractDistribZkTestBase.java:173) =09at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFi= nish(AbstractDistribZkTestBase.java:131) =09at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFi= nish(AbstractDistribZkTestBase.java:126) =09at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollections= API(CollectionsAPIDistributedZkTest.java:511) =09at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.doTest(Collecti= onsAPIDistributedZkTest.java:145) =09at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseD= istributedSearchTestCase.java:815) =09at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) =09at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.= java:57) =09at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces= sorImpl.java:43) =09at java.lang.reflect.Method.invoke(Method.java:601) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(Randomized= Runner.java:1559) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(Random= izedRunner.java:79) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(Random= izedRunner.java:737) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(Random= izedRunner.java:773) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(Random= izedRunner.java:787) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$= 1.evaluate(SystemPropertiesRestoreRule.java:53) =09at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRu= leSetupTeardownChained.java:50) =09at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFi= eldCacheSanity.java:51) =09at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBef= oreAfterRule.java:46) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRul= e$1.evaluate(SystemPropertiesInvariantRule.java:55) =09at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleT= hreadAndTestName.java:49) =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(Test= RuleIgnoreAfterMaxFailures.java:70) =09at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFai= lure.java:48) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.= run(ThreadLeakControl.java:358) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTa= sk(ThreadLeakControl.java:782) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(Threa= dLeakControl.java:442) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(Ran= domizedRunner.java:746) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(Random= izedRunner.java:648) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(Random= izedRunner.java:682) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(Random= izedRunner.java:693) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$= 1.evaluate(SystemPropertiesRestoreRule.java:53) =09at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBef= oreAfterRule.java:46) =09at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStor= eClassName.java:42) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRul= e$1.evaluate(SystemPropertiesInvariantRule.java:55) =09at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMeth= odsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39) =09at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMeth= odsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRule= AssertionsRequired.java:43) =09at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFai= lure.java:48) =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(Test= RuleIgnoreAfterMaxFailures.java:70) =09at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIg= noreTestSuites.java:55) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.= run(ThreadLeakControl.java:358) =09at java.lang.Thread.run(Thread.java:722) Build Log: [...truncated 9332 lines...] [junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZkTest [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.164; org.apache.solr.BaseD= istributedSearchTestCase; Setting hostContext system property: / [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.174; org.apache.solr.SolrT= estCaseJ4; ###Starting testDistribSearch [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.177; org.apache.solr.cloud= .ZkTestServer; STARTING ZK TEST SERVER [junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0 [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.179; org.apache.solr.cloud= .ZkTestServer$ZKServerMain; Starting server [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.280; org.apache.solr.cloud= .ZkTestServer; start zk server on port:50232 [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.286; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.301; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@3b36f290 name:ZooKeeperConnection Watcher:127.0.0.1:50232 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.301; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.302; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /solr [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.316; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.321; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@26546c0 name:ZooKeeperConnection Watcher:127.0.0.1:50232/solr got ev= ent WatchedEvent state:SyncConnected type:None path:null path:null type:Non= e [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.322; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.322; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.331; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/shards [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.345; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.352; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/shards [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.360; org.apache.solr.cloud= .AbstractZkTestCase; put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr= -trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrcon= fig-tlog.xml to /configs/conf1/solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.361; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.373; org.apache.solr.cloud= .AbstractZkTestCase; put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr= -trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/schema.= xml to /configs/conf1/schema.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.374; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.383; org.apache.solr.cloud= .AbstractZkTestCase; put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr= -trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/stopwor= ds.txt to /configs/conf1/stopwords.txt [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.384; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.393; org.apache.solr.cloud= .AbstractZkTestCase; put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr= -trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/protwor= ds.txt to /configs/conf1/protwords.txt [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.394; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.400; org.apache.solr.cloud= .AbstractZkTestCase; put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr= -trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/currenc= y.xml to /configs/conf1/currency.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.401; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.417; org.apache.solr.cloud= .AbstractZkTestCase; put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr= -trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/open-ex= change-rates.json to /configs/conf1/open-exchange-rates.json [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.418; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.427; org.apache.solr.cloud= .AbstractZkTestCase; put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr= -trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/mapping= -ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.429; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.437; org.apache.solr.cloud= .AbstractZkTestCase; put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr= -trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/old_syn= onyms.txt to /configs/conf1/old_synonyms.txt [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.439; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.448; org.apache.solr.cloud= .AbstractZkTestCase; put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr= -trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/synonym= s.txt to /configs/conf1/synonyms.txt [junit4:junit4] 1> INFO - 2013-04-28 03:10:47.450; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.105; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.117; org.eclipse.jetty.ser= ver.AbstractConnector; Started SelectChannelConnector@127.0.0.1:50235 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.118; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.119; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.119; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /Users/jenkins/je= nkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0= /./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1367118647461 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.120; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /Users/jenkins/jen= kins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/= ./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1367118647461/s= olr.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.120; org.apache.solr.core.= CoreContainer; New CoreContainer 1881613238 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.121; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/Users/jenkins/jenki= ns-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./= org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1367118647461/' [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.122; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/Users/jenkins/j= enkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1367118647461= /' [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.347; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.348; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.348; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.349; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.349; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.350; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.351; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.352; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.352; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.353; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= sPerHost=3D20&maxConnections=3D10000&socketTimeout=3D120000&connTimeout=3D1= 5000&retry=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.382; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.383; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:50232/solr [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.384; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.388; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.403; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@4c9168e7 name:ZooKeeperConnection Watcher:127.0.0.1:50232 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.404; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.409; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D500&maxConnectionsPerHost=3D16&socketTimeout=3D120000&connTimeout=3D150= 00 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.435; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.440; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@1a70b3f2 name:ZooKeeperConnection Watcher:127.0.0.1:50232/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.440; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.444; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/queue [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.455; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/collection-queue-work [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.463; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.470; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:502= 35_ [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.480; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:50235_ [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.490; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer_elect/election [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.503; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer_elect/leader [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.509; org.apache.solr.cloud= .Overseer; Overseer (id=3D89595487662243843-127.0.0.1:50235_-n_0000000000) = starting [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.519; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/queue-work [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.529; org.apache.solr.cloud= .OverseerCollectionProcessor; Process current queue of collection creations [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.533; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /clusterstate.json [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.542; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /aliases.json [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.551; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.569; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /Users/je= nkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core= /test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-136711= 8647461/collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.570; org.apache.solr.cloud= .ZkController; Check for collection zkNode:control_collection [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.570; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Starting to work on the main queue [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.573; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.573; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/control_collection [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.578; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/Users/jenkins/j= enkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1367118647461= /collection1/' [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.580; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/Users/jenkins/jenkins-slave/workspace/Luc= ene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.Ba= sicDistributedZkTest-controljetty-1367118647461/collection1/lib/classes/' t= o classloader [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.580; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/Users/jenkins/jenkins-slave/workspace/Luc= ene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.Ba= sicDistributedZkTest-controljetty-1367118647461/collection1/lib/README' to = classloader [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.697; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_50 [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.794; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.797; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:48.805; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.799; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.815; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.821; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.864; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.872; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.881; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-28 03:10:49.884; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-28 03:10:49.885; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.885; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-28 03:10:49.888; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-28 03:10:49.889; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.889; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.890; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slav= e/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apa= che.solr.cloud.BasicDistributedZkTest-controljetty-1367118647461/collection= 1/, dataDir=3D./org.apache.solr.cloud.BasicDistributedZkTest-1367118647176/= control/data/ [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.890; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@35d6593a [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.891; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.892; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.B= asicDistributedZkTest-1367118647176/control/data [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.893; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.BasicDistributedZkTest-1367118647176/control/data/index/ [junit4:junit4] 1> WARN - 2013-04-28 03:10:49.894; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Basic= DistributedZkTest-1367118647176/control/data/index' doesn't exist. Creating= new index... [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.902; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.B= asicDistributedZkTest-1367118647176/control/data/index [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.911; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927455tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@109ebd74),segFN=3Dsegments_1,gene= ration=3D1} [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.911; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.915; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.916; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.917; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.918; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.919; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.919; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.919; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.922; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.922; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.943; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.959; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@6dee12d0 main [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.965; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Bas= icDistributedZkTest-1367118647176/control/data/tlog [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.967; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.967; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.971; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@6dee12d0 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.973; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-28 03:10:49.973; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-28 03:10:50.082; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:50.084; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"1", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"control_collection", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:50235_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:50235"} [junit4:junit4] 1> INFO - 2013-04-28 03:10:50.084; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Create collection control_collection with nu= mShards 1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:50.084; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:50.094; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 1) [junit4:junit4] 1> INFO - 2013-04-28 03:10:50.977; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:50.977; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :50235 collection:control_collection shard:shard1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:50.980; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elec= t/shard1/election [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.009; org.apache.solr.cloud= .ShardLeaderElectionContext; Running the leader process. [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.016; org.apache.solr.cloud= .ShardLeaderElectionContext; Enough replicas found to continue. [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.017; org.apache.solr.cloud= .ShardLeaderElectionContext; I may be the new leader - try and sync [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.017; org.apache.solr.cloud= .SyncStrategy; Sync replicas to http://127.0.0.1:50235/collection1/ [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.017; org.apache.solr.cloud= .SyncStrategy; Sync Success - now sync replicas to me [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.018; org.apache.solr.cloud= .SyncStrategy; http://127.0.0.1:50235/collection1/ has no replicas [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.018; org.apache.solr.cloud= .ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:50235/co= llection1/ [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.019; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/sha= rd1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.608; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.633; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 1) [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.650; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:50235/collection1/ and leader is htt= p://127.0.0.1:50235/collection1/ [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.651; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:50235 [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.652; org.apache.solr.cloud= .ZkController; I am the leader, no recovery necessary [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.652; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.652; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.660; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.667; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/Users/jenkins/jenkins-slave/workspace/Lu= cene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.668; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.668; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.696; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config: [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.700; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.707; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@2c6e003c name:ZooKeeperConnection Watcher:127.0.0.1:50232/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.707; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.710; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:51.717; org.apache.solr.cloud= .ChaosMonkey; monkey: init - expire sessions:true cause connection loss:tru= e [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.304; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.313; org.eclipse.jetty.ser= ver.AbstractConnector; Started SelectChannelConnector@127.0.0.1:50239 [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.315; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.316; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.317; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /Users/jenkins/je= nkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0= /./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1367118651718 [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.317; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /Users/jenkins/jen= kins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/= ./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1367118651718/solr.xm= l [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.318; org.apache.solr.core.= CoreContainer; New CoreContainer 1065315136 [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.320; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/Users/jenkins/jenki= ns-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./= org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1367118651718/' [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.321; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/Users/jenkins/j= enkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1367118651718/' [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.539; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.540; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.541; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.541; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.542; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.543; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.544; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.544; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.550; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.554; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= sPerHost=3D20&maxConnections=3D10000&socketTimeout=3D120000&connTimeout=3D1= 5000&retry=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.582; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.584; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:50232/solr [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.585; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.587; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.592; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@53a2a1c name:ZooKeeperConnection Watcher:127.0.0.1:50232 got event W= atchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.593; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.597; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D500&maxConnectionsPerHost=3D16&socketTimeout=3D120000&connTimeout=3D150= 00 [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.628; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.634; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@7e759bd1 name:ZooKeeperConnection Watcher:127.0.0.1:50232/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.634; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:52.645; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.151; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.153; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"1", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"control_collection", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:50235_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:50235"} [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.161; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 1) [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.162; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 1) [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.162; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 1) [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.655; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:502= 39_ [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.657; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:50239_ [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.671; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 1) [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.675; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 1) [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.678; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.678; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.687; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.688; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.700; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /Users/je= nkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core= /test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-136711865171= 8/collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.701; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.702; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.703; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.706; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/Users/jenkins/j= enkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1367118651718/colle= ction1/' [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.712; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/Users/jenkins/jenkins-slave/workspace/Luc= ene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.Ba= sicDistributedZkTest-jetty1-1367118651718/collection1/lib/classes/' to clas= sloader [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.714; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/Users/jenkins/jenkins-slave/workspace/Luc= ene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.Ba= sicDistributedZkTest-jetty1-1367118651718/collection1/lib/README' to classl= oader [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.805; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_50 [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.905; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.910; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:53.919; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-28 03:10:54.936; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-28 03:10:54.958; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-28 03:10:54.962; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.007; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.016; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.024; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-28 03:10:55.026; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-28 03:10:55.030; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.032; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-28 03:10:55.039; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-28 03:10:55.039; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.040; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.040; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slav= e/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apa= che.solr.cloud.BasicDistributedZkTest-jetty1-1367118651718/collection1/, da= taDir=3D./org.apache.solr.cloud.BasicDistributedZkTest-1367118647176/jetty1= / [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.041; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@35d6593a [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.041; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.042; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.B= asicDistributedZkTest-1367118647176/jetty1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.043; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.BasicDistributedZkTest-1367118647176/jetty1/index/ [junit4:junit4] 1> WARN - 2013-04-28 03:10:55.043; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Basic= DistributedZkTest-1367118647176/jetty1/index' doesn't exist. Creating new i= ndex... [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.046; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.B= asicDistributedZkTest-1367118647176/jetty1/index [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.053; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927456tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@2464bb06),segFN=3Dsegments_1,gene= ration=3D1} [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.054; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.059; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.059; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.060; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.061; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.062; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.063; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.063; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.064; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.065; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.098; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.111; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@6716c429 main [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.112; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Bas= icDistributedZkTest-1367118647176/jetty1/tlog [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.113; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.114; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.119; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@6716c429 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.123; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-28 03:10:55.124; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-28 03:10:56.190; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:56.193; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"2", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:50239_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:50239"} [junit4:junit4] 1> INFO - 2013-04-28 03:10:56.194; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Create collection collection1 with numShards= 2 [junit4:junit4] 1> INFO - 2013-04-28 03:10:56.194; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:56.216; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:56.216; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:56.216; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.128; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.129; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :50239 collection:collection1 shard:shard1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.131; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard= 1/election [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.153; org.apache.solr.cloud= .ShardLeaderElectionContext; Running the leader process. [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.160; org.apache.solr.cloud= .ShardLeaderElectionContext; Enough replicas found to continue. [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.161; org.apache.solr.cloud= .ShardLeaderElectionContext; I may be the new leader - try and sync [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.161; org.apache.solr.cloud= .SyncStrategy; Sync replicas to http://127.0.0.1:50239/collection1/ [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.162; org.apache.solr.cloud= .SyncStrategy; Sync Success - now sync replicas to me [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.162; org.apache.solr.cloud= .SyncStrategy; http://127.0.0.1:50239/collection1/ has no replicas [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.162; org.apache.solr.cloud= .ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:50239/co= llection1/ [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.163; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.735; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.762; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.763; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.765; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.810; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:50239/collection1/ and leader is htt= p://127.0.0.1:50239/collection1/ [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.811; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:50239 [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.811; org.apache.solr.cloud= .ZkController; I am the leader, no recovery necessary [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.812; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.812; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.816; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.821; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/Users/jenkins/jenkins-slave/workspace/Lu= cene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.823; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-28 03:10:57.825; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.427; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.440; org.eclipse.jetty.ser= ver.AbstractConnector; Started SelectChannelConnector@127.0.0.1:50242 [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.441; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.442; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.443; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /Users/jenkins/je= nkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0= /./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1367118657859 [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.443; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /Users/jenkins/jen= kins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/= ./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1367118657859/solr.xm= l [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.444; org.apache.solr.core.= CoreContainer; New CoreContainer 235236916 [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.445; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/Users/jenkins/jenki= ns-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./= org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1367118657859/' [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.445; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/Users/jenkins/j= enkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1367118657859/' [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.674; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.675; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.676; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.677; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.677; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.678; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.678; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.680; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.680; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.681; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= sPerHost=3D20&maxConnections=3D10000&socketTimeout=3D120000&connTimeout=3D1= 5000&retry=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.714; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.715; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:50232/solr [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.715; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.719; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.724; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@5f4d4bb9 name:ZooKeeperConnection Watcher:127.0.0.1:50232 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.725; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.736; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D500&maxConnectionsPerHost=3D16&socketTimeout=3D120000&connTimeout=3D150= 00 [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.769; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.775; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@5385db45 name:ZooKeeperConnection Watcher:127.0.0.1:50232/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.776; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:10:58.788; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.284; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.287; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"2", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:50239_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:50239"} [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.302; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.302; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.303; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.303; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.801; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:502= 42_ [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.806; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:50242_ [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.819; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.819; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.819; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.822; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.823; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.836; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.836; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.837; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.847; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /Users/je= nkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core= /test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-136711865785= 9/collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.848; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.849; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.850; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.854; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/Users/jenkins/j= enkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1367118657859/colle= ction1/' [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.855; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/Users/jenkins/jenkins-slave/workspace/Luc= ene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.Ba= sicDistributedZkTest-jetty2-1367118657859/collection1/lib/classes/' to clas= sloader [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.857; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/Users/jenkins/jenkins-slave/workspace/Luc= ene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.Ba= sicDistributedZkTest-jetty2-1367118657859/collection1/lib/README' to classl= oader [junit4:junit4] 1> INFO - 2013-04-28 03:10:59.949; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_50 [junit4:junit4] 1> INFO - 2013-04-28 03:11:00.052; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-28 03:11:00.056; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-28 03:11:00.065; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.059; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.094; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.102; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.147; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.156; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.187; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-28 03:11:01.191; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-28 03:11:01.192; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.193; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-28 03:11:01.198; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-28 03:11:01.198; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.199; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.199; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slav= e/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apa= che.solr.cloud.BasicDistributedZkTest-jetty2-1367118657859/collection1/, da= taDir=3D./org.apache.solr.cloud.BasicDistributedZkTest-1367118647176/jetty2= / [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.200; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@35d6593a [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.200; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.201; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.B= asicDistributedZkTest-1367118647176/jetty2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.202; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.BasicDistributedZkTest-1367118647176/jetty2/index/ [junit4:junit4] 1> WARN - 2013-04-28 03:11:01.202; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Basic= DistributedZkTest-1367118647176/jetty2/index' doesn't exist. Creating new i= ndex... [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.205; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.B= asicDistributedZkTest-1367118647176/jetty2/index [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.213; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927457tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@177312a3),segFN=3Dsegments_1,gene= ration=3D1} [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.213; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.219; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.219; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.220; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.221; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.223; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.224; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.224; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.226; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.227; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.251; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.262; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@5ab57c42 main [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.263; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Bas= icDistributedZkTest-1367118647176/jetty2/tlog [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.264; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.265; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.270; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@5ab57c42 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.274; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-28 03:11:01.274; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-28 03:11:02.341; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:02.344; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"3", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:50242_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:50242"} [junit4:junit4] 1> INFO - 2013-04-28 03:11:02.344; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:02.345; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:02.355; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:02.357; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:02.360; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:02.367; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.279; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.280; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :50242 collection:collection1 shard:shard2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.284; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard= 2/election [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.300; org.apache.solr.cloud= .ShardLeaderElectionContext; Running the leader process. [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.306; org.apache.solr.cloud= .ShardLeaderElectionContext; Enough replicas found to continue. [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.306; org.apache.solr.cloud= .ShardLeaderElectionContext; I may be the new leader - try and sync [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.307; org.apache.solr.cloud= .SyncStrategy; Sync replicas to http://127.0.0.1:50242/collection1/ [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.307; org.apache.solr.cloud= .SyncStrategy; Sync Success - now sync replicas to me [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.307; org.apache.solr.cloud= .SyncStrategy; http://127.0.0.1:50242/collection1/ has no replicas [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.307; org.apache.solr.cloud= .ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:50242/co= llection1/ [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.308; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.883; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.912; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.913; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.913; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.913; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.953; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:50242/collection1/ and leader is htt= p://127.0.0.1:50242/collection1/ [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.954; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:50242 [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.954; org.apache.solr.cloud= .ZkController; I am the leader, no recovery necessary [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.954; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.955; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.959; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.965; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/Users/jenkins/jenkins-slave/workspace/Lu= cene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.968; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-28 03:11:03.969; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.530; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.538; org.eclipse.jetty.ser= ver.AbstractConnector; Started SelectChannelConnector@127.0.0.1:50245 [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.539; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.540; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.540; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /Users/jenkins/je= nkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0= /./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1367118664001 [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.541; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /Users/jenkins/jen= kins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/= ./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1367118664001/solr.xm= l [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.541; org.apache.solr.core.= CoreContainer; New CoreContainer 2023317851 [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.542; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/Users/jenkins/jenki= ns-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./= org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1367118664001/' [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.543; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/Users/jenkins/j= enkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1367118664001/' [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.777; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.778; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.778; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.779; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.779; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.780; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.780; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.781; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.781; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.781; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= sPerHost=3D20&maxConnections=3D10000&socketTimeout=3D120000&connTimeout=3D1= 5000&retry=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.803; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.804; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:50232/solr [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.804; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.808; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.813; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@3ede4586 name:ZooKeeperConnection Watcher:127.0.0.1:50232 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.814; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.819; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D500&maxConnectionsPerHost=3D16&socketTimeout=3D120000&connTimeout=3D150= 00 [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.844; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.850; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@51a81e4c name:ZooKeeperConnection Watcher:127.0.0.1:50232/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.851; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:11:04.863; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.440; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.442; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"3", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard2", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:50242_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:50242"} [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.453; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.456; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.459; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.459; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.459; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.878; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:502= 45_ [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.881; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:50245_ [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.888; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.888; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.888; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.888; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.894; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.894; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.903; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.904; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.903; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.904; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.917; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /Users/je= nkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core= /test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-136711866400= 1/collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.918; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.920; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.920; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.924; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/Users/jenkins/j= enkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1367118664001/colle= ction1/' [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.925; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/Users/jenkins/jenkins-slave/workspace/Luc= ene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.Ba= sicDistributedZkTest-jetty3-1367118664001/collection1/lib/classes/' to clas= sloader [junit4:junit4] 1> INFO - 2013-04-28 03:11:05.926; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/Users/jenkins/jenkins-slave/workspace/Luc= ene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.Ba= sicDistributedZkTest-jetty3-1367118664001/collection1/lib/README' to classl= oader [junit4:junit4] 1> INFO - 2013-04-28 03:11:06.021; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_50 [junit4:junit4] 1> INFO - 2013-04-28 03:11:06.119; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-28 03:11:06.123; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-28 03:11:06.133; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.133; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.157; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.162; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.200; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.215; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.223; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-28 03:11:07.226; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-28 03:11:07.227; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.228; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-28 03:11:07.231; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-28 03:11:07.232; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.234; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.234; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slav= e/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apa= che.solr.cloud.BasicDistributedZkTest-jetty3-1367118664001/collection1/, da= taDir=3D./org.apache.solr.cloud.BasicDistributedZkTest-1367118647176/jetty3= / [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.235; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@35d6593a [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.236; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.237; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.B= asicDistributedZkTest-1367118647176/jetty3 [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.237; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.BasicDistributedZkTest-1367118647176/jetty3/index/ [junit4:junit4] 1> WARN - 2013-04-28 03:11:07.237; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Basic= DistributedZkTest-1367118647176/jetty3/index' doesn't exist. Creating new i= ndex... [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.240; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.B= asicDistributedZkTest-1367118647176/jetty3/index [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.249; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927458tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@71799400),segFN=3Dsegments_1,gene= ration=3D1} [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.250; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.255; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.256; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.257; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.258; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.259; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.260; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.261; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.262; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.263; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.290; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.301; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@16fef794 main [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.302; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Bas= icDistributedZkTest-1367118647176/jetty3/tlog [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.304; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.305; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.311; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@16fef794 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.316; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-28 03:11:07.317; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-28 03:11:08.483; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:08.485; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"4", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:50245_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:50245"} [junit4:junit4] 1> INFO - 2013-04-28 03:11:08.486; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:08.486; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:08.497; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:08.498; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:08.500; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:08.501; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:08.502; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.323; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.324; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :50245 collection:collection1 shard:shard1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.333; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:50245/collection1/ and leader is htt= p://127.0.0.1:50239/collection1/ [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.334; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:50245 [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.334; org.apache.solr.cloud= .ZkController; Core needs to recover:collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.335; org.apache.solr.updat= e.DefaultSolrCoreState; Running recovery - first canceling any ongoing reco= very [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.336; org.apache.solr.cloud= .RecoveryStrategy; Starting recovery process. core=3Dcollection1 recoverin= gAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.338; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.342; org.apache.solr.cloud= .RecoveryStrategy; ###### startupVersions=3D[] [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.343; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Drecovering [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.343; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.345; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/Users/jenkins/jenkins-slave/workspace/Lu= cene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.345; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.346; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.347; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:11:09.390; org.apache.solr.handl= er.admin.CoreAdminHandler; Going to wait for coreNodeName: 4, state: recove= ring, checkLive: true, onlyIfLeader: true [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.009; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.021; org.eclipse.jetty.ser= ver.AbstractConnector; Started SelectChannelConnector@127.0.0.1:50249 [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.024; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.025; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.026; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"4", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"recovering", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:50245_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:50245"} [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.030; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.030; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /Users/jenkins/je= nkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0= /./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1367118669386 [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.037; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /Users/jenkins/jen= kins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/= ./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1367118669386/solr.xm= l [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.038; org.apache.solr.core.= CoreContainer; New CoreContainer 35674873 [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.039; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/Users/jenkins/jenki= ns-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./= org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1367118669386/' [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.039; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/Users/jenkins/j= enkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1367118669386/' [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.044; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.045; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.045; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.045; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.045; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.294; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.295; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.296; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.296; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.297; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.297; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.298; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.299; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.300; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.300; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= sPerHost=3D20&maxConnections=3D10000&socketTimeout=3D120000&connTimeout=3D1= 5000&retry=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.335; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.337; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:50232/solr [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.337; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.342; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.351; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@645976d0 name:ZooKeeperConnection Watcher:127.0.0.1:50232 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.353; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.358; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D500&maxConnectionsPerHost=3D16&socketTimeout=3D120000&connTimeout=3D150= 00 [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.385; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.391; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@2a6cba4b name:ZooKeeperConnection Watcher:127.0.0.1:50232/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.392; org.apache.solr.handl= er.admin.CoreAdminHandler; Waited coreNodeName: 4, state: recovering, check= Live: true, onlyIfLeader: true for: 1 seconds. [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.393; org.apache.solr.servl= et.SolrDispatchFilter; [admin] webapp=3Dnull path=3D/admin/cores params=3D{= coreNodeName=3D4&state=3Drecovering&nodeName=3D127.0.0.1:50245_&action=3DPR= EPRECOVERY&checkLive=3Dtrue&core=3Dcollection1&wt=3Djavabin&onlyIfLeader=3D= true&version=3D2} status=3D0 QTime=3D1003=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.392; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-28 03:11:10.410; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.426; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:502= 49_ [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.434; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:50249_ [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.455; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.455; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.456; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.455; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.460; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.461; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.466; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.473; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.474; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.476; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.478; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.492; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /Users/je= nkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core= /test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-136711866938= 6/collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.492; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.494; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.494; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.501; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/Users/jenkins/j= enkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1367118669386/colle= ction1/' [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.503; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/Users/jenkins/jenkins-slave/workspace/Luc= ene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.Ba= sicDistributedZkTest-jetty4-1367118669386/collection1/lib/classes/' to clas= sloader [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.503; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/Users/jenkins/jenkins-slave/workspace/Luc= ene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.Ba= sicDistributedZkTest-jetty4-1367118669386/collection1/lib/README' to classl= oader [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.594; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_50 [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.697; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.700; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-28 03:11:11.712; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.395; org.apache.solr.cloud= .RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:50239/colle= ction1/ core=3Dcollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.396; org.apache.solr.updat= e.PeerSync; PeerSync: core=3Dcollection1 url=3Dhttp://127.0.0.1:50245 START= replicas=3D[http://127.0.0.1:50239/collection1/] nUpdates=3D100 [junit4:junit4] 1> WARN - 2013-04-28 03:11:12.397; org.apache.solr.updat= e.PeerSync; no frame of reference to tell of we've missed updates [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.446; org.apache.solr.cloud= .RecoveryStrategy; PeerSync Recovery was not successful - trying replicatio= n. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.448; org.apache.solr.cloud= .RecoveryStrategy; Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.448; org.apache.solr.cloud= .RecoveryStrategy; Begin buffering updates. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.449; org.apache.solr.updat= e.UpdateLog; Starting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog= =3Dnull} [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.449; org.apache.solr.cloud= .RecoveryStrategy; Attempting to replicate from http://127.0.0.1:50239/coll= ection1/. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.450; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.467; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/get params=3D{getVersions=3D100&d= istrib=3Dfalse&wt=3Djavabin&qt=3D/get&version=3D2} status=3D0 QTime=3D5=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.527; org.apache.solr.updat= e.DirectUpdateHandler2; start commit{,optimize=3Dfalse,openSearcher=3Dfalse= ,waitSearcher=3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommi= t=3Dfalse} [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.533; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927456tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@2464bb06),segFN=3Dsegments_1,gene= ration=3D1} [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.537; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.543; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927456tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@2464bb06),segFN=3Dsegments_1,gene= ration=3D1} [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927456tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@2464bb06),segFN=3Dsegments_2,gene= ration=3D2} [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.544; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.545; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@3df4d189 realtime [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.545; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.546; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{waitSearcher=3Dtrue&openSearcher=3Dfalse&commit=3Dtrue&wt=3Djavabin&c= ommit_end_point=3Dtrue&version=3D2&softCommit=3Dfalse} {commit=3D} 0 19 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.548; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.549; org.apache.solr.handl= er.SnapPuller; No value set for 'pollInterval'. Timer Task not started. [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.554; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.555; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{command=3Di= ndexversion&qt=3D/replication&wt=3Djavabin&version=3D2} status=3D0 QTime=3D= 3=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.556; org.apache.solr.handl= er.SnapPuller; Master's generation: 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.557; org.apache.solr.handl= er.SnapPuller; Slave's generation: 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.558; org.apache.solr.handl= er.SnapPuller; Starting replication process [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.564; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{command=3Df= ilelist&qt=3D/replication&wt=3Djavabin&generation=3D2&version=3D2} status= =3D0 QTime=3D1=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.570; org.apache.solr.handl= er.SnapPuller; Number of files in latest index in master: 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.573; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.B= asicDistributedZkTest-1367118647176/jetty3/index.20130427231112571 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.574; org.apache.solr.handl= er.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.= RAMDirectory@33e2108b lockFactory=3Dorg.apache.lucene.store.NativeFSLockFac= tory@784e697e) fullCopy=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.582; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{file=3Dsegm= ents_2&command=3Dfilecontent&checksum=3Dtrue&wt=3Dfilestream&qt=3D/replicat= ion&generation=3D2} status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.593; org.apache.solr.handl= er.SnapPuller; Total time taken for download : 0 secs [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.596; org.apache.solr.updat= e.DefaultSolrCoreState; Creating new IndexWriter... [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.596; org.apache.solr.updat= e.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=3Dcolle= ction1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.601; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927458tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@71799400),segFN=3Dsegments_1,gene= ration=3D1} [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927458tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@71799400),segFN=3Dsegments_2,gene= ration=3D2} [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.604; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.604; org.apache.solr.updat= e.DefaultSolrCoreState; New IndexWriter is ready to be used. [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.616; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@22e40d92 main [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.618; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@22e40d92 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.624; org.apache.solr.core.= CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.BasicDist= ributedZkTest-1367118647176/jetty3/index.20130427231112571 [CachedDir<>] [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.624; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.BasicDi= stributedZkTest-1367118647176/jetty3/index.20130427231112571 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.625; org.apache.solr.core.= CachingDirectoryFactory; Removing directory before core close: ./org.apache= .solr.cloud.BasicDistributedZkTest-1367118647176/jetty3/index.2013042723111= 2571 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.625; org.apache.solr.cloud= .RecoveryStrategy; No replay needed. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.625; org.apache.solr.cloud= .RecoveryStrategy; Replication Recovery was successful - registering as Act= ive. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.625; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.626; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.635; org.apache.solr.cloud= .RecoveryStrategy; Finished recovery process. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.946; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.967; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-28 03:11:12.974; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.021; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.049; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.065; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-28 03:11:13.069; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-28 03:11:13.070; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.071; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-28 03:11:13.075; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-28 03:11:13.076; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.077; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.077; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slav= e/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apa= che.solr.cloud.BasicDistributedZkTest-jetty4-1367118669386/collection1/, da= taDir=3D./org.apache.solr.cloud.BasicDistributedZkTest-1367118647176/jetty4= / [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.078; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@35d6593a [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.080; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.082; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.B= asicDistributedZkTest-1367118647176/jetty4 [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.082; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.BasicDistributedZkTest-1367118647176/jetty4/index/ [junit4:junit4] 1> WARN - 2013-04-28 03:11:13.083; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Basic= DistributedZkTest-1367118647176/jetty4/index' doesn't exist. Creating new i= ndex... [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.085; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.087; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"4", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:50245_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:50245"} [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.089; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.B= asicDistributedZkTest-1367118647176/jetty4/index [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.103; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.104; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.104; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.105; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.106; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.103; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.115; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927459tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@51be2dd8),segFN=3Dsegments_1,gene= ration=3D1} [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.116; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.124; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.125; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.126; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.128; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.129; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.130; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.134; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.135; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.136; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.160; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.173; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@150fb701 main [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.174; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Bas= icDistributedZkTest-1367118647176/jetty4/tlog [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.176; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.177; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.184; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@150fb701 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.196; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-28 03:11:13.196; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-28 03:11:14.631; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:14.633; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"5", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:50249_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:50249"} [junit4:junit4] 1> INFO - 2013-04-28 03:11:14.634; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:14.634; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:14.648; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:14.649; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:14.650; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:14.659; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:14.660; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:14.661; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.201; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.201; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :50249 collection:collection1 shard:shard2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.210; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:50249/collection1/ and leader is htt= p://127.0.0.1:50242/collection1/ [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.211; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:50249 [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.211; org.apache.solr.cloud= .ZkController; Core needs to recover:collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.211; org.apache.solr.updat= e.DefaultSolrCoreState; Running recovery - first canceling any ongoing reco= very [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.213; org.apache.solr.cloud= .RecoveryStrategy; Starting recovery process. core=3Dcollection1 recoverin= gAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.215; org.apache.solr.cloud= .RecoveryStrategy; ###### startupVersions=3D[] [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.215; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Drecovering [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.215; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.217; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.219; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.221; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/Users/jenkins/jenkins-slave/workspace/Lu= cene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.222; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.222; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.254; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.257; org.apache.solr.handl= er.admin.CoreAdminHandler; Going to wait for coreNodeName: 5, state: recove= ring, checkLive: true, onlyIfLeader: true [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.259; org.apache.solr.cloud= .AbstractDistribZkTestBase; Wait for recoveries to finish - collection: col= lection1 failOnTimeout:true timeout (sec):230 [junit4:junit4] 1> INFO - 2013-04-28 03:11:15.261; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:16.180; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:16.182; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"5", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard2", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"recovering", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:50249_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:50249"} [junit4:junit4] 1> INFO - 2013-04-28 03:11:16.195; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:16.196; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:16.197; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:16.206; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:16.207; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:16.207; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:16.259; org.apache.solr.handl= er.admin.CoreAdminHandler; Waited coreNodeName: 5, state: recovering, check= Live: true, onlyIfLeader: true for: 1 seconds. [junit4:junit4] 1> INFO - 2013-04-28 03:11:16.260; org.apache.solr.servl= et.SolrDispatchFilter; [admin] webapp=3Dnull path=3D/admin/cores params=3D{= coreNodeName=3D5&state=3Drecovering&nodeName=3D127.0.0.1:50249_&action=3DPR= EPRECOVERY&checkLive=3Dtrue&core=3Dcollection1&wt=3Djavabin&onlyIfLeader=3D= true&version=3D2} status=3D0 QTime=3D1003=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:16.265; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:17.271; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.262; org.apache.solr.cloud= .RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:50242/colle= ction1/ core=3Dcollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.263; org.apache.solr.updat= e.PeerSync; PeerSync: core=3Dcollection1 url=3Dhttp://127.0.0.1:50249 START= replicas=3D[http://127.0.0.1:50242/collection1/] nUpdates=3D100 [junit4:junit4] 1> WARN - 2013-04-28 03:11:18.264; org.apache.solr.updat= e.PeerSync; no frame of reference to tell of we've missed updates [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.265; org.apache.solr.cloud= .RecoveryStrategy; PeerSync Recovery was not successful - trying replicatio= n. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.266; org.apache.solr.cloud= .RecoveryStrategy; Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.267; org.apache.solr.cloud= .RecoveryStrategy; Begin buffering updates. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.267; org.apache.solr.updat= e.UpdateLog; Starting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog= =3Dnull} [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.268; org.apache.solr.cloud= .RecoveryStrategy; Attempting to replicate from http://127.0.0.1:50242/coll= ection1/. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.268; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.306; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.314; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/get params=3D{getVersions=3D100&d= istrib=3Dfalse&wt=3Djavabin&qt=3D/get&version=3D2} status=3D0 QTime=3D8=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.316; org.apache.solr.updat= e.DirectUpdateHandler2; start commit{,optimize=3Dfalse,openSearcher=3Dfalse= ,waitSearcher=3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommi= t=3Dfalse} [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.323; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927457tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@177312a3),segFN=3Dsegments_1,gene= ration=3D1} [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.326; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.331; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927457tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@177312a3),segFN=3Dsegments_1,gene= ration=3D1} [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927457tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@177312a3),segFN=3Dsegments_2,gene= ration=3D2} [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.332; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.333; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@6adebac0 realtime [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.334; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.335; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{waitSearcher=3Dtrue&openSearcher=3Dfalse&commit=3Dtrue&wt=3Djavabin&c= ommit_end_point=3Dtrue&version=3D2&softCommit=3Dfalse} {commit=3D} 0 19 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.337; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.337; org.apache.solr.handl= er.SnapPuller; No value set for 'pollInterval'. Timer Task not started. [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.342; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.342; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{command=3Di= ndexversion&qt=3D/replication&wt=3Djavabin&version=3D2} status=3D0 QTime=3D= 1=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.344; org.apache.solr.handl= er.SnapPuller; Master's generation: 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.344; org.apache.solr.handl= er.SnapPuller; Slave's generation: 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.345; org.apache.solr.handl= er.SnapPuller; Starting replication process [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.348; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{command=3Df= ilelist&qt=3D/replication&wt=3Djavabin&generation=3D2&version=3D2} status= =3D0 QTime=3D1=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.349; org.apache.solr.handl= er.SnapPuller; Number of files in latest index in master: 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.351; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.B= asicDistributedZkTest-1367118647176/jetty4/index.20130427231118349 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.352; org.apache.solr.handl= er.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.= RAMDirectory@33daeacb lockFactory=3Dorg.apache.lucene.store.NativeFSLockFac= tory@289d032d) fullCopy=3Dfalse [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.354; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{file=3Dsegm= ents_2&command=3Dfilecontent&checksum=3Dtrue&wt=3Dfilestream&qt=3D/replicat= ion&generation=3D2} status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.357; org.apache.solr.handl= er.SnapPuller; Total time taken for download : 0 secs [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.360; org.apache.solr.updat= e.DefaultSolrCoreState; Creating new IndexWriter... [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.360; org.apache.solr.updat= e.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=3Dcolle= ction1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.365; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927459tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@51be2dd8),segFN=3Dsegments_1,gene= ration=3D1} [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927459tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@51be2dd8),segFN=3Dsegments_2,gene= ration=3D2} [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.366; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.367; org.apache.solr.updat= e.DefaultSolrCoreState; New IndexWriter is ready to be used. [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.367; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@61b8e5db main [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.369; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@61b8e5db main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.370; org.apache.solr.core.= CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.BasicDist= ributedZkTest-1367118647176/jetty4/index.20130427231118349 [CachedDir<>] [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.371; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.BasicDi= stributedZkTest-1367118647176/jetty4/index.20130427231118349 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.373; org.apache.solr.core.= CachingDirectoryFactory; Removing directory before core close: ./org.apache= .solr.cloud.BasicDistributedZkTest-1367118647176/jetty4/index.2013042723111= 8349 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.375; org.apache.solr.cloud= .RecoveryStrategy; No replay needed. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.377; org.apache.solr.cloud= .RecoveryStrategy; Replication Recovery was successful - registering as Act= ive. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.377; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.377; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-28 03:11:18.389; org.apache.solr.cloud= .RecoveryStrategy; Finished recovery process. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.241; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.244; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"5", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard2", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:50249_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:50249"} [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.261; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.262; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.262; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.263; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.263; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.264; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.320; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.323; org.apache.solr.cloud= .AbstractDistribZkTestBase; Recoveries finished - collection: collection1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.348; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DBaseDirectoryWrapper(org.apache.lucene= .store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-tr= unk-MacOSX/solr/build/solr-core/test/J0/index2744927455tmp lockFactory=3Dor= g.apache.lucene.store.NativeFSLockFactory@109ebd74),segFN=3Dsegments_1,gene= ration=3D1} [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.350; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.352; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@8da40da realtime [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.353; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {deleteByQuery=3D*:* (-1433527836309716992)= } 0 11 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.420; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{update.distrib=3DFROMLEADER&_version_=3D-1433527836355854336&update.f= rom=3Dhttp://127.0.0.1:50239/collection1/&wt=3Djavabin&version=3D2} {delete= ByQuery=3D*:* (-1433527836355854336)} 0 6 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.450; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{update.distrib=3DFROMLEADER&_version_=3D-1433527836386263040&update.f= rom=3Dhttp://127.0.0.1:50242/collection1/&wt=3Djavabin&version=3D2} {delete= ByQuery=3D*:* (-1433527836386263040)} 0 6 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.451; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{update.distrib=3DTOLEADER&wt=3Djavabin&version=3D2} {deleteByQuery=3D= *:* (-1433527836386263040)} 0 36 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.453; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {deleteByQuery=3D*:* (-1433527836355854336)= } 0 67 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.462; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[1 (1433527836430303232)]} 0 5 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.486; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[1 (1433527836447080448)]} 0 6 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.488; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[1 (1433527836447080448)]} 0 15 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.490; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[1]} 0 22 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.496; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[2 (1433527836469100544)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.528; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[2 (1433527836476440576)]} 0 8 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.530; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[2 (1433527836476440576)]} 0 30 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.536; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[3 (1433527836511043584)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.549; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[3 (1433527836521529344)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.551; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[3 (1433527836521529344)]} 0 8 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.553; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[3]} 0 12 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.558; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[4 (1433527836535160832)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.579; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[4 (1433527836545646592)]} 0 6 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.581; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[4 (1433527836545646592)]} 0 14 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.582; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[4]} 0 19 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.588; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[5 (1433527836565569536)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.603; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[5 (1433527836577103872)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.605; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[5 (1433527836577103872)]} 0 8 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.606; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[5]} 0 12 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.612; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[6 (1433527836591783936)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.625; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[6 (1433527836600172544)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.627; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[6 (1433527836600172544)]} 0 8 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.629; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[6]} 0 13 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.634; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[7 (1433527836614852608)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.651; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[7 (1433527836623241216)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.653; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[7 (1433527836623241216)]} 0 14 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.660; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[8 (1433527836641067008)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.674; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[8 (1433527836650504192)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.676; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[8 (1433527836650504192)]} 0 9 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.678; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[8]} 0 14 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.683; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[9 (1433527836666232832)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.694; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[9 (1433527836672524288)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.696; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[9 (1433527836672524288)]} 0 9 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.702; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[10 (1433527836685107200)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.732; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[10 (1433527836712370176)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.734; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[10 (1433527836712370176)]} 0 8 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.736; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[10]} 0 19 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.741; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[11 (1433527836727050240)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.754; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[11 (1433527836735438848)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.756; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[11 (1433527836735438848)]} 0 8 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.757; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[11]} 0 12 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.763; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[12 (1433527836749070336)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.787; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[12 (1433527836771090432)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.788; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[12 (1433527836771090432)]} 0 8 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.789; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[12]} 0 22 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.795; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[13 (1433527836783673344)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.809; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[13 (1433527836792061952)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.811; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[13 (1433527836792061952)]} 0 9 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.812; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[13]} 0 13 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.817; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[14 (1433527836806742016)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.829; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[14 (1433527836815130624)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.831; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[14 (1433527836815130624)]} 0 7 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.832; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[14]} 0 12 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.844; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[15 (1433527836829810688)]} 0 7 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.866; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[15 (1433527836850782208)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.869; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[15 (1433527836850782208)]} 0 11 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.872; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[15]} 0 20 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.880; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[16 (1433527836871753728)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.901; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[16 (1433527836886433792)]} 0 5 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.905; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[16 (1433527836886433792)]} 0 14 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.926; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[17 (1433527836909502464)]} 0 13 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.953; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[17 (1433527836934668288)]} 0 6 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.955; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[17 (1433527836934668288)]} 0 18 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.958; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[17]} 0 25 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.963; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[100 (1433527836959834112)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.973; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[100 (1433527836966125568)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.974; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[100 (1433527836966125568)]} 0 7 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.979; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[101 (1433527836976611328)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.988; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[101 (1433527836981854208)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.991; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[101 (1433527836981854208)]} 0 8 [junit4:junit4] 1> INFO - 2013-04-28 03:11:19.997; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[102 (1433527836995485696)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.007; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[102 (1433527837000728576)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.009; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[102 (1433527837000728576)]} 0 8 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.014; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[103 (1433527837013311488)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.032; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[103 (1433527837025894400)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.034; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[103 (1433527837025894400)]} 0 10 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.039; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[104 (1433527837039525888)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.057; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[104 (1433527837053157376)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.062; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[104 (1433527837053157376)]} 0 11 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.068; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[105 (1433527837069934592)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.087; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[105 (1433527837081468928)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.088; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[105 (1433527837081468928)]} 0 12 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.090; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[105]} 0 18 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.097; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[106 (1433527837100343296)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.105; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[106 (1433527837105586176)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.107; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[106 (1433527837105586176)]} 0 6 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.111; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[107 (1433527837115023360)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.120; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[107 (1433527837120266240)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.121; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[107 (1433527837120266240)]} 0 6 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.126; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[108 (1433527837130752000)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.138; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[108 (1433527837139140608)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.146; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[108 (1433527837139140608)]} 0 13 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.148; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[108]} 0 18 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.152; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[109 (1433527837159063552)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.166; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[109 (1433527837168500736)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.168; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[109 (1433527837168500736)]} 0 7 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.169; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[109]} 0 11 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.174; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[110 (1433527837181083648)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.187; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[110 (1433527837189472256)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.189; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[110 (1433527837189472256)]} 0 8 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.190; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[110]} 0 12 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.195; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[111 (1433527837203103744)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.212; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[111 (1433527837208346624)]} 0 8 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.213; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[111 (1433527837208346624)]} 0 14 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.224; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[112 (1433527837233512448)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.232; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[112 (1433527837238755328)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.234; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[112 (1433527837238755328)]} 0 6 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.239; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[113 (1433527837249241088)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.249; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[113 (1433527837254483968)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.251; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[113 (1433527837254483968)]} 0 9 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.259; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[114 (1433527837269164032)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.270; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[114 (1433527837278601216)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.272; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[114 (1433527837278601216)]} 0 7 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.273; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[114]} 0 10 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.285; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[115 (1433527837294329856)]} 0 5 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.301; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[115 (1433527837310058496)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.303; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[115 (1433527837310058496)]} 0 7 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.308; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[116 (1433527837322641408)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.327; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[116 (1433527837337321472)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.329; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50239/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[116 (1433527837337321472)]} 0 7 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.331; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[116]} 0 19 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.335; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[117 (1433527837349904384)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.343; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:50242/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[117 (1433527837355147264)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-28 03:11:20.344; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D [...truncated too long message...] seconds [junit4:junit4] > =09at __randomizedtesting.SeedInfo.seed([36C481287727D= 9FB:B7220F300078B9C7]:0) [junit4:junit4] > =09at org.apache.solr.cloud.AbstractDistribZkTestBase.= waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:173) [junit4:junit4] > =09at org.apache.solr.cloud.AbstractDistribZkTestBase.= waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:131) [junit4:junit4] > =09at org.apache.solr.cloud.AbstractDistribZkTestBase.= waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:126) [junit4:junit4] > =09at org.apache.solr.cloud.CollectionsAPIDistributedZ= kTest.testCollectionsAPI(CollectionsAPIDistributedZkTest.java:511) [junit4:junit4] > =09at org.apache.solr.cloud.CollectionsAPIDistributedZ= kTest.doTest(CollectionsAPIDistributedZkTest.java:145) [junit4:junit4] > =09at org.apache.solr.BaseDistributedSearchTestCase.te= stDistribSearch(BaseDistributedSearchTestCase.java:815) [junit4:junit4] > =09at java.lang.Thread.run(Thread.java:722) [junit4:junit4] 1> INFO - 2013-04-28 03:21:56.960; org.apache.solr.SolrT= estCaseJ4; ###deleteCore [junit4:junit4] 2> 291879 T4203 ccr.ThreadLeakControl.checkThreadLeaks WA= RNING Will linger awaiting termination of 1 leaked thread(s). [junit4:junit4] 1> WARN - 2013-04-28 03:21:57.124; org.apache.solr.cloud= .LeaderElector$1;=20 [junit4:junit4] 1> org.apache.zookeeper.KeeperException$SessionExpiredExc= eption: KeeperErrorCode =3D Session expired for /collections/awholynewcolle= ction_0/leader_elect/shard2/election [junit4:junit4] 1> =09at org.apache.zookeeper.KeeperException.create(Keep= erException.java:127) [junit4:junit4] 1> =09at org.apache.zookeeper.KeeperException.create(Keep= erException.java:51) [junit4:junit4] 1> =09at org.apache.zookeeper.ZooKeeper.getChildren(ZooKe= eper.java:1468) [junit4:junit4] 1> =09at org.apache.solr.common.cloud.SolrZkClient$6.exec= ute(SolrZkClient.java:235) [junit4:junit4] 1> =09at org.apache.solr.common.cloud.SolrZkClient$6.exec= ute(SolrZkClient.java:232) [junit4:junit4] 1> =09at org.apache.solr.common.cloud.ZkCmdExecutor.retry= Operation(ZkCmdExecutor.java:65) [junit4:junit4] 1> =09at org.apache.solr.common.cloud.SolrZkClient.getChi= ldren(SolrZkClient.java:232) [junit4:junit4] 1> =09at org.apache.solr.cloud.LeaderElector.checkIfIamLe= ader(LeaderElector.java:84) [junit4:junit4] 1> =09at org.apache.solr.cloud.LeaderElector.access$000(L= eaderElector.java:55) [junit4:junit4] 1> =09at org.apache.solr.cloud.LeaderElector$1.process(Le= aderElector.java:129) [junit4:junit4] 1> =09at org.apache.zookeeper.ClientCnxn$EventThread.proc= essEvent(ClientCnxn.java:519) [junit4:junit4] 1> =09at org.apache.zookeeper.ClientCnxn$EventThread.run(= ClientCnxn.java:495) [junit4:junit4] 1> INFO - 2013-04-28 03:21:57.124; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 1) [junit4:junit4] 1> WARN - 2013-04-28 03:21:57.125; org.apache.solr.commo= n.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to= ZK [junit4:junit4] 1> WARN - 2013-04-28 03:21:57.125; org.apache.solr.commo= n.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to= ZK [junit4:junit4] 1> WARN - 2013-04-28 03:21:57.125; org.apache.solr.cloud= .LeaderElector$1;=20 [junit4:junit4] 1> org.apache.zookeeper.KeeperException$SessionExpiredExc= eption: KeeperErrorCode =3D Session expired for /collections/awholynewcolle= ction_0/leader_elect/shard1/election [junit4:junit4] 1> =09at org.apache.zookeeper.KeeperException.create(Keep= erException.java:127) [junit4:junit4] 1> =09at org.apache.zookeeper.KeeperException.create(Keep= erException.java:51) [junit4:junit4] 1> =09at org.apache.zookeeper.ZooKeeper.getChildren(ZooKe= eper.java:1468) [junit4:junit4] 1> =09at org.apache.solr.common.cloud.SolrZkClient$6.exec= ute(SolrZkClient.java:235) [junit4:junit4] 1> =09at org.apache.solr.common.cloud.SolrZkClient$6.exec= ute(SolrZkClient.java:232) [junit4:junit4] 1> =09at org.apache.solr.common.cloud.ZkCmdExecutor.retry= Operation(ZkCmdExecutor.java:65) [junit4:junit4] 1> =09at org.apache.solr.common.cloud.SolrZkClient.getChi= ldren(SolrZkClient.java:232) [junit4:junit4] 1> =09at org.apache.solr.cloud.LeaderElector.checkIfIamLe= ader(LeaderElector.java:84) [junit4:junit4] 1> =09at org.apache.solr.cloud.LeaderElector.access$000(L= eaderElector.java:55) [junit4:junit4] 1> =09at org.apache.solr.cloud.LeaderElector$1.process(Le= aderElector.java:129) [junit4:junit4] 1> =09at org.apache.zookeeper.ClientCnxn$EventThread.proc= essEvent(ClientCnxn.java:519) [junit4:junit4] 1> =09at org.apache.zookeeper.ClientCnxn$EventThread.run(= ClientCnxn.java:495) [junit4:junit4] 2> NOTE: test params are: codec=3DHighCompressionCompress= ingStoredFields(storedFieldsFormat=3DCompressingStoredFieldsFormat(compress= ionMode=3DHIGH_COMPRESSION, chunkSize=3D406), termVectorsFormat=3DCompressi= ngTermVectorsFormat(compressionMode=3DHIGH_COMPRESSION, chunkSize=3D406)), = sim=3DRandomSimilarityProvider(queryNorm=3Dfalse,coord=3Dno): {}, locale=3D= ar_SA, timezone=3DAmerica/Miquelon [junit4:junit4] 2> NOTE: Mac OS X 10.8.3 x86_64/Oracle Corporation 1.7.0_= 21 (64-bit)/cpus=3D2,threads=3D2,free=3D225788840,total=3D519438336 [junit4:junit4] 2> NOTE: All tests run in this JVM: [TestPostingsSolrHigh= lighter, QueryEqualityTest, StatsComponentTest, QueryElevationComponentTest= , TestJmxIntegration, TestDistributedSearch, SOLR749Test, BasicFunctionalit= yTest, TestHashPartitioner, TestSolrQueryParserDefaultOperatorResource, Mor= eLikeThisHandlerTest, IndexReaderFactoryTest, CacheHeaderTest, SolrCmdDistr= ibutorTest, OverseerTest, DirectUpdateHandlerOptimizeTest, TestZkChroot, Te= stFieldCollectionResource, TestSolrXMLSerializer, SuggesterTest, SolrCoreTe= st, SolrInfoMBeanTest, DistanceFunctionTest, SuggesterTSTTest, TestGrouping= Search, SolrPluginUtilsTest, CoreAdminHandlerTest, RecoveryZkTest, TestFiel= dResource, TestDocumentBuilder, QueryParsingTest, TestCloudManagedSchema, T= estMergePolicyConfig, TestDynamicFieldCollectionResource, TestQuerySenderLi= stener, CopyFieldTest, SchemaVersionSpecificBehaviorTest, PreAnalyzedUpdate= ProcessorTest, SpellCheckCollatorTest, ChaosMonkeySafeLeaderTest, XsltUpdat= eRequestHandlerTest, SliceStateUpdateTest, DefaultValueUpdateProcessorTest,= JSONWriterTest, TestSolrJ, TestSolrDeletionPolicy2, NoCacheHeaderTest, Doc= umentAnalysisRequestHandlerTest, PrimUtilsTest, DirectSolrSpellCheckerTest,= TestOmitPositions, CircularListTest, SimpleFacetsTest, SortByFunctionTest,= CoreContainerCoreInitFailuresTest, SpellCheckComponentTest, BadCopyFieldTe= st, AlternateDirectoryTest, AutoCommitTest, TestSchemaVersionResource, Test= BinaryResponseWriter, ZkSolrClientTest, TestLMJelinekMercerSimilarityFactor= y, TestStressVersions, TestSystemIdResolver, TestSolr4Spatial, SyncSliceTes= t, FastVectorHighlighterTest, WordBreakSolrSpellCheckerTest, SuggesterWFSTT= est, ZkCLITest, TestSerializedLuceneMatchVersion, StandardRequestHandlerTes= t, HardAutoCommitTest, LeaderElectionTest, TestRemoteStreaming, OverseerCol= lectionProcessorTest, StatelessScriptUpdateProcessorFactoryTest, TestDocSet= , BadIndexSchemaTest, RequiredFieldsTest, RequestHandlersTest, AliasIntegra= tionTest, TestFieldTypeCollectionResource, XmlUpdateRequestHandlerTest, Tes= tSchemaSimilarityResource, DocumentBuilderTest, PreAnalyzedFieldTest, TestC= odecSupport, TestSchemaNameResource, FileBasedSpellCheckerTest, TestWordDel= imiterFilterFactory, CurrencyFieldOpenExchangeTest, TermVectorComponentTest= , TestAtomicUpdateErrorCases, TermVectorComponentDistributedTest, TestRando= mFaceting, TestFunctionQuery, TestFoldingMultitermQuery, TestFaceting, DOMU= tilTest, SampleTest, FieldAnalysisRequestHandlerTest, TestLMDirichletSimila= rityFactory, TestBadConfig, TestNumberUtils, PolyFieldTest, TestCopyFieldCo= llectionResource, TestSolrXml, PathHierarchyTokenizerFactoryTest, LeaderEle= ctionIntegrationTest, SpellPossibilityIteratorTest, TestUpdate, SimplePostT= oolTest, TestSweetSpotSimilarityFactory, DebugComponentTest, TestPropInject= Defaults, TestCSVLoader, UpdateParamsTest, TestStressLucene, SolrRequestPar= serTest, SoftAutoCommitTest, TestAnalyzedSuggestions, TestConfig, ResourceL= oaderTest, TestManagedSchemaFieldResource, OpenCloseCoreStressTest, TestTri= e, URLClassifyProcessorTest, TestJmxMonitoredMap, FullSolrCloudDistribCmdsT= est, TestPluginEnable, TestArbitraryIndexDir, TestCSVResponseWriter, TestJo= in, EchoParamsTest, TestManagedSchema, ShardSplitTest, SearchHandlerTest, T= estReversedWildcardFilterFactory, TestCoreDiscovery, BasicDistributedZkTest= , BasicDistributedZk2Test, UnloadDistributedZkTest, CollectionsAPIDistribut= edZkTest] [junit4:junit4] Completed in 292.20s, 1 test, 1 failure <<< FAILURES! [...truncated 443 lines...] BUILD FAILED /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:3= 78: The following error occurred while executing this line: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:3= 58: The following error occurred while executing this line: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:3= 9: The following error occurred while executing this line: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build.= xml:181: The following error occurred while executing this line: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/common= -build.xml:437: The following error occurred while executing this line: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/comm= on-build.xml:1240: The following error occurred while executing this line: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/comm= on-build.xml:884: There were test failures: 293 suites, 1219 tests, 1 error= , 1 failure, 18 ignored (6 assumptions) Total time: 107 minutes 41 seconds Build step 'Invoke Ant' marked build as failure Description set: Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseConcMa= rkSweepGC Archiving artifacts Recording test results Email was triggered for: Failure Sending email for trigger: Failure ------=_Part_116_1450143248.1367120635399 Content-Type: text/plain; charset=us-ascii --------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org For additional commands, e-mail: dev-help@lucene.apache.org ------=_Part_116_1450143248.1367120635399--