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 1B0DC109A5 for ; Wed, 1 May 2013 05:08:53 +0000 (UTC) Received: (qmail 5221 invoked by uid 500); 1 May 2013 05:08:51 -0000 Delivered-To: apmail-lucene-dev-archive@lucene.apache.org Received: (qmail 4635 invoked by uid 500); 1 May 2013 05:08:47 -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 4609 invoked by uid 99); 1 May 2013 05:08:46 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 01 May 2013 05:08:46 +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 (nike.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; Wed, 01 May 2013 05:08:23 +0000 Received: from serv1 (localhost.localdomain [127.0.0.1]) by mail.sd-datasolutions.de (Postfix) with ESMTP id 29DF314AA043 for ; Wed, 1 May 2013 05:08:03 +0000 (UTC) Date: Wed, 1 May 2013 05:07:48 +0000 (UTC) From: Policeman Jenkins Server To: dev@lucene.apache.org Message-ID: <1597379879.67.1367384883142.JavaMail.jenkins@serv1.sd-datasolutions.de> In-Reply-To: <448084593.65.1367380533306.JavaMail.jenkins@serv1.sd-datasolutions.de> References: <448084593.65.1367380533306.JavaMail.jenkins@serv1.sd-datasolutions.de> Subject: [JENKINS] Lucene-Solr-trunk-Linux (64bit/jdk1.8.0-ea-b86) - Build # 5431 - Still Failing! MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----=_Part_66_2028343524.1367384868493" X-Jenkins-Job: Lucene-Solr-trunk-Linux X-Jenkins-Result: FAILURE X-Virus-Checked: Checked by ClamAV on apache.org ------=_Part_66_2028343524.1367384868493 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/5431/ Java: 64bit/jdk1.8.0-ea-b86 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC 2 tests failed. REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch Error Message: Wrong doc count on shard1_0 expected:<318> but was:<317> Stack Trace: java.lang.AssertionError: Wrong doc count on shard1_0 expected:<318> but wa= s:<317> =09at __randomizedtesting.SeedInfo.seed([48A0C3D79B0D8FDD:C9464DCFEC52EFE1]= :0) =09at org.junit.Assert.fail(Assert.java:93) =09at org.junit.Assert.failNotEquals(Assert.java:647) =09at org.junit.Assert.assertEquals(Assert.java:128) =09at org.junit.Assert.assertEquals(Assert.java:472) =09at org.apache.solr.cloud.ShardSplitTest.checkDocCountsAndShardStates(Sha= rdSplitTest.java:158) =09at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:134) =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:490) =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.UnloadDistributedZkTest.testDistribSearch Error Message: Still found shard2 in collection test_unload_shard_and_collection Stack Trace: java.lang.AssertionError: Still found shard2 in collection test_unload_shar= d_and_collection =09at __randomizedtesting.SeedInfo.seed([48A0C3D79B0D8FDD:C9464DCFEC52EFE1]= :0) =09at org.junit.Assert.fail(Assert.java:93) =09at org.apache.solr.cloud.UnloadDistributedZkTest.testUnloadShardAndColle= ction(UnloadDistributedZkTest.java:127) =09at org.apache.solr.cloud.UnloadDistributedZkTest.doTest(UnloadDistribute= dZkTest.java:77) =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:490) =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 9377 lines...] [junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.428; org.apache.solr.BaseD= istributedSearchTestCase; Setting hostContext system property: / [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.433; org.apache.solr.SolrT= estCaseJ4; ###Starting testDistribSearch [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.433; 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-05-01 04:53:14.434; org.apache.solr.cloud= .ZkTestServer$ZKServerMain; Starting server [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.534; org.apache.solr.cloud= .ZkTestServer; start zk server on port:45543 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.535; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.625; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@4d8946ee name:ZooKeeperConnection Watcher:127.0.0.1:45543 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.626; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.626; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /solr [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.631; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.633; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@434eb12f name:ZooKeeperConnection Watcher:127.0.0.1:45543/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.633; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.633; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.637; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/shards [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.640; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.642; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/shards [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.645; org.apache.solr.cloud= .AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux= /solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml = to /configs/conf1/solrconfig.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.646; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.650; org.apache.solr.cloud= .AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux= /solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /confi= gs/conf1/schema.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.651; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.655; org.apache.solr.cloud= .AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux= /solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /co= nfigs/conf1/stopwords.txt [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.656; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.659; org.apache.solr.cloud= .AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux= /solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /co= nfigs/conf1/protwords.txt [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.659; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.662; org.apache.solr.cloud= .AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux= /solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /con= figs/conf1/currency.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.663; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.667; org.apache.solr.cloud= .AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux= /solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.= json to /configs/conf1/open-exchange-rates.json [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.667; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.670; org.apache.solr.cloud= .AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux= /solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Acc= ent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.670; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.674; org.apache.solr.cloud= .AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux= /solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to = /configs/conf1/old_synonyms.txt [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.674; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.677; org.apache.solr.cloud= .AbstractZkTestCase; put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux= /solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /con= figs/conf1/synonyms.txt [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.678; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.743; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.750; org.eclipse.jetty.ser= ver.AbstractConnector; Started SelectChannelConnector@127.0.0.1:44688 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.750; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.751; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.751; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/= workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache= .solr.cloud.ShardSplitTest-controljetty-1367383994682 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.751; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/w= orkspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.= solr.cloud.ShardSplitTest-controljetty-1367383994682/solr.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.752; org.apache.solr.core.= CoreContainer; New CoreContainer 627232888 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.752; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/wor= kspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.so= lr.cloud.ShardSplitTest-controljetty-1367383994682/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.752; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins= /workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apach= e.solr.cloud.ShardSplitTest-controljetty-1367383994682/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.801; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.801; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.802; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.802; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.802; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.802; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.803; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.803; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.803; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.804; 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-05-01 04:53:14.807; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.807; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:45543/solr [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.808; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.809; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.810; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@9a5ae1d name:ZooKeeperConnection Watcher:127.0.0.1:45543 got event W= atchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.811; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.813; 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-05-01 04:53:14.816; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.818; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@6c86f440 name:ZooKeeperConnection Watcher:127.0.0.1:45543/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.818; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.820; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/queue [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.824; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/collection-queue-work [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.827; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.829; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:446= 88_ [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.829; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:44688_ [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.832; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer_elect/election [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.837; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer_elect/leader [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.838; org.apache.solr.cloud= .Overseer; Overseer (id=3D89612877459292163-127.0.0.1:44688_-n_0000000000) = starting [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.841; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/queue-work [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.844; org.apache.solr.cloud= .OverseerCollectionProcessor; Process current queue of collection creations [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.844; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /clusterstate.json [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.847; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /aliases.json [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.848; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.851; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Starting to work on the main queue [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.865; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/= jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./or= g.apache.solr.cloud.ShardSplitTest-controljetty-1367383994682/collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.865; org.apache.solr.cloud= .ZkController; Check for collection zkNode:control_collection [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.866; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.866; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/control_collection [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.867; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins= /workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apach= e.solr.cloud.ShardSplitTest-controljetty-1367383994682/collection1/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.867; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-tru= nk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-= controljetty-1367383994682/collection1/lib/README' to classloader [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.868; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-tru= nk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-= controljetty-1367383994682/collection1/lib/classes/' to classloader [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.891; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_50 [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.925; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.927; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:14.932; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.299; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.304; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.306; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.325; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.329; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.342; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-05-01 04:53:15.345; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-05-01 04:53:15.345; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.345; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-05-01 04:53:15.348; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-05-01 04:53:15.348; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.348; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.349; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/= Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.clou= d.ShardSplitTest-controljetty-1367383994682/collection1/, dataDir=3D./org.a= pache.solr.cloud.ShardSplitTest-1367383994433/control/data/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.349; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@15475813 [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.350; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.351; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.S= hardSplitTest-1367383994433/control/data [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.351; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ShardSplitTest-1367383994433/control/data/index/ [junit4:junit4] 1> WARN - 2013-05-01 04:53:15.352; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Shard= SplitTest-1367383994433/control/data/index' doesn't exist. Creating new ind= ex... [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.352; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.S= hardSplitTest-1367383994433/control/data/index [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.355; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@5197fa83 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@2b299ec4),segFN=3Dsegments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.355; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.358; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.358; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.359; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.360; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.361; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.361; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.362; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.362; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.363; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.367; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.373; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@5ce0a029 main [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.373; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Sha= rdSplitTest-1367383994433/control/data/tlog [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.374; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.375; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.380; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@5ce0a029 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.381; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-05-01 04:53:15.382; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-05-01 04:53:16.368; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:16.370; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "base_url":"http://127.0.0.1:44688", [junit4:junit4] 1> "core_node_name":"1", [junit4:junit4] 1> "node_name":"127.0.0.1:44688_", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "collection":"control_collection", [junit4:junit4] 1> "shard_state":"active"} [junit4:junit4] 1> INFO - 2013-05-01 04:53:16.370; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Create collection control_collection with nu= mShards 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:16.370; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:16.378; 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-05-01 04:53:17.384; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.385; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :44688 collection:control_collection shard:shard1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.386; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elec= t/shard1/election [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.400; org.apache.solr.cloud= .ShardLeaderElectionContext; Running the leader process. [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.406; org.apache.solr.cloud= .ShardLeaderElectionContext; Enough replicas found to continue. [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.406; org.apache.solr.cloud= .ShardLeaderElectionContext; I may be the new leader - try and sync [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.406; org.apache.solr.cloud= .SyncStrategy; Sync replicas to http://127.0.0.1:44688/collection1/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.407; org.apache.solr.cloud= .SyncStrategy; Sync Success - now sync replicas to me [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.407; org.apache.solr.cloud= .SyncStrategy; http://127.0.0.1:44688/collection1/ has no replicas [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.407; org.apache.solr.cloud= .ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:44688/co= llection1/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.408; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/sha= rd1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.886; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.901; 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-05-01 04:53:17.922; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:44688/collection1/ and leader is htt= p://127.0.0.1:44688/collection1/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.922; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:44688 [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.923; org.apache.solr.cloud= .ZkController; I am the leader, no recovery necessary [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.923; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.923; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.926; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.929; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/mnt/ssd/jenkins/workspace/Lucene-Solr-tr= unk-Linux/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.929; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.930; 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-05-01 04:53:17.936; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config: [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.938; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.941; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@4647e1f9 name:ZooKeeperConnection Watcher:127.0.0.1:45543/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.941; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.945; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:17.950; org.apache.solr.cloud= .ChaosMonkey; monkey: init - expire sessions:true cause connection loss:tru= e [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.026; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.029; org.eclipse.jetty.ser= ver.AbstractConnector; Started SelectChannelConnector@127.0.0.1:34880 [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.030; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.030; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.030; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/= workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache= .solr.cloud.ShardSplitTest-jetty1-1367383997950 [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.030; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/w= orkspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.= solr.cloud.ShardSplitTest-jetty1-1367383997950/solr.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.031; org.apache.solr.core.= CoreContainer; New CoreContainer 913360592 [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.031; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/wor= kspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.so= lr.cloud.ShardSplitTest-jetty1-1367383997950/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.031; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins= /workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apach= e.solr.cloud.ShardSplitTest-jetty1-1367383997950/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.077; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.077; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.078; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.078; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.078; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.079; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.079; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.079; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.080; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.080; 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-05-01 04:53:18.083; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.083; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:45543/solr [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.084; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.085; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.086; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@3080014 name:ZooKeeperConnection Watcher:127.0.0.1:45543 got event W= atchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.087; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.090; 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-05-01 04:53:18.093; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.095; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@7d55288b name:ZooKeeperConnection Watcher:127.0.0.1:45543/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.095; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:18.102; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.107; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:348= 80_ [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.109; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:34880_ [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.115; 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-05-01 04:53:19.115; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.115; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.118; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.125; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/= jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./or= g.apache.solr.cloud.ShardSplitTest-jetty1-1367383997950/collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.126; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.127; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.127; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.130; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins= /workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apach= e.solr.cloud.ShardSplitTest-jetty1-1367383997950/collection1/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.131; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-tru= nk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-= jetty1-1367383997950/collection1/lib/README' to classloader [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.131; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-tru= nk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-= jetty1-1367383997950/collection1/lib/classes/' to classloader [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.160; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_50 [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.195; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.197; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.200; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.412; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.413; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "base_url":"http://127.0.0.1:44688", [junit4:junit4] 1> "core_node_name":"1", [junit4:junit4] 1> "node_name":"127.0.0.1:44688_", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "collection":"control_collection", [junit4:junit4] 1> "shard_state":"active"} [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.418; 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-05-01 04:53:19.418; 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-05-01 04:53:19.418; 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-05-01 04:53:19.550; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.555; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.557; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.579; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.584; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.589; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-05-01 04:53:19.591; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-05-01 04:53:19.592; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.592; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-05-01 04:53:19.594; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-05-01 04:53:19.595; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.595; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.595; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/= Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.clou= d.ShardSplitTest-jetty1-1367383997950/collection1/, dataDir=3D./org.apache.= solr.cloud.ShardSplitTest-1367383994433/jetty1/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.596; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@15475813 [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.597; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.597; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.S= hardSplitTest-1367383994433/jetty1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.598; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ShardSplitTest-1367383994433/jetty1/index/ [junit4:junit4] 1> WARN - 2013-05-01 04:53:19.598; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Shard= SplitTest-1367383994433/jetty1/index' doesn't exist. Creating new index... [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.599; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.S= hardSplitTest-1367383994433/jetty1/index [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.601; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@7d579e15 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@d0ab7bf),segFN=3Dsegments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.601; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.604; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.605; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.606; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.607; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.607; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.608; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.608; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.609; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.610; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.614; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.618; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@513f771 main [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.619; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Sha= rdSplitTest-1367383994433/jetty1/tlog [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.620; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.620; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.626; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@513f771 main{Stand= ardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.630; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-05-01 04:53:19.630; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-05-01 04:53:20.925; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:20.926; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "base_url":"http://127.0.0.1:34880", [junit4:junit4] 1> "core_node_name":"2", [junit4:junit4] 1> "node_name":"127.0.0.1:34880_", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_state":"active"} [junit4:junit4] 1> INFO - 2013-05-01 04:53:20.927; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Create collection collection1 with numShards= 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:20.927; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:20.935; 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-05-01 04:53:20.935; 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-05-01 04:53:20.935; 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-05-01 04:53:21.632; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:21.633; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :34880 collection:collection1 shard:shard2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:21.634; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard= 2/election [junit4:junit4] 1> INFO - 2013-05-01 04:53:21.640; org.apache.solr.cloud= .ShardLeaderElectionContext; Running the leader process. [junit4:junit4] 1> INFO - 2013-05-01 04:53:21.642; org.apache.solr.cloud= .ShardLeaderElectionContext; Enough replicas found to continue. [junit4:junit4] 1> INFO - 2013-05-01 04:53:21.643; org.apache.solr.cloud= .ShardLeaderElectionContext; I may be the new leader - try and sync [junit4:junit4] 1> INFO - 2013-05-01 04:53:21.643; org.apache.solr.cloud= .SyncStrategy; Sync replicas to http://127.0.0.1:34880/collection1/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:21.643; org.apache.solr.cloud= .SyncStrategy; Sync Success - now sync replicas to me [junit4:junit4] 1> INFO - 2013-05-01 04:53:21.643; org.apache.solr.cloud= .SyncStrategy; http://127.0.0.1:34880/collection1/ has no replicas [junit4:junit4] 1> INFO - 2013-05-01 04:53:21.643; org.apache.solr.cloud= .ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:34880/co= llection1/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:21.644; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.444; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.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: 2) [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.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: 2) [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.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: 2) [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.503; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:34880/collection1/ and leader is htt= p://127.0.0.1:34880/collection1/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.503; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:34880 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.503; org.apache.solr.cloud= .ZkController; I am the leader, no recovery necessary [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.503; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.504; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.505; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.507; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/mnt/ssd/jenkins/workspace/Lucene-Solr-tr= unk-Linux/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.507; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.507; 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-05-01 04:53:22.570; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.572; org.eclipse.jetty.ser= ver.AbstractConnector; Started SelectChannelConnector@127.0.0.1:52172 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.573; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.574; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.574; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/= workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache= .solr.cloud.ShardSplitTest-jetty2-1367384002511 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.574; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/w= orkspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.= solr.cloud.ShardSplitTest-jetty2-1367384002511/solr.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.575; org.apache.solr.core.= CoreContainer; New CoreContainer 872062204 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.575; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/wor= kspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.so= lr.cloud.ShardSplitTest-jetty2-1367384002511/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.575; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins= /workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apach= e.solr.cloud.ShardSplitTest-jetty2-1367384002511/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.634; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.634; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.634; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.635; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.635; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.635; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.636; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.636; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.636; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.637; 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-05-01 04:53:22.640; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.640; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:45543/solr [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.640; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.641; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.643; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@4f004852 name:ZooKeeperConnection Watcher:127.0.0.1:45543 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.644; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.647; 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-05-01 04:53:22.650; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.652; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@723f882f name:ZooKeeperConnection Watcher:127.0.0.1:45543/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.652; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:22.657; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.662; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:521= 72_ [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.665; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:52172_ [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.670; 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-05-01 04:53:23.670; 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-05-01 04:53:23.671; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.671; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.672; 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-05-01 04:53:23.673; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.674; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.681; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/= jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./or= g.apache.solr.cloud.ShardSplitTest-jetty2-1367384002511/collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.681; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.682; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.683; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.685; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins= /workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apach= e.solr.cloud.ShardSplitTest-jetty2-1367384002511/collection1/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.686; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-tru= nk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-= jetty2-1367384002511/collection1/lib/README' to classloader [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.687; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-tru= nk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-= jetty2-1367384002511/collection1/lib/classes/' to classloader [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.742; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_50 [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.779; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.782; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.793; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.978; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.979; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "shard":"shard2", [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "base_url":"http://127.0.0.1:34880", [junit4:junit4] 1> "core_node_name":"2", [junit4:junit4] 1> "node_name":"127.0.0.1:34880_", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_state":"active"} [junit4:junit4] 1> INFO - 2013-05-01 04:53:23.984; 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-05-01 04:53:23.984; 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-05-01 04:53:23.984; 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-05-01 04:53:23.984; 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-05-01 04:53:24.158; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.164; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.166; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.187; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.192; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.198; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-05-01 04:53:24.200; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-05-01 04:53:24.201; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.202; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-05-01 04:53:24.204; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-05-01 04:53:24.205; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.205; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.206; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/= Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.clou= d.ShardSplitTest-jetty2-1367384002511/collection1/, dataDir=3D./org.apache.= solr.cloud.ShardSplitTest-1367383994433/jetty2/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.206; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@15475813 [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.207; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.208; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.S= hardSplitTest-1367383994433/jetty2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.208; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ShardSplitTest-1367383994433/jetty2/index/ [junit4:junit4] 1> WARN - 2013-05-01 04:53:24.208; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Shard= SplitTest-1367383994433/jetty2/index' doesn't exist. Creating new index... [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.209; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.S= hardSplitTest-1367383994433/jetty2/index [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.211; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@7b773269 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@52973ed4),segFN=3Dsegments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.212; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.215; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.216; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.216; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.217; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.218; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.219; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.219; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.220; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.221; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.224; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.226; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@124c016c main [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.226; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Sha= rdSplitTest-1367383994433/jetty2/tlog [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.227; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.227; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.230; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@124c016c main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.232; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-05-01 04:53:24.232; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-05-01 04:53:25.490; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:25.491; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "base_url":"http://127.0.0.1:52172", [junit4:junit4] 1> "core_node_name":"3", [junit4:junit4] 1> "node_name":"127.0.0.1:52172_", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_state":"active"} [junit4:junit4] 1> INFO - 2013-05-01 04:53:25.491; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:25.491; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:25.499; 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-05-01 04:53:25.499; 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-05-01 04:53:25.499; 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-05-01 04:53:25.499; 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-05-01 04:53:26.234; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:26.235; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :52172 collection:collection1 shard:shard1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:26.236; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard= 1/election [junit4:junit4] 1> INFO - 2013-05-01 04:53:26.247; org.apache.solr.cloud= .ShardLeaderElectionContext; Running the leader process. [junit4:junit4] 1> INFO - 2013-05-01 04:53:26.251; org.apache.solr.cloud= .ShardLeaderElectionContext; Enough replicas found to continue. [junit4:junit4] 1> INFO - 2013-05-01 04:53:26.252; org.apache.solr.cloud= .ShardLeaderElectionContext; I may be the new leader - try and sync [junit4:junit4] 1> INFO - 2013-05-01 04:53:26.252; org.apache.solr.cloud= .SyncStrategy; Sync replicas to http://127.0.0.1:52172/collection1/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:26.252; org.apache.solr.cloud= .SyncStrategy; Sync Success - now sync replicas to me [junit4:junit4] 1> INFO - 2013-05-01 04:53:26.253; org.apache.solr.cloud= .SyncStrategy; http://127.0.0.1:52172/collection1/ has no replicas [junit4:junit4] 1> INFO - 2013-05-01 04:53:26.253; org.apache.solr.cloud= .ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:52172/co= llection1/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:26.253; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.006; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.021; 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-05-01 04:53:27.021; 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-05-01 04:53:27.021; 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-05-01 04:53:27.021; 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-05-01 04:53:27.065; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:52172/collection1/ and leader is htt= p://127.0.0.1:52172/collection1/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.065; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:52172 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.065; org.apache.solr.cloud= .ZkController; I am the leader, no recovery necessary [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.066; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.066; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.069; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.071; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/mnt/ssd/jenkins/workspace/Lucene-Solr-tr= unk-Linux/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.072; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.072; 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-05-01 04:53:27.166; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.169; org.eclipse.jetty.ser= ver.AbstractConnector; Started SelectChannelConnector@127.0.0.1:56665 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.170; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.170; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.171; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/= workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache= .solr.cloud.ShardSplitTest-jetty3-1367384007079 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.171; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/w= orkspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.= solr.cloud.ShardSplitTest-jetty3-1367384007079/solr.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.171; org.apache.solr.core.= CoreContainer; New CoreContainer 1299429589 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.172; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/wor= kspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.so= lr.cloud.ShardSplitTest-jetty3-1367384007079/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.172; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins= /workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apach= e.solr.cloud.ShardSplitTest-jetty3-1367384007079/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.208; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.209; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.209; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.209; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.210; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.210; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.210; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.211; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.211; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.211; 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-05-01 04:53:27.214; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.214; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:45543/solr [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.215; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.216; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.218; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@60e68588 name:ZooKeeperConnection Watcher:127.0.0.1:45543 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.219; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.221; 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-05-01 04:53:27.225; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.235; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@aed1c7c name:ZooKeeperConnection Watcher:127.0.0.1:45543/solr got ev= ent WatchedEvent state:SyncConnected type:None path:null path:null type:Non= e [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.236; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:27.242; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.247; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:566= 65_ [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.249; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:56665_ [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.254; 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-05-01 04:53:28.255; 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-05-01 04:53:28.255; 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-05-01 04:53:28.256; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.256; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.257; 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-05-01 04:53:28.268; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.269; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.270; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.276; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/= jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./or= g.apache.solr.cloud.ShardSplitTest-jetty3-1367384007079/collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.276; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.278; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.278; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.280; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins= /workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apach= e.solr.cloud.ShardSplitTest-jetty3-1367384007079/collection1/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.281; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-tru= nk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-= jetty3-1367384007079/collection1/lib/README' to classloader [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.282; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-tru= nk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-= jetty3-1367384007079/collection1/lib/classes/' to classloader [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.324; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_50 [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.361; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.363; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.367; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.536; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.536; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "base_url":"http://127.0.0.1:52172", [junit4:junit4] 1> "core_node_name":"3", [junit4:junit4] 1> "node_name":"127.0.0.1:52172_", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_state":"active"} [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.541; 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-05-01 04:53:28.541; 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-05-01 04:53:28.541; 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-05-01 04:53:28.541; 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-05-01 04:53:28.541; 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-05-01 04:53:28.746; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.751; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.753; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.777; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.782; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.797; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-05-01 04:53:28.800; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-05-01 04:53:28.801; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.801; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-05-01 04:53:28.804; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-05-01 04:53:28.804; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.805; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.805; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/= Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.clou= d.ShardSplitTest-jetty3-1367384007079/collection1/, dataDir=3D./org.apache.= solr.cloud.ShardSplitTest-1367383994433/jetty3/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.805; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@15475813 [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.806; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.807; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.S= hardSplitTest-1367383994433/jetty3 [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.808; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ShardSplitTest-1367383994433/jetty3/index/ [junit4:junit4] 1> WARN - 2013-05-01 04:53:28.808; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Shard= SplitTest-1367383994433/jetty3/index' doesn't exist. Creating new index... [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.809; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.S= hardSplitTest-1367383994433/jetty3/index [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.811; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@5cc4a3e7 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@33ab7e75),segFN=3Dsegments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.812; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.816; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.817; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.818; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.818; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.819; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.820; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.820; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.821; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.822; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.825; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.827; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@12295bd4 main [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.827; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Sha= rdSplitTest-1367383994433/jetty3/tlog [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.828; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.828; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.834; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@12295bd4 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.838; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-05-01 04:53:28.838; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.048; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.049; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "base_url":"http://127.0.0.1:56665", [junit4:junit4] 1> "core_node_name":"4", [junit4:junit4] 1> "node_name":"127.0.0.1:56665_", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_state":"active"} [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.050; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.050; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.059; 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-05-01 04:53:30.059; 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-05-01 04:53:30.059; 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-05-01 04:53:30.059; 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-05-01 04:53:30.059; 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-05-01 04:53:30.841; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.842; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :56665 collection:collection1 shard:shard2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.848; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:56665/collection1/ and leader is htt= p://127.0.0.1:34880/collection1/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.848; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:56665 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.849; org.apache.solr.cloud= .ZkController; Core needs to recover:collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.849; org.apache.solr.updat= e.DefaultSolrCoreState; Running recovery - first canceling any ongoing reco= very [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.850; org.apache.solr.cloud= .RecoveryStrategy; Starting recovery process. core=3Dcollection1 recoverin= gAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.851; org.apache.solr.cloud= .RecoveryStrategy; ###### startupVersions=3D[] [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.851; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.852; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Drecovering [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.852; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.854; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/mnt/ssd/jenkins/workspace/Lucene-Solr-tr= unk-Linux/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.855; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.854; 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-05-01 04:53:30.855; 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-05-01 04:53:30.864; 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-05-01 04:53:30.931; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.934; org.eclipse.jetty.ser= ver.AbstractConnector; Started SelectChannelConnector@127.0.0.1:51500 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.935; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.935; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.936; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /mnt/ssd/jenkins/= workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache= .solr.cloud.ShardSplitTest-jetty4-1367384010862 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.936; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /mnt/ssd/jenkins/w= orkspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.= solr.cloud.ShardSplitTest-jetty4-1367384010862/solr.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.936; org.apache.solr.core.= CoreContainer; New CoreContainer 1738922500 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.937; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/wor= kspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.so= lr.cloud.ShardSplitTest-jetty4-1367384010862/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.937; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins= /workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apach= e.solr.cloud.ShardSplitTest-jetty4-1367384010862/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.983; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.983; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.984; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.984; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.984; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.985; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.985; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.986; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.986; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.986; 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-05-01 04:53:30.990; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.991; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:45543/solr [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.991; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.992; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.994; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@345f8dc4 name:ZooKeeperConnection Watcher:127.0.0.1:45543 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.995; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:30.998; 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-05-01 04:53:31.002; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:31.004; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@575084ac name:ZooKeeperConnection Watcher:127.0.0.1:45543/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-05-01 04:53:31.004; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-05-01 04:53:31.010; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:31.568; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:31.570; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "shard":"shard2", [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "base_url":"http://127.0.0.1:56665", [junit4:junit4] 1> "core_node_name":"4", [junit4:junit4] 1> "node_name":"127.0.0.1:56665_", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "state":"recovering", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_state":"active"} [junit4:junit4] 1> INFO - 2013-05-01 04:53:31.579; 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-05-01 04:53:31.580; 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-05-01 04:53:31.580; 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-05-01 04:53:31.580; 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-05-01 04:53:31.580; 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-05-01 04:53:31.580; 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-05-01 04:53:31.864; 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-05-01 04:53:31.865; org.apache.solr.servl= et.SolrDispatchFilter; [admin] webapp=3Dnull path=3D/admin/cores params=3D{= core=3Dcollection1&onlyIfLeader=3Dtrue&version=3D2&checkLive=3Dtrue&coreNod= eName=3D4&action=3DPREPRECOVERY&wt=3Djavabin&state=3Drecovering&nodeName=3D= 127.0.0.1:56665_} status=3D0 QTime=3D1002=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.016; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:515= 00_ [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.019; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:51500_ [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.023; 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-05-01 04:53:32.024; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.024; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.024; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.025; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.025; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.025; 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-05-01 04:53:32.025; 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-05-01 04:53:32.026; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.024; 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-05-01 04:53:32.024; 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-05-01 04:53:32.026; 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-05-01 04:53:32.035; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/= jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./or= g.apache.solr.cloud.ShardSplitTest-jetty4-1367384010862/collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.036; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.037; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.037; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.040; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/mnt/ssd/jenkins= /workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apach= e.solr.cloud.ShardSplitTest-jetty4-1367384010862/collection1/' [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.041; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-tru= nk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-= jetty4-1367384010862/collection1/lib/README' to classloader [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.041; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-tru= nk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-= jetty4-1367384010862/collection1/lib/classes/' to classloader [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.085; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_50 [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.124; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.126; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.130; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.478; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.483; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.486; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.507; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.512; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.518; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-05-01 04:53:32.520; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-05-01 04:53:32.521; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.522; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-05-01 04:53:32.524; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-05-01 04:53:32.524; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.525; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.525; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/= Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.clou= d.ShardSplitTest-jetty4-1367384010862/collection1/, dataDir=3D./org.apache.= solr.cloud.ShardSplitTest-1367383994433/jetty4/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.526; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@15475813 [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.526; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.527; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.S= hardSplitTest-1367383994433/jetty4 [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.528; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ShardSplitTest-1367383994433/jetty4/index/ [junit4:junit4] 1> WARN - 2013-05-01 04:53:32.528; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Shard= SplitTest-1367383994433/jetty4/index' doesn't exist. Creating new index... [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.529; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.S= hardSplitTest-1367383994433/jetty4/index [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.531; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@2b826c0c lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@2204daed),segFN=3Dsegments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.531; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.535; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.535; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.536; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.537; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.538; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.538; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.539; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.540; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.540; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.544; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.546; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@5360b4e9 main [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.546; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Sha= rdSplitTest-1367383994433/jetty4/tlog [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.546; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.547; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.552; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@5360b4e9 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.555; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-05-01 04:53:32.555; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.088; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.089; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "base_url":"http://127.0.0.1:51500", [junit4:junit4] 1> "core_node_name":"5", [junit4:junit4] 1> "node_name":"127.0.0.1:51500_", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_state":"active"} [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.089; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.089; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.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: 5) [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.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: 5) [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.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: 5) [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.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: 5) [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.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: 5) [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.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: 5) [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.558; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.558; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :51500 collection:collection1 shard:shard1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.565; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:51500/collection1/ and leader is htt= p://127.0.0.1:52172/collection1/ [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.565; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:51500 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.566; org.apache.solr.cloud= .ZkController; Core needs to recover:collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.566; org.apache.solr.updat= e.DefaultSolrCoreState; Running recovery - first canceling any ongoing reco= very [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.567; org.apache.solr.cloud= .RecoveryStrategy; Starting recovery process. core=3Dcollection1 recoverin= gAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.568; org.apache.solr.cloud= .RecoveryStrategy; ###### startupVersions=3D[] [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.568; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.568; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Drecovering [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.569; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.570; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/mnt/ssd/jenkins/workspace/Lucene-Solr-tr= unk-Linux/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.571; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.572; 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-05-01 04:53:33.575; 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-05-01 04:53:33.579; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.581; org.apache.solr.cloud= .AbstractFullDistribZkTestBase; Wait for recoveries to finish - wait 15 for= each attempt [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.582; org.apache.solr.cloud= .AbstractDistribZkTestBase; Wait for recoveries to finish - collection: col= lection1 failOnTimeout:true timeout (sec):15 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.582; 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-05-01 04:53:33.584; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.867; org.apache.solr.cloud= .RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:34880/colle= ction1/ core=3Dcollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.867; org.apache.solr.updat= e.PeerSync; PeerSync: core=3Dcollection1 url=3Dhttp://127.0.0.1:56665 START= replicas=3D[http://127.0.0.1:34880/collection1/] nUpdates=3D100 [junit4:junit4] 1> WARN - 2013-05-01 04:53:33.868; org.apache.solr.updat= e.PeerSync; no frame of reference to tell of we've missed updates [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.869; org.apache.solr.cloud= .RecoveryStrategy; PeerSync Recovery was not successful - trying replicatio= n. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.869; org.apache.solr.cloud= .RecoveryStrategy; Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.869; org.apache.solr.cloud= .RecoveryStrategy; Begin buffering updates. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.870; org.apache.solr.updat= e.UpdateLog; Starting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog= =3Dnull} [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.870; org.apache.solr.cloud= .RecoveryStrategy; Attempting to replicate from http://127.0.0.1:34880/coll= ection1/. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.871; 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-05-01 04:53:33.878; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/get params=3D{version=3D2&distrib= =3Dfalse&wt=3Djavabin&qt=3D/get&getVersions=3D100} status=3D0 QTime=3D1=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.878; 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-05-01 04:53:33.881; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@7d579e15 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@d0ab7bf),segFN=3Dsegments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.882; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.883; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@7d579e15 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@d0ab7bf),segFN=3Dsegments_1,generation=3D1} [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@7d579e15 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@d0ab7bf),segFN=3Dsegments_2,generation=3D2} [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.884; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.884; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@11351241 realtime [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.885; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.886; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{commit=3Dtrue&waitSearcher=3Dtrue&version=3D2&wt=3Djavabin&openSearch= er=3Dfalse&softCommit=3Dfalse&commit_end_point=3Dtrue} {commit=3D} 0 8 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.887; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.888; org.apache.solr.handl= er.SnapPuller; No value set for 'pollInterval'. Timer Task not started. [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.895; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.895; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{version=3D2= &command=3Dindexversion&qt=3D/replication&wt=3Djavabin} status=3D0 QTime=3D= 6=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.896; org.apache.solr.handl= er.SnapPuller; Master's generation: 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.897; org.apache.solr.handl= er.SnapPuller; Slave's generation: 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.897; org.apache.solr.handl= er.SnapPuller; Starting replication process [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.900; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{version=3D2= &command=3Dfilelist&qt=3D/replication&wt=3Djavabin&generation=3D2} status= =3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.901; org.apache.solr.handl= er.SnapPuller; Number of files in latest index in master: 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.903; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.S= hardSplitTest-1367383994433/jetty3/index.20130501005333902 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.903; org.apache.solr.handl= er.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.= RAMDirectory@36089038 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFac= tory@5d481806) fullCopy=3Dfalse [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.906; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{checksum=3D= true&command=3Dfilecontent&wt=3Dfilestream&qt=3D/replication&generation=3D2= &file=3Dsegments_2} status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.908; org.apache.solr.handl= er.SnapPuller; Total time taken for download : 0 secs [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.910; org.apache.solr.updat= e.DefaultSolrCoreState; Creating new IndexWriter... [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.910; org.apache.solr.updat= e.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=3Dcolle= ction1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.912; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@5cc4a3e7 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@33ab7e75),segFN=3Dsegments_1,generation=3D1} [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@5cc4a3e7 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@33ab7e75),segFN=3Dsegments_2,generation=3D2} [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.913; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.914; org.apache.solr.updat= e.DefaultSolrCoreState; New IndexWriter is ready to be used. [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.914; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@12c8ff56 main [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.916; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@12c8ff56 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.916; org.apache.solr.core.= CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ShardSpli= tTest-1367383994433/jetty3/index.20130501005333902 [CachedDir<>] [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.917; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ShardSp= litTest-1367383994433/jetty3/index.20130501005333902 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.917; org.apache.solr.core.= CachingDirectoryFactory; Removing directory before core close: ./org.apache= .solr.cloud.ShardSplitTest-1367383994433/jetty3/index.20130501005333902 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.918; org.apache.solr.cloud= .RecoveryStrategy; No replay needed. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.918; org.apache.solr.cloud= .RecoveryStrategy; Replication Recovery was successful - registering as Act= ive. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.918; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.918; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-05-01 04:53:33.921; org.apache.solr.cloud= .RecoveryStrategy; Finished recovery process. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:34.586; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:34.600; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:34.601; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "base_url":"http://127.0.0.1:51500", [junit4:junit4] 1> "core_node_name":"5", [junit4:junit4] 1> "node_name":"127.0.0.1:51500_", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "state":"recovering", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_state":"active"} [junit4:junit4] 1> INFO - 2013-05-01 04:53:34.605; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "shard":"shard2", [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "base_url":"http://127.0.0.1:56665", [junit4:junit4] 1> "core_node_name":"4", [junit4:junit4] 1> "node_name":"127.0.0.1:56665_", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_state":"active"} [junit4:junit4] 1> INFO - 2013-05-01 04:53:34.609; 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-05-01 04:53:34.609; 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-05-01 04:53:34.609; 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-05-01 04:53:34.609; 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-05-01 04:53:34.609; 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-05-01 04:53:34.609; 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-05-01 04:53:35.584; org.apache.solr.handl= er.admin.CoreAdminHandler; Waited coreNodeName: 5, state: recovering, check= Live: true, onlyIfLeader: true for: 2 seconds. [junit4:junit4] 1> INFO - 2013-05-01 04:53:35.584; org.apache.solr.servl= et.SolrDispatchFilter; [admin] webapp=3Dnull path=3D/admin/cores params=3D{= core=3Dcollection1&onlyIfLeader=3Dtrue&version=3D2&checkLive=3Dtrue&coreNod= eName=3D5&action=3DPREPRECOVERY&wt=3Djavabin&state=3Drecovering&nodeName=3D= 127.0.0.1:51500_} status=3D0 QTime=3D2002=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:35.589; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:36.592; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.586; org.apache.solr.cloud= .RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:52172/colle= ction1/ core=3Dcollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.586; org.apache.solr.updat= e.PeerSync; PeerSync: core=3Dcollection1 url=3Dhttp://127.0.0.1:51500 START= replicas=3D[http://127.0.0.1:52172/collection1/] nUpdates=3D100 [junit4:junit4] 1> WARN - 2013-05-01 04:53:37.587; org.apache.solr.updat= e.PeerSync; no frame of reference to tell of we've missed updates [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.587; org.apache.solr.cloud= .RecoveryStrategy; PeerSync Recovery was not successful - trying replicatio= n. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.588; org.apache.solr.cloud= .RecoveryStrategy; Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.588; org.apache.solr.cloud= .RecoveryStrategy; Begin buffering updates. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.588; org.apache.solr.updat= e.UpdateLog; Starting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog= =3Dnull} [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.588; org.apache.solr.cloud= .RecoveryStrategy; Attempting to replicate from http://127.0.0.1:52172/coll= ection1/. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.589; 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-05-01 04:53:37.604; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.606; 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-05-01 04:53:37.606; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/get params=3D{version=3D2&distrib= =3Dfalse&wt=3Djavabin&qt=3D/get&getVersions=3D100} status=3D0 QTime=3D1=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.610; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@7b773269 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@52973ed4),segFN=3Dsegments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.612; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.613; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@7b773269 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@52973ed4),segFN=3Dsegments_1,generation=3D1} [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@7b773269 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@52973ed4),segFN=3Dsegments_2,generation=3D2} [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.613; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.614; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@4cc4e63 realtime [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.614; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.615; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{commit=3Dtrue&waitSearcher=3Dtrue&version=3D2&wt=3Djavabin&openSearch= er=3Dfalse&softCommit=3Dfalse&commit_end_point=3Dtrue} {commit=3D} 0 9 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.616; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.617; org.apache.solr.handl= er.SnapPuller; No value set for 'pollInterval'. Timer Task not started. [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.621; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.621; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{version=3D2= &command=3Dindexversion&qt=3D/replication&wt=3Djavabin} status=3D0 QTime=3D= 2=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.622; org.apache.solr.handl= er.SnapPuller; Master's generation: 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.623; org.apache.solr.handl= er.SnapPuller; Slave's generation: 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.623; org.apache.solr.handl= er.SnapPuller; Starting replication process [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.626; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{version=3D2= &command=3Dfilelist&qt=3D/replication&wt=3Djavabin&generation=3D2} status= =3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.628; org.apache.solr.handl= er.SnapPuller; Number of files in latest index in master: 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.629; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.S= hardSplitTest-1367383994433/jetty4/index.20130501005337628 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.629; org.apache.solr.handl= er.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.= RAMDirectory@74beec37 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFac= tory@42251145) fullCopy=3Dfalse [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.632; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{checksum=3D= true&command=3Dfilecontent&wt=3Dfilestream&qt=3D/replication&generation=3D2= &file=3Dsegments_2} status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.634; org.apache.solr.handl= er.SnapPuller; Total time taken for download : 0 secs [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.635; org.apache.solr.updat= e.DefaultSolrCoreState; Creating new IndexWriter... [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.636; org.apache.solr.updat= e.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=3Dcolle= ction1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.637; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@2b826c0c lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@2204daed),segFN=3Dsegments_1,generation=3D1} [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@2b826c0c lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@2204daed),segFN=3Dsegments_2,generation=3D2} [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.638; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.639; org.apache.solr.updat= e.DefaultSolrCoreState; New IndexWriter is ready to be used. [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.639; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@56df4845 main [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.641; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@56df4845 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.642; org.apache.solr.core.= CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ShardSpli= tTest-1367383994433/jetty4/index.20130501005337628 [CachedDir<>] [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.642; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ShardSp= litTest-1367383994433/jetty4/index.20130501005337628 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.643; org.apache.solr.core.= CachingDirectoryFactory; Removing directory before core close: ./org.apache= .solr.cloud.ShardSplitTest-1367383994433/jetty4/index.20130501005337628 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.643; org.apache.solr.cloud= .RecoveryStrategy; No replay needed. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.644; org.apache.solr.cloud= .RecoveryStrategy; Replication Recovery was successful - registering as Act= ive. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.644; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.644; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-05-01 04:53:37.647; org.apache.solr.cloud= .RecoveryStrategy; Finished recovery process. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:38.610; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.125; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.127; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "base_url":"http://127.0.0.1:51500", [junit4:junit4] 1> "core_node_name":"5", [junit4:junit4] 1> "node_name":"127.0.0.1:51500_", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_state":"active"} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.134; 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-05-01 04:53:39.134; 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-05-01 04:53:39.134; 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-05-01 04:53:39.134; 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-05-01 04:53:39.134; 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-05-01 04:53:39.134; 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-05-01 04:53:39.613; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.615; org.apache.solr.cloud= .AbstractDistribZkTestBase; Recoveries finished - collection: collection1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.624; org.apache.solr.updat= e.DirectUpdateHandler2; start commit{,optimize=3Dfalse,openSearcher=3Dtrue,= waitSearcher=3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit= =3Dfalse} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.627; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@5197fa83 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@2b299ec4),segFN=3Dsegments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.628; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.629; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@5197fa83 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@2b299ec4),segFN=3Dsegments_1,generation=3D1} [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@5197fa83 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@2b299ec4),segFN=3Dsegments_2,generation=3D2} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.630; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.631; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@72146b87 main [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.631; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.633; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@72146b87 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.634; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{commit=3Dtrue&waitSearcher=3Dtrue&version=3D2&wt=3Djavabin&softCommit= =3Dfalse} {commit=3D} 0 10 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.641; org.apache.solr.updat= e.DirectUpdateHandler2; start commit{,optimize=3Dfalse,openSearcher=3Dtrue,= waitSearcher=3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit= =3Dfalse} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.644; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@7b773269 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@52973ed4),segFN=3Dsegments_2,generation=3D2} [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@7b773269 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@52973ed4),segFN=3Dsegments_3,generation=3D3} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.644; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 3 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.645; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@58b4251e main [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.646; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.647; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@58b4251e main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.648; org.apache.solr.updat= e.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:51500/co= llection1/, StdNode: http://127.0.0.1:34880/collection1/, StdNode: http://1= 27.0.0.1:56665/collection1/] params:commit_end_point=3Dtrue&commit=3Dtrue&s= oftCommit=3Dfalse&waitSearcher=3Dtrue&expungeDeletes=3Dfalse [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.653; org.apache.solr.updat= e.DirectUpdateHandler2; start commit{,optimize=3Dfalse,openSearcher=3Dtrue,= waitSearcher=3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit= =3Dfalse} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.660; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@7d579e15 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@d0ab7bf),segFN=3Dsegments_2,generation=3D2} [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@7d579e15 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@d0ab7bf),segFN=3Dsegments_3,generation=3D3} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.661; org.apache.solr.updat= e.DirectUpdateHandler2; start commit{,optimize=3Dfalse,openSearcher=3Dtrue,= waitSearcher=3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit= =3Dfalse} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.661; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 3 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.663; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@2b826c0c lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@2204daed),segFN=3Dsegments_2,generation=3D2} [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@2b826c0c lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@2204daed),segFN=3Dsegments_3,generation=3D3} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.664; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 3 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.663; org.apache.solr.updat= e.DirectUpdateHandler2; start commit{,optimize=3Dfalse,openSearcher=3Dtrue,= waitSearcher=3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit= =3Dfalse} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.663; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@7002f016 main [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.666; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@5cc4a3e7 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@33ab7e75),segFN=3Dsegments_2,generation=3D2} [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@5cc4a3e7 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@33ab7e75),segFN=3Dsegments_3,generation=3D3} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.668; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 3 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.668; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@7002f016 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.665; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@33b02bc3 main [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.669; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@6a14026e main [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.667; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.671; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@33b02bc3 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.670; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.669; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.672; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{commit=3Dtrue&waitSearcher=3Dtrue&version=3D2&wt=3Djavabin&softCommit= =3Dfalse&expungeDeletes=3Dfalse&commit_end_point=3Dtrue} {commit=3D} 0 12 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.671; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@6a14026e main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.671; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{commit=3Dtrue&waitSearcher=3Dtrue&version=3D2&wt=3Djavabin&softCommit= =3Dfalse&expungeDeletes=3Dfalse&commit_end_point=3Dtrue} {commit=3D} 0 18 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.674; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{commit=3Dtrue&waitSearcher=3Dtrue&version=3D2&wt=3Djavabin&softCommit= =3Dfalse&expungeDeletes=3Dfalse&commit_end_point=3Dtrue} {commit=3D} 0 11 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.675; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{commit=3Dtrue&waitSearcher=3Dtrue&version=3D2&wt=3Djavabin&softCommit= =3Dfalse} {commit=3D} 0 34 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.677; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.682; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/select params=3D{rows=3D0&q=3D*:*= &version=3D2&distrib=3Dfalse&wt=3Djavabin&tests=3DcheckShardConsistency} hi= ts=3D0 status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.686; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/select params=3D{rows=3D0&q=3D*:*= &version=3D2&distrib=3Dfalse&wt=3Djavabin&tests=3DcheckShardConsistency} hi= ts=3D0 status=3D0 QTime=3D1=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.689; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/select params=3D{rows=3D0&q=3D*:*= &version=3D2&distrib=3Dfalse&wt=3Djavabin&tests=3DcheckShardConsistency} hi= ts=3D0 status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:39.693; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/select params=3D{rows=3D0&q=3D*:*= &version=3D2&distrib=3Dfalse&wt=3Djavabin&tests=3DcheckShardConsistency} hi= ts=3D0 status=3D0 QTime=3D1=20 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.700; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {deleteByQuery=3D*:* (-1433806067936002048)= } 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.709; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&update.from=3Dht= tp://127.0.0.1:52172/collection1/&_version_=3D-1433806067942293504} {delete= ByQuery=3D*:* (-1433806067942293504)} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.714; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&update.from=3Dht= tp://127.0.0.1:34880/collection1/&_version_=3D-1433806067946487808} {delete= ByQuery=3D*:* (-1433806067946487808)} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.715; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin} {deleteByQuery=3D= *:* (-1433806067946487808)} 0 7 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.716; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {deleteByQuery=3D*:* (-1433806067942293504)= } 0 12 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.724; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[0 (1433806067959070720)]} 0 4 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.737; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[0 (1433806067967459328)]} 0 4 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.738; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[0 (1433806067967459328)]} 0 11 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.744; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[1 (1433806067983187968)]} 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.755; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[1 (1433806067988430848)]} 0 3 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.756; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[1 (1433806067988430848)]} 0 8 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.762; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[2 (1433806068001013760)]} 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.774; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[2 (1433806068006256640)]} 0 3 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.776; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[2 (1433806068006256640)]} 0 11 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.782; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[3 (1433806068021985280)]} 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.794; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[3 (1433806068028276736)]} 0 3 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.796; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[3 (1433806068028276736)]} 0 10 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.802; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[4 (1433806068044005376)]} 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.816; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[4 (1433806068053442560)]} 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.817; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dhtt= p://127.0.0.1:34880/collection1/} {add=3D[4 (1433806068053442560)]} 0 8 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.818; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[4]} 0 11 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.824; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[5 (1433806068067074048)]} 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.839; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[5 (1433806068076511232)]} 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.840; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dhtt= p://127.0.0.1:52172/collection1/} {add=3D[5 (1433806068076511232)]} 0 9 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.842; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[5]} 0 15 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.846; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[6 (1433806068090142720)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.855; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[6 (1433806068095385600)]} 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.856; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[6 (1433806068095385600)]} 0 6 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.861; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[7 (1433806068105871360)]} 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.869; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[7 (1433806068111114240)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.870; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[7 (1433806068111114240)]} 0 6 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.875; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[8 (1433806068120551424)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.885; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[8 (1433806068127891456)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.886; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dhtt= p://127.0.0.1:34880/collection1/} {add=3D[8 (1433806068127891456)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.887; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[8]} 0 9 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.891; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[9 (1433806068137328640)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.900; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[9 (1433806068143620096)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.901; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dhtt= p://127.0.0.1:52172/collection1/} {add=3D[9 (1433806068143620096)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.901; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[9]} 0 8 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.905; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[10 (1433806068152008704)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.912; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[10 (1433806068156203008)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.913; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[10 (1433806068156203008)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.917; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[11 (1433806068164591616)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.924; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[11 (1433806068167737344)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.924; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[11 (1433806068167737344)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.929; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[12 (1433806068177174528)]} 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.939; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[12 (1433806068183465984)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.940; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dhtt= p://127.0.0.1:34880/collection1/} {add=3D[12 (1433806068183465984)]} 0 6 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.940; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[12]} 0 8 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.945; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[13 (1433806068193951744)]} 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.954; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[13 (1433806068200243200)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.955; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dhtt= p://127.0.0.1:34880/collection1/} {add=3D[13 (1433806068200243200)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.956; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[13]} 0 8 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.960; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[14 (1433806068209680384)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.967; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[14 (1433806068213874688)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.968; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[14 (1433806068213874688)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.972; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[15 (1433806068223311872)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.983; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[15 (1433806068229603328)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.984; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dhtt= p://127.0.0.1:34880/collection1/} {add=3D[15 (1433806068229603328)]} 0 6 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.985; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[15]} 0 10 [junit4:junit4] 1> INFO - 2013-05-01 04:53:41.990; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[16 (1433806068241137664)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.000; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[16 (1433806068248477696)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.001; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dhtt= p://127.0.0.1:34880/collection1/} {add=3D[16 (1433806068248477696)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.002; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[16]} 0 8 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.006; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[17 (1433806068257914880)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.022; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[17 (1433806068265254912)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.023; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dhtt= p://127.0.0.1:52172/collection1/} {add=3D[17 (1433806068265254912)]} 0 12 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.024; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[17]} 0 15 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.028; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[18 (1433806068280983552)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.035; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[18 (1433806068285177856)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.036; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[18 (1433806068285177856)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.040; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[19 (1433806068293566464)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.047; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[19 (1433806068297760768)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.048; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[19 (1433806068297760768)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.052; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[20 (1433806068307197952)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.059; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[20 (1433806068311392256)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.060; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[20 (1433806068311392256)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.064; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[21 (1433806068318732288)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.075; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[21 (1433806068326072320)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.076; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dhtt= p://127.0.0.1:52172/collection1/} {add=3D[21 (1433806068326072320)]} 0 6 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.077; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[21]} 0 10 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.081; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[22 (1433806068336558080)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.091; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[22 (1433806068343898112)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.092; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dhtt= p://127.0.0.1:34880/collection1/} {add=3D[22 (1433806068343898112)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.093; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[22]} 0 9 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.097; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[23 (1433806068353335296)]} 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.105; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[23 (1433806068357529600)]} 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.106; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[23 (1433806068357529600)]} 0 6 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.109; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[24 (1433806068366966784)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.117; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[24 (1433806068371161088)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.117; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[24 (1433806068371161088)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.121; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[25 (1433806068378501120)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.130; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[25 (1433806068385841152)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.131; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dhtt= p://127.0.0.1:52172/collection1/} {add=3D[25 (1433806068385841152)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.132; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[25]} 0 8 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.136; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[26 (1433806068394229760)]} 0 2 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.145; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[26 (1433806068400521216)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.146; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dhtt= p://127.0.0.1:52172/collection1/} {add=3D[26 (1433806068400521216)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.146; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[26]} 0 8 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.150; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[27 (1433806068408909824)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.157; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[27 (1433806068413104128)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.158; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[27 (1433806068413104128)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.162; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[28 (1433806068421492736)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.170; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:52172/collection1/} {add=3D[28 (1433806068427784192)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.171; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dhtt= p://127.0.0.1:34880/collection1/} {add=3D[28 (1433806068427784192)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.171; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[28]} 0 7 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.175; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[29 (1433806068435124224)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.182; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[29 (1433806068439318528)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.183; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[29 (1433806068439318528)]} 0 5 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.186; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[30 (1433806068447707136)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.192; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[30 (1433806068450852864)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.193; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[30 (1433806068450852864)]} 0 4 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.196; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&wt=3Djavabin} {add=3D[31 (1433806068458192896)]} 0 1 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.204; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DFROMLEADER&wt=3Djavabin&distrib.from=3Dh= ttp://127.0.0.1:34880/collection1/} {add=3D[31 (1433806068463435776)]} 0 0 [junit4:junit4] 1> INFO - 2013-05-01 04:53:42.205; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{version=3D2&update.distrib=3DTOLEADER&wt=3Djavabin&distrib.from=3Dh [...truncated too long message...] olrCoreState; SolrCoreState ref count has reached 0 - closing IndexWriter [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.180; org.apache.solr.updat= e.DefaultSolrCoreState; closing IndexWriter with IndexWriterCloser [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.179; 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-05-01 04:59:36.179; 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-05-01 04:59:36.182; org.apache.solr.core.= SolrCore; [unloadcollection4] Closing main searcher on request. [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.183; org.apache.solr.core.= CachingDirectoryFactory; Closing MockDirectoryFactory - 2 directories curre= ntly being tracked [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.184; org.apache.solr.core.= CachingDirectoryFactory; looking to close /mnt/ssd/jenkins/workspace/Lucene= -Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-UnloadDistributed= ZkTest-1367384238506/1367384261213unloadcollection_4n/index.201304302357538= 48 [CachedDir<>] [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.184; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: /mnt/ssd/jenkins/workspace/Luce= ne-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-UnloadDistribut= edZkTest-1367384238506/1367384261213unloadcollection_4n/index.2013043023575= 3848 [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.185; org.apache.solr.core.= CachingDirectoryFactory; looking to close /mnt/ssd/jenkins/workspace/Lucene= -Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-UnloadDistributed= ZkTest-1367384238506/1367384261213unloadcollection_4n [CachedDir<>] [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.186; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: /mnt/ssd/jenkins/workspace/Luce= ne-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-UnloadDistribut= edZkTest-1367384238506/1367384261213unloadcollection_4n [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.187; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; According to ZK I (id=3D89612893454860300-12= 7.0.0.1:42824_rmdq%2Fgl-n_0000000004) am no longer a leader. [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.189; 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-05-01 04:59:36.189; org.apache.solr.commo= n.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to= ZK [junit4:junit4] 1> WARN - 2013-05-01 04:59:36.190; org.apache.solr.commo= n.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to= ZK [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.190; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (0) [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.191; 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: 0) [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.213; org.eclipse.jetty.ser= ver.handler.ContextHandler; stopped o.e.j.s.ServletContextHandler{/rmdq/gl,= null} [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.268; org.apache.solr.SolrT= estCaseJ4; ###Ending testDistribSearch [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.271; org.apache.solr.cloud= .ZkTestServer; connecting to 127.0.0.1:53511 53511 [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.374; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@5e8677b3 name:ZooKeeperConnection Watcher:127.0.0.1:53511/solr got e= vent WatchedEvent state:Disconnected type:None path:null path:null type:Non= e [junit4:junit4] 1> INFO - 2013-05-01 04:59:36.374; org.apache.solr.commo= n.cloud.ConnectionManager; Client->ZooKeeper status change trigger but we a= re already closed [junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-So= lr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-UnloadDistributedZkT= est-1367384238506 [junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=3DUnloadDis= tributedZkTest -Dtests.method=3DtestDistribSearch -Dtests.seed=3D48A0C3D79B= 0D8FDD -Dtests.multiplier=3D3 -Dtests.slow=3Dtrue -Dtests.locale=3Dpt_PT -D= tests.timezone=3DAmerica/Atikokan -Dtests.file.encoding=3DUTF-8 [junit4:junit4] FAILURE 138s J1 | UnloadDistributedZkTest.testDistribSearc= h <<< [junit4:junit4] > Throwable #1: java.lang.AssertionError: Still found sh= ard2 in collection test_unload_shard_and_collection [junit4:junit4] > =09at __randomizedtesting.SeedInfo.seed([48A0C3D79B0D8= FDD:C9464DCFEC52EFE1]:0) [junit4:junit4] > =09at org.apache.solr.cloud.UnloadDistributedZkTest.te= stUnloadShardAndCollection(UnloadDistributedZkTest.java:127) [junit4:junit4] > =09at org.apache.solr.cloud.UnloadDistributedZkTest.do= Test(UnloadDistributedZkTest.java:77) [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-05-01 04:59:36.396; org.apache.solr.SolrT= estCaseJ4; ###deleteCore [junit4:junit4] 2> 137903 T2141 ccr.ThreadLeakControl.checkThreadLeaks WA= RNING Will linger awaiting termination of 2 leaked thread(s). [junit4:junit4] 2> NOTE: test params are: codec=3DLucene42: {range_facet_= sl=3DPostingsFormat(name=3DMockRandom), range_facet_si=3DPostingsFormat(nam= e=3DMemory doPackFST=3D false), range_facet_l=3DLucene41(blocksize=3D128), = other_tl1=3DLucene41(blocksize=3D128), a_si=3DPostingsFormat(name=3DMemory = doPackFST=3D false), _version_=3DLucene41(blocksize=3D128), id=3DPulsing41(= freqCutoff=3D19 minBlockSize=3D23 maxBlockSize=3D62), text=3DPostingsFormat= (name=3DMockRandom), timestamp=3DLucene41(blocksize=3D128), multiDefault=3D= PostingsFormat(name=3DMemory doPackFST=3D false), intDefault=3DLucene41(blo= cksize=3D128), a_t=3DLucene41(blocksize=3D128)}, docValues:{timestamp=3DDoc= ValuesFormat(name=3DDisk)}, sim=3DRandomSimilarityProvider(queryNorm=3Dfals= e,coord=3Dcrazy): {}, locale=3Dpt_PT, timezone=3DAmerica/Atikokan [junit4:junit4] 2> NOTE: Linux 3.2.0-40-generic amd64/Oracle Corporation = 1.8.0-ea (64-bit)/cpus=3D8,threads=3D1,free=3D76815360,total=3D188350464 [junit4:junit4] 2> NOTE: All tests run in this JVM: [DisMaxRequestHandler= Test, FullSolrCloudDistribCmdsTest, TestQuerySenderNoQuery, TestHashPartiti= oner, TestFastOutputStream, TestCopyFieldCollectionResource, SimplePostTool= Test, SampleTest, TestOmitPositions, TestDistributedGrouping, TestSchemaVer= sionResource, TestNumberUtils, SolrCoreCheckLockOnStartupTest, XmlUpdateReq= uestHandlerTest, CurrencyFieldOpenExchangeTest, IndexSchemaRuntimeFieldTest= , TestReload, TestUpdate, EchoParamsTest, XsltUpdateRequestHandlerTest, Sol= rIndexConfigTest, TestDefaultSimilarityFactory, ZkNodePropsTest, SpellCheck= ComponentTest, NumericFieldsTest, SpellPossibilityIteratorTest, SolrRequest= ParserTest, UniqFieldsUpdateProcessorFactoryTest, HighlighterTest, OpenClos= eCoreStressTest, BadCopyFieldTest, TestBinaryResponseWriter, BadIndexSchema= Test, BasicZkTest, TestStressLucene, SolrPluginUtilsTest, ClusterStateTest,= TestLazyCores, TestMergePolicyConfig, TestSuggestSpellingConverter, TestSc= hemaNameResource, TestUniqueKeyFieldResource, OutputWriterTest, SpellCheckC= ollatorTest, CachingDirectoryFactoryTest, CopyFieldTest, TestWordDelimiterF= ilterFactory, IndexReaderFactoryTest, PingRequestHandlerTest, CurrencyField= XmlFileTest, TestSolrXml, TestSchemaResource, TestJmxMonitoredMap, LeaderEl= ectionIntegrationTest, BasicDistributedZk2Test, MultiTermTest, ConvertedLeg= acyTest, StandardRequestHandlerTest, PathHierarchyTokenizerFactoryTest, Tes= tDistributedSearch, CoreContainerCoreInitFailuresTest, URLClassifyProcessor= Test, DirectUpdateHandlerTest, TestCodecSupport, TestStressReorder, SolrCmd= DistributorTest, TermVectorComponentDistributedTest, TestSolrXMLSerializer,= IndexBasedSpellCheckerTest, BasicDistributedZkTest, UnloadDistributedZkTes= t] [junit4:junit4] Completed on J1 in 138.69s, 1 test, 1 failure <<< FAILURES! [...truncated 502 lines...] BUILD FAILED /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:378: The follo= wing error occurred while executing this line: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:358: The follo= wing error occurred while executing this line: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The follow= ing error occurred while executing this line: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The = following error occurred while executing this line: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:43= 7: The following error occurred while executing this line: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:= 1240: The following error occurred while executing this line: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:= 884: There were test failures: 293 suites, 1219 tests, 2 failures, 13 ignor= ed (7 assumptions) Total time: 36 minutes 50 seconds Build step 'Invoke Ant' marked build as failure Description set: Java: 64bit/jdk1.8.0-ea-b86 -XX:-UseCompressedOops -XX:+Us= eConcMarkSweepGC Archiving artifacts Recording test results Email was triggered for: Failure Sending email for trigger: Failure ------=_Part_66_2028343524.1367384868493 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_66_2028343524.1367384868493--