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 DA8E2F952 for ; Tue, 30 Apr 2013 22:03:11 +0000 (UTC) Received: (qmail 30183 invoked by uid 500); 30 Apr 2013 22:03:10 -0000 Delivered-To: apmail-lucene-dev-archive@lucene.apache.org Received: (qmail 30130 invoked by uid 500); 30 Apr 2013 22:03:10 -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 30117 invoked by uid 99); 30 Apr 2013 22:03:10 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 30 Apr 2013 22:03:10 +0000 X-ASF-Spam-Status: No, hits=-2000.0 required=5.0 tests=ALL_TRUSTED,NORMAL_HTTP_TO_IP,WEIRD_PORT X-Spam-Check-By: apache.org Received: from [140.211.11.8] (HELO aegis.apache.org) (140.211.11.8) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 30 Apr 2013 22:02:47 +0000 Received: from aegis.apache.org (localhost [127.0.0.1]) by aegis.apache.org (Postfix) with ESMTP id B7AAFC0071 for ; Tue, 30 Apr 2013 22:02:24 +0000 (UTC) Date: Tue, 30 Apr 2013 22:02:03 +0000 (UTC) From: Apache Jenkins Server To: dev@lucene.apache.org Message-ID: <1019509527.6599.1367359344733.JavaMail.hudson@aegis> Subject: [JENKINS] Lucene-Solr-Tests-4.x-java7 - Build # 1210 - Failure MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----=_Part_6598_2006511544.1367359323600" X-Jenkins-Job: Lucene-Solr-Tests-4.x-java7 X-Jenkins-Result: FAILURE X-Virus-Checked: Checked by ClamAV on apache.org ------=_Part_6598_2006511544.1367359323600 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-java7/1210/ 1 tests failed. REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch Error Message: shard1 is not consistent. Got 305 from http://127.0.0.1:40396/collection1l= astClient and got 5 from http://127.0.0.1:13369/collection1 Stack Trace: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://12= 7.0.0.1:40396/collection1lastClient and got 5 from http://127.0.0.1:13369/c= ollection1 =09at __randomizedtesting.SeedInfo.seed([281FAD1599F56F49:A9F9230DEEAA0F75]= :0) =09at org.junit.Assert.fail(Assert.java:93) =09at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsist= ency(AbstractFullDistribZkTestBase.java:963) =09at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238) =09at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseD= istributedSearchTestCase.java:815) =09at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) =09at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.= java:57) =09at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces= sorImpl.java:43) =09at java.lang.reflect.Method.invoke(Method.java:601) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(Randomized= Runner.java:1559) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(Random= izedRunner.java:79) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(Random= izedRunner.java:737) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(Random= izedRunner.java:773) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(Random= izedRunner.java:787) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$= 1.evaluate(SystemPropertiesRestoreRule.java:53) =09at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRu= leSetupTeardownChained.java:50) =09at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFi= eldCacheSanity.java:51) =09at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBef= oreAfterRule.java:46) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRul= e$1.evaluate(SystemPropertiesInvariantRule.java:55) =09at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleT= hreadAndTestName.java:49) =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(Test= RuleIgnoreAfterMaxFailures.java:70) =09at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFai= lure.java:48) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.= run(ThreadLeakControl.java:358) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTa= sk(ThreadLeakControl.java:782) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(Threa= dLeakControl.java:442) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(Ran= domizedRunner.java:746) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(Random= izedRunner.java:648) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(Random= izedRunner.java:682) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(Random= izedRunner.java:693) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$= 1.evaluate(SystemPropertiesRestoreRule.java:53) =09at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBef= oreAfterRule.java:46) =09at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStor= eClassName.java:42) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRul= e$1.evaluate(SystemPropertiesInvariantRule.java:55) =09at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMeth= odsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39) =09at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMeth= odsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRule= AssertionsRequired.java:43) =09at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFai= lure.java:48) =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(Test= RuleIgnoreAfterMaxFailures.java:70) =09at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIg= noreTestSuites.java:55) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.= run(ThreadLeakControl.java:358) =09at java.lang.Thread.run(Thread.java:722) Build Log: [...truncated 9191 lines...] [junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest [junit4:junit4] 1> INFO - 2013-04-30 21:28:54.543; org.apache.solr.BaseD= istributedSearchTestCase; Setting hostContext system property: / [junit4:junit4] 1> INFO - 2013-04-30 21:28:54.550; org.apache.solr.SolrT= estCaseJ4; ###Starting testDistribSearch [junit4:junit4] 1> INFO - 2013-04-30 21:28:54.557; org.apache.solr.cloud= .ZkTestServer; STARTING ZK TEST SERVER [junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0 [junit4:junit4] 1> INFO - 2013-04-30 21:28:54.564; org.apache.solr.cloud= .ZkTestServer$ZKServerMain; Starting server [junit4:junit4] 1> INFO - 2013-04-30 21:28:54.865; org.apache.solr.cloud= .ZkTestServer; start zk server on port:18488 [junit4:junit4] 1> INFO - 2013-04-30 21:28:55.054; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> WARN - 2013-04-30 21:28:55.087; org.apache.zookeeper.= server.NIOServerCnxn; Exception causing close of session 0x0 due to java.io= .IOException: ZooKeeperServer not running [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.072; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@41ba156c name:ZooKeeperConnection Watcher:127.0.0.1:18488 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.073; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.078; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /solr [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.172; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.176; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@5bb46e1d name:ZooKeeperConnection Watcher:127.0.0.1:18488/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.177; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.193; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.201; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/shards [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.207; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.212; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/shards [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.218; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/sol= rconfig-tlog.xml to /configs/conf1/solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.220; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.231; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/sch= ema.xml to /configs/conf1/schema.xml [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.235; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.343; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/sto= pwords.txt to /configs/conf1/stopwords.txt [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.344; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.351; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/pro= twords.txt to /configs/conf1/protwords.txt [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.352; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.360; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/cur= rency.xml to /configs/conf1/currency.xml [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.361; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.367; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/ope= n-exchange-rates.json to /configs/conf1/open-exchange-rates.json [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.368; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.374; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/map= ping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.376; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.383; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/old= _synonyms.txt to /configs/conf1/old_synonyms.txt [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.384; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.390; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/syn= onyms.txt to /configs/conf1/synonyms.txt [junit4:junit4] 1> INFO - 2013-04-30 21:28:57.391; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt [junit4:junit4] 1> WARN - 2013-04-30 21:28:57.399; org.apache.zookeeper.= server.NIOServerCnxn; caught end of stream exception [junit4:junit4] 1> EndOfStreamException: Unable to read additional data f= rom client sessionid 0x13e5cd925cb0001, likely client has closed socket [junit4:junit4] 1> =09at org.apache.zookeeper.server.NIOServerCnxn.doIO(N= IOServerCnxn.java:220) [junit4:junit4] 1> =09at org.apache.zookeeper.server.NIOServerCnxnFactory= .run(NIOServerCnxnFactory.java:208) [junit4:junit4] 1> =09at java.lang.Thread.run(Thread.java:722) [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.369; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.612; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:60870 [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.653; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.654; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.655; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/tes= t/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1367357337399 [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.655; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test= /J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1367357337399/solr.x= ml [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.656; org.apache.solr.core.= CoreContainer; New CoreContainer 1482490429 [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.656; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1367357337399/' [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.657; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/te= st/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1367357337399/' [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.810; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.811; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.812; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.812; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.813; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.813; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.814; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.814; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.815; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.815; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= sPerHost=3D20&maxConnections=3D10000&socketTimeout=3D120000&connTimeout=3D1= 5000&retry=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.830; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.831; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:18488/solr [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.851; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.852; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.882; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@d0f92b5 name:ZooKeeperConnection Watcher:127.0.0.1:18488 got event W= atchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.883; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.890; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D500&maxConnectionsPerHost=3D16&socketTimeout=3D120000&connTimeout=3D150= 00 [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.905; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.908; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@7bec046e name:ZooKeeperConnection Watcher:127.0.0.1:18488/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.908; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.919; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/queue [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.934; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/collection-queue-work [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.954; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.957; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:608= 70_ [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.965; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:60870_ [junit4:junit4] 1> INFO - 2013-04-30 21:28:58.969; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer_elect/election [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.003; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer_elect/leader [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.008; org.apache.solr.cloud= .Overseer; Overseer (id=3D89611130305708035-127.0.0.1:60870_-n_0000000000) = starting [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.045; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/queue-work [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.061; org.apache.solr.cloud= .OverseerCollectionProcessor; Process current queue of collection creations [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.062; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /clusterstate.json [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.066; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /aliases.json [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.068; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.093; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Starting to work on the main queue [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.107; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-= core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-13673573373= 99/collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.108; org.apache.solr.cloud= .ZkController; Check for collection zkNode:control_collection [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.109; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.109; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/control_collection [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.112; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/te= st/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1367357337399/coll= ection1/' [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.113; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.clou= d.SyncSliceTest-controljetty-1367357337399/collection1/lib/README' to class= loader [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.114; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.clou= d.SyncSliceTest-controljetty-1367357337399/collection1/lib/classes/' to cla= ssloader [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.196; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_44 [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.253; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.355; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-30 21:28:59.405; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.099; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.117; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.121; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.171; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.187; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.194; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-30 21:29:00.200; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-30 21:29:00.201; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.201; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-30 21:29:00.203; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-30 21:29:00.204; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.204; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.232; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org= .apache.solr.cloud.SyncSliceTest-controljetty-1367357337399/collection1/, d= ataDir=3D./org.apache.solr.cloud.SyncSliceTest-1367357334551/control/data/ [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.236; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@550aaabb [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.238; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.239; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org= .apache.solr.cloud.SyncSliceTest-1367357334551/control/data [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.239; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.SyncSliceTest-1367357334551/control/data/index/ [junit4:junit4] 1> WARN - 2013-04-30 21:29:00.240; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncS= liceTest-1367357334551/control/data/index' doesn't exist. Creating new inde= x... [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.241; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org= .apache.solr.cloud.SyncSliceTest-1367357334551/control/data/index [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.271; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/control/data/index lockFactory=3Dorg.apache.lucene.store.= NativeFSLockFactory@39823684; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN= =3Dsegments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.271; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.313; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.313; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.314; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.315; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.316; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.316; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.317; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.318; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.319; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.328; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.337; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@4bc33a68 main [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.356; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.356; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.362; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@4bc33a68 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.368; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.368; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.605; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.607; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"1", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"control_collection", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:60870_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:60870"} [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.607; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Create collection control_collection with nu= mShards 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.640; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:00.672; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 1) [junit4:junit4] 1> INFO - 2013-04-30 21:29:01.373; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:01.374; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :60870 collection:control_collection shard:shard1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:01.384; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D10000&maxConnectionsPerHost=3D20&connTimeout=3D30000&socketTimeout=3D30= 000&retry=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:01.400; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elec= t/shard1/election [junit4:junit4] 1> INFO - 2013-04-30 21:29:01.428; org.apache.solr.cloud= .ShardLeaderElectionContext; Running the leader process. [junit4:junit4] 1> INFO - 2013-04-30 21:29:01.439; org.apache.solr.cloud= .ShardLeaderElectionContext; Enough replicas found to continue. [junit4:junit4] 1> INFO - 2013-04-30 21:29:01.440; org.apache.solr.cloud= .ShardLeaderElectionContext; I may be the new leader - try and sync [junit4:junit4] 1> INFO - 2013-04-30 21:29:01.445; org.apache.solr.cloud= .SyncStrategy; Sync replicas to http://127.0.0.1:60870/collection1/ [junit4:junit4] 1> INFO - 2013-04-30 21:29:01.446; org.apache.solr.cloud= .SyncStrategy; Sync Success - now sync replicas to me [junit4:junit4] 1> INFO - 2013-04-30 21:29:01.447; org.apache.solr.cloud= .SyncStrategy; http://127.0.0.1:60870/collection1/ has no replicas [junit4:junit4] 1> INFO - 2013-04-30 21:29:01.447; org.apache.solr.cloud= .ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:60870/co= llection1/ [junit4:junit4] 1> INFO - 2013-04-30 21:29:01.448; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/sha= rd1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.180; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.202; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 1) [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.231; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:60870/collection1/ and leader is htt= p://127.0.0.1:60870/collection1/ [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.236; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:60870 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.236; org.apache.solr.cloud= .ZkController; I am the leader, no recovery necessary [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.237; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.237; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.242; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.244; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.244; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.321; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.347; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config: [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.356; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.358; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@1ab395af name:ZooKeeperConnection Watcher:127.0.0.1:18488/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.359; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.361; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.368; org.apache.solr.cloud= .ChaosMonkey; monkey: init - expire sessions:true cause connection loss:tru= e [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.600; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.604; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:22849 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.605; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.606; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.606; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/tes= t/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1367357342369 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.607; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test= /J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1367357342369/solr.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.608; org.apache.solr.core.= CoreContainer; New CoreContainer 435345839 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.609; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1367357342369/' [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.610; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/te= st/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1367357342369/' [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.750; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.751; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.752; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.752; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.753; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.754; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.754; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.755; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.756; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.757; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= sPerHost=3D20&maxConnections=3D10000&socketTimeout=3D120000&connTimeout=3D1= 5000&retry=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.777; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.778; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:18488/solr [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.778; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.780; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.783; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@70f4f7ea name:ZooKeeperConnection Watcher:127.0.0.1:18488 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.784; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.787; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D500&maxConnectionsPerHost=3D16&socketTimeout=3D120000&connTimeout=3D150= 00 [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.801; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.804; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@af7c30f name:ZooKeeperConnection Watcher:127.0.0.1:18488/solr got ev= ent WatchedEvent state:SyncConnected type:None path:null path:null type:Non= e [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.804; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:02.817; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.717; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.718; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"1", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"control_collection", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:60870_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:60870"} [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.751; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 1) [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.752; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 1) [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.751; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 1) [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.823; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:228= 49_ [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.825; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:22849_ [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.829; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 1) [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.830; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.830; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.830; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.831; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.832; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.842; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-= core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1367357342369/col= lection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.843; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.844; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.845; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.847; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/te= st/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1367357342369/collection= 1/' [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.849; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.clou= d.SyncSliceTest-jetty1-1367357342369/collection1/lib/README' to classloader [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.850; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.clou= d.SyncSliceTest-jetty1-1367357342369/collection1/lib/classes/' to classload= er [junit4:junit4] 1> INFO - 2013-04-30 21:29:03.929; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_44 [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.007; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.109; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.152; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.713; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.729; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.733; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.765; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.773; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.779; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-30 21:29:04.782; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-30 21:29:04.782; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.783; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-30 21:29:04.785; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-30 21:29:04.785; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.786; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.786; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org= .apache.solr.cloud.SyncSliceTest-jetty1-1367357342369/collection1/, dataDir= =3D./org.apache.solr.cloud.SyncSliceTest-1367357334551/jetty1/ [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.786; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@550aaabb [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.787; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.788; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org= .apache.solr.cloud.SyncSliceTest-1367357334551/jetty1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.789; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.SyncSliceTest-1367357334551/jetty1/index/ [junit4:junit4] 1> WARN - 2013-04-30 21:29:04.789; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncS= liceTest-1367357334551/jetty1/index' doesn't exist. Creating new index... [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.790; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org= .apache.solr.cloud.SyncSliceTest-1367357334551/jetty1/index [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.796; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.796; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.800; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.801; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.802; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.803; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.804; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.805; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.805; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.806; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.807; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.815; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.822; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@547c4baf main [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.824; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.824; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.832; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@547c4baf main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.839; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-30 21:29:04.839; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.264; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.265; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"2", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:22849_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:22849"} [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.266; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Create collection collection1 with numShards= 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.266; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.274; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.274; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.274; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.843; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.843; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :22849 collection:collection1 shard:shard1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.845; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard= 1/election [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.864; org.apache.solr.cloud= .ShardLeaderElectionContext; Running the leader process. [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.875; org.apache.solr.cloud= .ShardLeaderElectionContext; Enough replicas found to continue. [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.875; org.apache.solr.cloud= .ShardLeaderElectionContext; I may be the new leader - try and sync [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.876; org.apache.solr.cloud= .SyncStrategy; Sync replicas to http://127.0.0.1:22849/collection1/ [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.876; org.apache.solr.cloud= .SyncStrategy; Sync Success - now sync replicas to me [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.876; org.apache.solr.cloud= .SyncStrategy; http://127.0.0.1:22849/collection1/ has no replicas [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.877; org.apache.solr.cloud= .ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:22849/co= llection1/ [junit4:junit4] 1> INFO - 2013-04-30 21:29:05.877; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:06.789; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:06.819; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-30 21:29:06.819; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-30 21:29:06.819; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-30 21:29:06.863; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:22849/collection1/ and leader is htt= p://127.0.0.1:22849/collection1/ [junit4:junit4] 1> INFO - 2013-04-30 21:29:06.863; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:22849 [junit4:junit4] 1> INFO - 2013-04-30 21:29:06.864; org.apache.solr.cloud= .ZkController; I am the leader, no recovery necessary [junit4:junit4] 1> INFO - 2013-04-30 21:29:06.864; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-30 21:29:06.865; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-30 21:29:06.868; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:06.870; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-04-30 21:29:06.871; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-30 21:29:06.872; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.036; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.039; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:10279 [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.040; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.040; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.041; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/tes= t/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1367357346883 [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.041; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test= /J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1367357346883/solr.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.042; org.apache.solr.core.= CoreContainer; New CoreContainer 1298496515 [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.042; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1367357346883/' [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.043; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/te= st/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1367357346883/' [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.136; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.136; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.137; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.137; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.138; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.138; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.139; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.139; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.140; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.140; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= sPerHost=3D20&maxConnections=3D10000&socketTimeout=3D120000&connTimeout=3D1= 5000&retry=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.152; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.153; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:18488/solr [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.153; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.154; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.158; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@6a9c3d70 name:ZooKeeperConnection Watcher:127.0.0.1:18488 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.159; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.172; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D500&maxConnectionsPerHost=3D16&socketTimeout=3D120000&connTimeout=3D150= 00 [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.182; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.185; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@756c99c2 name:ZooKeeperConnection Watcher:127.0.0.1:18488/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.185; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:07.194; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.200; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:102= 79_ [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.238; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:10279_ [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.243; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 2) [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.244; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.244; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.244; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.245; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.246; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.246; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.256; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-= core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1367357346883/col= lection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.257; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.258; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.258; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.261; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/te= st/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1367357346883/collection= 1/' [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.262; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.clou= d.SyncSliceTest-jetty2-1367357346883/collection1/lib/classes/' to classload= er [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.263; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.clou= d.SyncSliceTest-jetty2-1367357346883/collection1/lib/README' to classloader [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.326; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_44 [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.336; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.338; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"2", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:22849_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:22849"} [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.352; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.352; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.352; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.352; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.396; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.498; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:08.554; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.288; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.302; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.306; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.333; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.339; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.344; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-30 21:29:09.345; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-30 21:29:09.346; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.346; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-30 21:29:09.348; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-30 21:29:09.348; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.348; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.349; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org= .apache.solr.cloud.SyncSliceTest-jetty2-1367357346883/collection1/, dataDir= =3D./org.apache.solr.cloud.SyncSliceTest-1367357334551/jetty2/ [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.349; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@550aaabb [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.350; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.351; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org= .apache.solr.cloud.SyncSliceTest-1367357334551/jetty2 [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.351; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.SyncSliceTest-1367357334551/jetty2/index/ [junit4:junit4] 1> WARN - 2013-04-30 21:29:09.352; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncS= liceTest-1367357334551/jetty2/index' doesn't exist. Creating new index... [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.353; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org= .apache.solr.cloud.SyncSliceTest-1367357334551/jetty2/index [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.358; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty2/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@623f1421; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.358; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.361; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.362; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.363; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.364; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.365; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.365; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.366; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.366; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.367; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.377; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.383; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@373986c1 main [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.384; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.385; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.392; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@373986c1 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.396; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.396; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.862; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.863; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"3", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:10279_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:10279"} [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.864; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.864; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.871; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.871; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.871; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:09.871; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.400; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.400; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :10279 collection:collection1 shard:shard1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.407; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:10279/collection1/ and leader is htt= p://127.0.0.1:22849/collection1/ [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.408; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:10279 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.408; org.apache.solr.cloud= .ZkController; Core needs to recover:collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.409; org.apache.solr.updat= e.DefaultSolrCoreState; Running recovery - first canceling any ongoing reco= very [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.416; org.apache.solr.cloud= .RecoveryStrategy; Starting recovery process. core=3Dcollection1 recoverin= gAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.417; org.apache.solr.cloud= .RecoveryStrategy; ###### startupVersions=3D[] [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.417; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.417; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Drecovering [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.418; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.419; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.420; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.420; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.420; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.660; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.663; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:40396 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.664; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.665; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.665; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/tes= t/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1367357350437 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.666; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test= /J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1367357350437/solr.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.666; org.apache.solr.core.= CoreContainer; New CoreContainer 1980638041 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.667; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1367357350437/' [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.668; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/te= st/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1367357350437/' [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.805; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.806; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.807; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.807; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.808; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.808; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.808; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.809; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.809; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.810; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= sPerHost=3D20&maxConnections=3D10000&socketTimeout=3D120000&connTimeout=3D1= 5000&retry=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.826; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.827; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:18488/solr [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.827; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.828; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.832; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@78688290 name:ZooKeeperConnection Watcher:127.0.0.1:18488 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.833; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.854; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D500&maxConnectionsPerHost=3D16&socketTimeout=3D120000&connTimeout=3D150= 00 [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.865; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.868; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@5f50ba51 name:ZooKeeperConnection Watcher:127.0.0.1:18488/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.868; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:10.883; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.389; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.391; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"3", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"recovering", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:10279_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:10279"} [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.407; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.408; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.407; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.407; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.408; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.595; org.apache.solr.handl= er.admin.CoreAdminHandler; Going to wait for coreNodeName: 3, state: recove= ring, checkLive: true, onlyIfLeader: true [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.596; org.apache.solr.handl= er.admin.CoreAdminHandler; Waited coreNodeName: 3, state: recovering, check= Live: true, onlyIfLeader: true for: 0 seconds. [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.597; org.apache.solr.servl= et.SolrDispatchFilter; [admin] webapp=3Dnull path=3D/admin/cores params=3D{= coreNodeName=3D3&state=3Drecovering&nodeName=3D127.0.0.1:10279_&action=3DPR= EPRECOVERY&checkLive=3Dtrue&core=3Dcollection1&wt=3Djavabin&onlyIfLeader=3D= true&version=3D2} status=3D0 QTime=3D6=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.890; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:403= 96_ [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.917; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:40396_ [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.921; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.922; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.921; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.921; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.921; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.924; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.923; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.923; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.924; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.936; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.944; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-= core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1367357350437/col= lection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.945; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.947; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.947; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.949; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/te= st/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1367357350437/collection= 1/' [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.951; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.clou= d.SyncSliceTest-jetty3-1367357350437/collection1/lib/classes/' to classload= er [junit4:junit4] 1> INFO - 2013-04-30 21:29:11.952; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.clou= d.SyncSliceTest-jetty3-1367357350437/collection1/lib/README' to classloader [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.020; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_44 [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.074; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.176; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.204; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.905; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.917; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.921; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.952; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.958; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.963; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-30 21:29:12.965; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-30 21:29:12.966; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.966; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-30 21:29:12.968; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-30 21:29:12.968; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.968; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.969; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org= .apache.solr.cloud.SyncSliceTest-jetty3-1367357350437/collection1/, dataDir= =3D./org.apache.solr.cloud.SyncSliceTest-1367357334551/jetty3/ [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.969; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@550aaabb [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.970; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.971; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org= .apache.solr.cloud.SyncSliceTest-1367357334551/jetty3 [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.971; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.SyncSliceTest-1367357334551/jetty3/index/ [junit4:junit4] 1> WARN - 2013-04-30 21:29:12.972; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncS= liceTest-1367357334551/jetty3/index' doesn't exist. Creating new index... [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.973; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org= .apache.solr.cloud.SyncSliceTest-1367357334551/jetty3/index [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.979; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty3/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@2db0e390; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.980; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.983; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.983; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.984; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.985; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.986; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.986; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.987; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.988; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.988; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-30 21:29:12.997; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.003; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@128cdd0c main [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.004; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.004; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.011; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@128cdd0c main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.014; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.015; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.707; org.apache.solr.cloud= .RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:22849/colle= ction1/ core=3Dcollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.715; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= sPerHost=3D20&maxConnections=3D10000&connTimeout=3D30000&socketTimeout=3D30= 000&retry=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.734; org.apache.solr.updat= e.PeerSync; PeerSync: core=3Dcollection1 url=3Dhttp://127.0.0.1:10279 START= replicas=3D[http://127.0.0.1:22849/collection1/] nUpdates=3D100 [junit4:junit4] 1> WARN - 2013-04-30 21:29:13.743; org.apache.solr.updat= e.PeerSync; no frame of reference to tell of we've missed updates [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.744; org.apache.solr.cloud= .RecoveryStrategy; PeerSync Recovery was not successful - trying replicatio= n. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.744; org.apache.solr.cloud= .RecoveryStrategy; Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.744; org.apache.solr.cloud= .RecoveryStrategy; Begin buffering updates. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.744; org.apache.solr.updat= e.UpdateLog; Starting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog= =3Dnull} [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.745; org.apache.solr.cloud= .RecoveryStrategy; Attempting to replicate from http://127.0.0.1:22849/coll= ection1/. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.745; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.791; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/get params=3D{getVersions=3D100&d= istrib=3Dfalse&wt=3Djavabin&qt=3D/get&version=3D2} status=3D0 QTime=3D7=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.809; org.apache.solr.updat= e.DirectUpdateHandler2; start commit{,optimize=3Dfalse,openSearcher=3Dfalse= ,waitSearcher=3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommi= t=3Dfalse} [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.815; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.816; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.847; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_1,generation=3D1} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_2,generation=3D2} [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.849; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 2 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.850; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@30185461 realtime [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.851; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.852; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{waitSearcher=3Dtrue&openSearcher=3Dfalse&commit=3Dtrue&wt=3Djavabin&c= ommit_end_point=3Dtrue&version=3D2&softCommit=3Dfalse} {commit=3D} 0 68 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.914; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.915; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:connTimeout= =3D5000&socketTimeout=3D20000&allowCompression=3Dfalse&maxConnections=3D100= 00&maxConnectionsPerHost=3D10000 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.942; org.apache.solr.handl= er.SnapPuller; No value set for 'pollInterval'. Timer Task not started. [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.984; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.985; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{command=3Di= ndexversion&qt=3D/replication&wt=3Djavabin&version=3D2} status=3D0 QTime=3D= 39=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.987; org.apache.solr.handl= er.SnapPuller; Master's generation: 2 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.988; org.apache.solr.handl= er.SnapPuller; Slave's generation: 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.988; org.apache.solr.handl= er.SnapPuller; Starting replication process [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.993; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{command=3Df= ilelist&qt=3D/replication&wt=3Djavabin&generation=3D2&version=3D2} status= =3D0 QTime=3D1=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.995; org.apache.solr.handl= er.SnapPuller; Number of files in latest index in master: 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.996; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org= .apache.solr.cloud.SyncSliceTest-1367357334551/jetty2/index.201304301429139= 95 [junit4:junit4] 1> INFO - 2013-04-30 21:29:13.997; org.apache.solr.handl= er.SnapPuller; Starting download to NRTCachingDirectory(org.apache.lucene.s= tore.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tes= ts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTe= st-1367357334551/jetty2/index.20130430142913995 lockFactory=3Dorg.apache.lu= cene.store.NativeFSLockFactory@2da1f51c; maxCacheMB=3D48.0 maxMergeSizeMB= =3D4.0) fullCopy=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.010; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{file=3Dsegm= ents_2&command=3Dfilecontent&checksum=3Dtrue&wt=3Dfilestream&qt=3D/replicat= ion&generation=3D2} status=3D0 QTime=3D4=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.026; org.apache.solr.handl= er.SnapPuller; Total time taken for download : 0 secs [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.034; org.apache.solr.updat= e.DefaultSolrCoreState; Creating new IndexWriter... [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.035; org.apache.solr.updat= e.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=3Dcolle= ction1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.040; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty2/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@623f1421; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_1,generation=3D1} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty2/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@623f1421; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_2,generation=3D2} [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.042; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 2 [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.043; org.apache.solr.updat= e.DefaultSolrCoreState; New IndexWriter is ready to be used. [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.044; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@d975a08 main [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.046; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@d975a08 main{Stand= ardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.047; org.apache.solr.core.= CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/wor= kspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.= solr.cloud.SyncSliceTest-1367357334551/jetty2/index.20130430142913995 [Cach= edDir<>] [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.048; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/w= orkspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apach= e.solr.cloud.SyncSliceTest-1367357334551/jetty2/index.20130430142913995 [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.049; org.apache.solr.core.= CachingDirectoryFactory; Removing directory before core close: /usr/home/hu= dson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-cor= e/test/J0/org.apache.solr.cloud.SyncSliceTest-1367357334551/jetty2/index.20= 130430142913995 [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.050; org.apache.solr.cloud= .RecoveryStrategy; No replay needed. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.051; org.apache.solr.cloud= .RecoveryStrategy; Replication Recovery was successful - registering as Act= ive. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.052; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.052; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.055; org.apache.solr.cloud= .RecoveryStrategy; Finished recovery process. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.430; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.433; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"4", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:40396_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:40396"} [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.433; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.434; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.440; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"3", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:10279_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:10279"} [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.453; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.454; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.454; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.454; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:14.453; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.019; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.019; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :40396 collection:collection1 shard:shard1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.025; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:40396/collection1/ and leader is htt= p://127.0.0.1:22849/collection1/ [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.025; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:40396 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.025; org.apache.solr.cloud= .ZkController; Core needs to recover:collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.026; org.apache.solr.updat= e.DefaultSolrCoreState; Running recovery - first canceling any ongoing reco= very [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.027; org.apache.solr.cloud= .RecoveryStrategy; Starting recovery process. core=3Dcollection1 recoverin= gAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.027; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.028; org.apache.solr.cloud= .RecoveryStrategy; ###### startupVersions=3D[] [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.028; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Drecovering [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.029; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.029; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.030; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.030; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.031; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.049; org.apache.solr.handl= er.admin.CoreAdminHandler; Going to wait for coreNodeName: 4, state: recove= ring, checkLive: true, onlyIfLeader: true [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.204; org.eclipse.jetty.ser= ver.Server; jetty-8.1.10.v20130312 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.207; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:13369 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.208; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.208; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.209; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/tes= t/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1367357355045 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.209; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test= /J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1367357355045/solr.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.209; org.apache.solr.core.= CoreContainer; New CoreContainer 2011208934 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.210; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J= 0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1367357355045/' [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.211; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/te= st/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1367357355045/' [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.330; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.331; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.332; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.332; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.333; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.333; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.333; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.334; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.334; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.335; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= sPerHost=3D20&maxConnections=3D10000&socketTimeout=3D120000&connTimeout=3D1= 5000&retry=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.348; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.349; org.apache.solr.core.= ZkContainer; Zookeeper client=3D127.0.0.1:18488/solr [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.349; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.350; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.354; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@401815bc name:ZooKeeperConnection Watcher:127.0.0.1:18488 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.355; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.369; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D500&maxConnectionsPerHost=3D16&socketTimeout=3D120000&connTimeout=3D150= 00 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.377; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.380; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@4d624712 name:ZooKeeperConnection Watcher:127.0.0.1:18488/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.380; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.393; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.971; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:15.973; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"4", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"recovering", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:40396_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:40396"} [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.058; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.058; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.058; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.058; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.058; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.058; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.399; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:133= 69_ [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.427; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:13369_ [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.438; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.439; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.440; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.440; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.440; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.439; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.439; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.442; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.441; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.440; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.443; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.442; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.453; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-= core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1367357355045/col= lection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.453; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.455; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.455; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.458; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/te= st/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1367357355045/collection= 1/' [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.460; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.clou= d.SyncSliceTest-jetty4-1367357355045/collection1/lib/classes/' to classload= er [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.461; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.clou= d.SyncSliceTest-jetty4-1367357355045/collection1/lib/README' to classloader [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.522; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_44 [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.594; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.696; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:16.732; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.052; org.apache.solr.handl= er.admin.CoreAdminHandler; Waited coreNodeName: 4, state: recovering, check= Live: true, onlyIfLeader: true for: 2 seconds. [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.053; org.apache.solr.servl= et.SolrDispatchFilter; [admin] webapp=3Dnull path=3D/admin/cores params=3D{= coreNodeName=3D4&state=3Drecovering&nodeName=3D127.0.0.1:40396_&action=3DPR= EPRECOVERY&checkLive=3Dtrue&core=3Dcollection1&wt=3Djavabin&onlyIfLeader=3D= true&version=3D2} status=3D0 QTime=3D2004=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.418; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.431; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.434; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.464; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.470; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.475; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-30 21:29:17.477; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-30 21:29:17.477; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.478; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-30 21:29:17.480; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-30 21:29:17.480; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.480; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.481; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org= .apache.solr.cloud.SyncSliceTest-jetty4-1367357355045/collection1/, dataDir= =3D./org.apache.solr.cloud.SyncSliceTest-1367357334551/jetty4/ [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.481; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@550aaabb [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.482; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.483; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org= .apache.solr.cloud.SyncSliceTest-1367357334551/jetty4 [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.484; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.SyncSliceTest-1367357334551/jetty4/index/ [junit4:junit4] 1> WARN - 2013-04-30 21:29:17.484; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncS= liceTest-1367357334551/jetty4/index' doesn't exist. Creating new index... [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.485; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org= .apache.solr.cloud.SyncSliceTest-1367357334551/jetty4/index [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.529; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty4/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@3647b000; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.529; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.533; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.533; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.534; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.535; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.536; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.536; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.536; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.537; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.538; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.548; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.555; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@2f3f15c8 main [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.556; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.556; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.564; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@2f3f15c8 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.567; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.567; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.604; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.605; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"5", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:13369_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:13369"} [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.606; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.606; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.619; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.619; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.619; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.619; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.619; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:17.619; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.571; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.571; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :13369 collection:collection1 shard:shard1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.593; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:13369/collection1/ and leader is htt= p://127.0.0.1:22849/collection1/ [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.593; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:13369 [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.594; org.apache.solr.cloud= .ZkController; Core needs to recover:collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.594; org.apache.solr.updat= e.DefaultSolrCoreState; Running recovery - first canceling any ongoing reco= very [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.595; org.apache.solr.cloud= .RecoveryStrategy; Starting recovery process. core=3Dcollection1 recoverin= gAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.596; org.apache.solr.cloud= .RecoveryStrategy; ###### startupVersions=3D[] [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.596; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.596; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Drecovering [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.597; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.598; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0 [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.599; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.600; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.600; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.616; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.616; org.apache.solr.handl= er.admin.CoreAdminHandler; Going to wait for coreNodeName: 5, state: recove= ring, checkLive: true, onlyIfLeader: true [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.620; org.apache.solr.cloud= .AbstractFullDistribZkTestBase; Wait for recoveries to finish - wait 15 for= each attempt [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.621; org.apache.solr.cloud= .AbstractDistribZkTestBase; Wait for recoveries to finish - collection: col= lection1 failOnTimeout:true timeout (sec):15 [junit4:junit4] 1> INFO - 2013-04-30 21:29:18.622; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.055; org.apache.solr.cloud= .RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:22849/colle= ction1/ core=3Dcollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.055; org.apache.solr.updat= e.PeerSync; PeerSync: core=3Dcollection1 url=3Dhttp://127.0.0.1:40396 START= replicas=3D[http://127.0.0.1:22849/collection1/] nUpdates=3D100 [junit4:junit4] 1> WARN - 2013-04-30 21:29:19.057; org.apache.solr.updat= e.PeerSync; no frame of reference to tell of we've missed updates [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.057; org.apache.solr.cloud= .RecoveryStrategy; PeerSync Recovery was not successful - trying replicatio= n. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.058; org.apache.solr.cloud= .RecoveryStrategy; Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.058; org.apache.solr.cloud= .RecoveryStrategy; Begin buffering updates. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.058; org.apache.solr.updat= e.UpdateLog; Starting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog= =3Dnull} [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.059; org.apache.solr.cloud= .RecoveryStrategy; Attempting to replicate from http://127.0.0.1:22849/coll= ection1/. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.059; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.060; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/get params=3D{getVersions=3D100&d= istrib=3Dfalse&wt=3Djavabin&qt=3D/get&version=3D2} status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.074; org.apache.solr.updat= e.DirectUpdateHandler2; start commit{,optimize=3Dfalse,openSearcher=3Dfalse= ,waitSearcher=3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommi= t=3Dfalse} [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.078; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_2,generation=3D2} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_3,generation=3D3} [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.079; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 3 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.080; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.080; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{waitSearcher=3Dtrue&openSearcher=3Dfalse&commit=3Dtrue&wt=3Djavabin&c= ommit_end_point=3Dtrue&version=3D2&softCommit=3Dfalse} {commit=3D} 0 6 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.082; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.083; org.apache.solr.handl= er.SnapPuller; No value set for 'pollInterval'. Timer Task not started. [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.087; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{command=3Di= ndexversion&qt=3D/replication&wt=3Djavabin&version=3D2} status=3D0 QTime=3D= 0=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.088; org.apache.solr.handl= er.SnapPuller; Master's generation: 3 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.089; org.apache.solr.handl= er.SnapPuller; Slave's generation: 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.089; org.apache.solr.handl= er.SnapPuller; Starting replication process [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.093; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{command=3Df= ilelist&qt=3D/replication&wt=3Djavabin&generation=3D3&version=3D2} status= =3D0 QTime=3D1=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.094; org.apache.solr.handl= er.SnapPuller; Number of files in latest index in master: 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.095; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org= .apache.solr.cloud.SyncSliceTest-1367357334551/jetty3/index.201304301429190= 95 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.096; org.apache.solr.handl= er.SnapPuller; Starting download to NRTCachingDirectory(org.apache.lucene.s= tore.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tes= ts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTe= st-1367357334551/jetty3/index.20130430142919095 lockFactory=3Dorg.apache.lu= cene.store.NativeFSLockFactory@dfa9549; maxCacheMB=3D48.0 maxMergeSizeMB=3D= 4.0) fullCopy=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.100; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{file=3Dsegm= ents_3&command=3Dfilecontent&checksum=3Dtrue&wt=3Dfilestream&qt=3D/replicat= ion&generation=3D3} status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.102; org.apache.solr.handl= er.SnapPuller; Total time taken for download : 0 secs [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.105; org.apache.solr.updat= e.DefaultSolrCoreState; Creating new IndexWriter... [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.105; org.apache.solr.updat= e.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=3Dcolle= ction1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.112; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty3/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@2db0e390; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_1,generation=3D1} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty3/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@2db0e390; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_3,generation=3D3} [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.112; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 3 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.113; org.apache.solr.updat= e.DefaultSolrCoreState; New IndexWriter is ready to be used. [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.115; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@3d88eb46 main [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.117; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@3d88eb46 main{Stan= dardDirectoryReader(segments_3:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.118; org.apache.solr.core.= CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/wor= kspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.= solr.cloud.SyncSliceTest-1367357334551/jetty3/index.20130430142919095 [Cach= edDir<>] [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.119; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/w= orkspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apach= e.solr.cloud.SyncSliceTest-1367357334551/jetty3/index.20130430142919095 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.119; org.apache.solr.core.= CachingDirectoryFactory; Removing directory before core close: /usr/home/hu= dson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-cor= e/test/J0/org.apache.solr.cloud.SyncSliceTest-1367357334551/jetty3/index.20= 130430142919095 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.121; org.apache.solr.cloud= .RecoveryStrategy; No replay needed. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.121; org.apache.solr.cloud= .RecoveryStrategy; Replication Recovery was successful - registering as Act= ive. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.121; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.122; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.124; org.apache.solr.cloud= .RecoveryStrategy; Finished recovery process. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.127; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.128; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"5", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"recovering", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:13369_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:13369"} [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.143; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"4", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:40396_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:40396"} [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.154; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.154; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.154; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.154; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.154; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.154; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.619; org.apache.solr.handl= er.admin.CoreAdminHandler; Waited coreNodeName: 5, state: recovering, check= Live: true, onlyIfLeader: true for: 1 seconds. [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.620; org.apache.solr.servl= et.SolrDispatchFilter; [admin] webapp=3Dnull path=3D/admin/cores params=3D{= coreNodeName=3D5&state=3Drecovering&nodeName=3D127.0.0.1:13369_&action=3DPR= EPRECOVERY&checkLive=3Dtrue&core=3Dcollection1&wt=3Djavabin&onlyIfLeader=3D= true&version=3D2} status=3D0 QTime=3D1004=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:19.626; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:20.629; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.622; org.apache.solr.cloud= .RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:22849/colle= ction1/ core=3Dcollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.622; org.apache.solr.updat= e.PeerSync; PeerSync: core=3Dcollection1 url=3Dhttp://127.0.0.1:13369 START= replicas=3D[http://127.0.0.1:22849/collection1/] nUpdates=3D100 [junit4:junit4] 1> WARN - 2013-04-30 21:29:21.623; org.apache.solr.updat= e.PeerSync; no frame of reference to tell of we've missed updates [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.624; org.apache.solr.cloud= .RecoveryStrategy; PeerSync Recovery was not successful - trying replicatio= n. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.624; org.apache.solr.cloud= .RecoveryStrategy; Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.624; org.apache.solr.cloud= .RecoveryStrategy; Begin buffering updates. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.625; org.apache.solr.updat= e.UpdateLog; Starting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog= =3Dnull} [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.625; org.apache.solr.cloud= .RecoveryStrategy; Attempting to replicate from http://127.0.0.1:22849/coll= ection1/. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.626; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnection= s=3D128&maxConnectionsPerHost=3D32&followRedirects=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.627; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/get params=3D{getVersions=3D100&d= istrib=3Dfalse&wt=3Djavabin&qt=3D/get&version=3D2} status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.633; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.649; org.apache.solr.updat= e.DirectUpdateHandler2; start commit{,optimize=3Dfalse,openSearcher=3Dfalse= ,waitSearcher=3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommi= t=3Dfalse} [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.655; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D3 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_2,generation=3D2} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_3,generation=3D3} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_4,generation=3D4} [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.656; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 4 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.657; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.658; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{waitSearcher=3Dtrue&openSearcher=3Dfalse&commit=3Dtrue&wt=3Djavabin&c= ommit_end_point=3Dtrue&version=3D2&softCommit=3Dfalse} {commit=3D} 0 9 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.659; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.660; org.apache.solr.handl= er.SnapPuller; No value set for 'pollInterval'. Timer Task not started. [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.664; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{command=3Di= ndexversion&qt=3D/replication&wt=3Djavabin&version=3D2} status=3D0 QTime=3D= 0=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.665; org.apache.solr.handl= er.SnapPuller; Master's generation: 4 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.666; org.apache.solr.handl= er.SnapPuller; Slave's generation: 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.666; org.apache.solr.handl= er.SnapPuller; Starting replication process [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.671; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{command=3Df= ilelist&qt=3D/replication&wt=3Djavabin&generation=3D4&version=3D2} status= =3D0 QTime=3D1=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.672; org.apache.solr.handl= er.SnapPuller; Number of files in latest index in master: 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.674; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org= .apache.solr.cloud.SyncSliceTest-1367357334551/jetty4/index.201304301429216= 73 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.675; org.apache.solr.handl= er.SnapPuller; Starting download to NRTCachingDirectory(org.apache.lucene.s= tore.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tes= ts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTe= st-1367357334551/jetty4/index.20130430142921673 lockFactory=3Dorg.apache.lu= cene.store.NativeFSLockFactory@414f0e6e; maxCacheMB=3D48.0 maxMergeSizeMB= =3D4.0) fullCopy=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.680; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{file=3Dsegm= ents_4&command=3Dfilecontent&checksum=3Dtrue&wt=3Dfilestream&qt=3D/replicat= ion&generation=3D4} status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.683; org.apache.solr.handl= er.SnapPuller; Total time taken for download : 0 secs [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.685; org.apache.solr.updat= e.DefaultSolrCoreState; Creating new IndexWriter... [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.686; org.apache.solr.updat= e.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=3Dcolle= ction1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.691; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty4/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@3647b000; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_1,generation=3D1} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty4/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@3647b000; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_4,generation=3D4} [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.692; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 4 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.693; org.apache.solr.updat= e.DefaultSolrCoreState; New IndexWriter is ready to be used. [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.694; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@1cae295f main [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.696; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@1cae295f main{Stan= dardDirectoryReader(segments_4:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.697; org.apache.solr.core.= CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/wor= kspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.= solr.cloud.SyncSliceTest-1367357334551/jetty4/index.20130430142921673 [Cach= edDir<>] [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.698; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/w= orkspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apach= e.solr.cloud.SyncSliceTest-1367357334551/jetty4/index.20130430142921673 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.698; org.apache.solr.core.= CachingDirectoryFactory; Removing directory before core close: /usr/home/hu= dson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-cor= e/test/J0/org.apache.solr.cloud.SyncSliceTest-1367357334551/jetty4/index.20= 130430142921673 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.700; org.apache.solr.cloud= .RecoveryStrategy; No replay needed. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.700; org.apache.solr.cloud= .RecoveryStrategy; Replication Recovery was successful - registering as Act= ive. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.701; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.701; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-30 21:29:21.703; org.apache.solr.cloud= .RecoveryStrategy; Finished recovery process. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.173; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.175; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"5", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:13369_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:13369"} [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.193; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.193; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.193; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.193; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.193; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.193; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 5) [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.636; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.638; org.apache.solr.cloud= .AbstractDistribZkTestBase; Recoveries finished - collection: collection1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.652; 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-04-30 21:29:22.659; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=3D1 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/control/data/index lockFactory=3Dorg.apache.lucene.store.= NativeFSLockFactory@39823684; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN= =3Dsegments_1,generation=3D1} [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.659; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 1 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.664; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/control/data/index lockFactory=3Dorg.apache.lucene.store.= NativeFSLockFactory@39823684; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN= =3Dsegments_1,generation=3D1} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/control/data/index lockFactory=3Dorg.apache.lucene.store.= NativeFSLockFactory@39823684; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN= =3Dsegments_2,generation=3D2} [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.665; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 2 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.667; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@637f62e8 main [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.668; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.669; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@637f62e8 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.671; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{waitSearcher=3Dtrue&commit=3Dtrue&wt=3Djavabin&version=3D2&softCommit= =3Dfalse} {commit=3D} 0 19 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.696; 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-04-30 21:29:22.701; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D4 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_2,generation=3D2} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_3,generation=3D3} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_4,generation=3D4} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_5,generation=3D5} [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.702; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 5 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.703; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@34e19bf main [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.704; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.706; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@34e19bf main{Stand= ardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.720; org.apache.solr.updat= e.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:10279/co= llection1/, StdNode: http://127.0.0.1:40396/collection1/, StdNode: http://1= 27.0.0.1:13369/collection1/] params:commit_end_point=3Dtrue&commit=3Dtrue&s= oftCommit=3Dfalse&waitSearcher=3Dtrue&expungeDeletes=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.746; 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-04-30 21:29:22.747; 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-04-30 21:29:22.748; 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-04-30 21:29:22.763; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty2/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@623f1421; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_2,generation=3D2} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty2/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@623f1421; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_3,generation=3D3} [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.763; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty4/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@3647b000; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_4,generation=3D4} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty4/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@3647b000; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_5,generation=3D5} [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.763; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 3 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.763; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty3/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@2db0e390; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_3,generation=3D3} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty3/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@2db0e390; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_4,generation=3D4} [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.764; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 5 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.766; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@3fc988f4 main [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.766; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 4 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.767; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.768; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@1077b5d0 main [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.769; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@3fc988f4 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.769; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.769; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@55801a6 main [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.770; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{waitSearcher=3Dtrue&commit=3Dtrue&wt=3Djavabin&expungeDeletes=3Dfalse= &commit_end_point=3Dtrue&version=3D2&softCommit=3Dfalse} {commit=3D} 0 23 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.771; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.771; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@1077b5d0 main{Stan= dardDirectoryReader(segments_4:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.773; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@55801a6 main{Stand= ardDirectoryReader(segments_3:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.774; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{waitSearcher=3Dtrue&commit=3Dtrue&wt=3Djavabin&expungeDeletes=3Dfalse= &commit_end_point=3Dtrue&version=3D2&softCommit=3Dfalse} {commit=3D} 0 27 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.774; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{waitSearcher=3Dtrue&commit=3Dtrue&wt=3Djavabin&expungeDeletes=3Dfalse= &commit_end_point=3Dtrue&version=3D2&softCommit=3Dfalse} {commit=3D} 0 28 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.776; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{waitSearcher=3Dtrue&commit=3Dtrue&wt=3Djavabin&version=3D2&softCommit= =3Dfalse} {commit=3D} 0 80 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.778; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.805; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/select params=3D{tests=3DcheckSha= rdConsistency&q=3D*:*&distrib=3Dfalse&wt=3Djavabin&version=3D2&rows=3D0} hi= ts=3D0 status=3D0 QTime=3D6=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.810; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/select params=3D{tests=3DcheckSha= rdConsistency&q=3D*:*&distrib=3Dfalse&wt=3Djavabin&version=3D2&rows=3D0} hi= ts=3D0 status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.813; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/select params=3D{tests=3DcheckSha= rdConsistency&q=3D*:*&distrib=3Dfalse&wt=3Djavabin&version=3D2&rows=3D0} hi= ts=3D0 status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:22.817; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/select params=3D{tests=3DcheckSha= rdConsistency&q=3D*:*&distrib=3Dfalse&wt=3Djavabin&version=3D2&rows=3D0} hi= ts=3D0 status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-30 21:29:24.925; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {deleteByQuery=3D*:* (-1433778116241653760)= } 0 60 [junit4:junit4] 1> INFO - 2013-04-30 21:29:24.942; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{update.distrib=3DFROMLEADER&_version_=3D-1433778116288839680&update.f= rom=3Dhttp://127.0.0.1:22849/collection1/&wt=3Djavabin&version=3D2} {delete= ByQuery=3D*:* (-1433778116288839680)} 0 2 [junit4:junit4] 1> INFO - 2013-04-30 21:29:24.942; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{update.distrib=3DFROMLEADER&_version_=3D-1433778116288839680&update.f= rom=3Dhttp://127.0.0.1:22849/collection1/&wt=3Djavabin&version=3D2} {delete= ByQuery=3D*:* (-1433778116288839680)} 0 2 [junit4:junit4] 1> INFO - 2013-04-30 21:29:24.942; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{update.distrib=3DFROMLEADER&_version_=3D-1433778116288839680&update.f= rom=3Dhttp://127.0.0.1:22849/collection1/&wt=3Djavabin&version=3D2} {delete= ByQuery=3D*:* (-1433778116288839680)} 0 2 [junit4:junit4] 1> INFO - 2013-04-30 21:29:24.944; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {deleteByQuery=3D*:* (-1433778116288839680)= } 0 14 [junit4:junit4] 1> INFO - 2013-04-30 21:29:24.956; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[0 (1433778116307714048)]} 0 9 [junit4:junit4] 1> INFO - 2013-04-30 21:29:24.981; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:22849/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[0 (1433778116320296960)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-30 21:29:24.981; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:22849/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[0 (1433778116320296960)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-30 21:29:24.984; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:22849/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[0 (1433778116320296960)]} 0 5 [junit4:junit4] 1> INFO - 2013-04-30 21:29:24.985; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[0 (1433778116320296960)]} 0 25 [junit4:junit4] 1> INFO - 2013-04-30 21:29:24.990; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[1 (1433778116350705664)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.015; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:22849/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[1 (1433778116355948544)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.016; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:22849/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[1 (1433778116355948544)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.016; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:22849/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[1 (1433778116355948544)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.018; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[1 (1433778116355948544)]} 0 24 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.023; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[2 (1433778116385308672)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.028; org.apache.solr.updat= e.processor.DistributedUpdateProcessor; test.distrib.skip.servers was found= and contains:[http://127.0.0.1:10279/collection1/] [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.029; org.apache.solr.updat= e.processor.DistributedUpdateProcessor; check url:http://127.0.0.1:10279/co= llection1/ against:[http://127.0.0.1:10279/collection1/] result:true [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.030; org.apache.solr.updat= e.processor.DistributedUpdateProcessor; check url:http://127.0.0.1:40396/co= llection1/ against:[http://127.0.0.1:10279/collection1/] result:false [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.030; org.apache.solr.updat= e.processor.DistributedUpdateProcessor; check url:http://127.0.0.1:13369/co= llection1/ against:[http://127.0.0.1:10279/collection1/] result:false [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.039; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:22849/collection1/&update.distrib=3DF= ROMLEADER&test.distrib.skip.servers=3Dhttp://127.0.0.1:10279/collection1/&w= t=3Djavabin&version=3D2} {add=3D[2 (1433778116394745856)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.040; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:22849/collection1/&update.distrib=3DF= ROMLEADER&test.distrib.skip.servers=3Dhttp://127.0.0.1:10279/collection1/&w= t=3Djavabin&version=3D2} {add=3D[2 (1433778116394745856)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.042; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{test.distrib.skip.servers=3Dhttp://127.0.0.1:10279/collection1/&wt=3D= javabin&version=3D2} {add=3D[2 (1433778116394745856)]} 0 14 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.047; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[3 (1433778116410474496)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.052; org.apache.solr.updat= e.processor.DistributedUpdateProcessor; test.distrib.skip.servers was found= and contains:[http://127.0.0.1:10279/collection1/, http://127.0.0.1:40396/= collection1/] [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.052; org.apache.solr.updat= e.processor.DistributedUpdateProcessor; check url:http://127.0.0.1:10279/co= llection1/ against:[http://127.0.0.1:10279/collection1/, http://127.0.0.1:4= 0396/collection1/] result:true [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.053; org.apache.solr.updat= e.processor.DistributedUpdateProcessor; check url:http://127.0.0.1:40396/co= llection1/ against:[http://127.0.0.1:10279/collection1/, http://127.0.0.1:4= 0396/collection1/] result:true [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.054; org.apache.solr.updat= e.processor.DistributedUpdateProcessor; check url:http://127.0.0.1:13369/co= llection1/ against:[http://127.0.0.1:10279/collection1/, http://127.0.0.1:4= 0396/collection1/] result:false [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.062; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:22849/collection1/&update.distrib=3DF= ROMLEADER&test.distrib.skip.servers=3Dhttp://127.0.0.1:10279/collection1/&w= t=3Djavabin&version=3D2} {add=3D[3 (1433778116418863104)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.063; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{test.distrib.skip.servers=3Dhttp://127.0.0.1:10279/collection1/&test.= distrib.skip.servers=3Dhttp://127.0.0.1:40396/collection1/&wt=3Djavabin&ver= sion=3D2} {add=3D[3 (1433778116418863104)]} 0 12 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.066; 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-04-30 21:29:25.147; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D2 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/control/data/index lockFactory=3Dorg.apache.lucene.store.= NativeFSLockFactory@39823684; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN= =3Dsegments_2,generation=3D2} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/control/data/index lockFactory=3Dorg.apache.lucene.store.= NativeFSLockFactory@39823684; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN= =3Dsegments_3,generation=3D3} [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.148; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 3 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.199; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@fa4b83c main [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.200; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.201; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@fa4b83c main{Stand= ardDirectoryReader(segments_3:3:nrt _0(4.4):C4)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.201; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{waitSearcher=3Dtrue&commit=3Dtrue&wt=3Djavabin&version=3D2&softCommit= =3Dfalse} {commit=3D} 0 135 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.206; 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-04-30 21:29:25.270; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=3D5 [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_2,generation=3D2} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_3,generation=3D3} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_4,generation=3D4} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_5,generation=3D5} [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceT= est-1367357334551/jetty1/index lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@26d01b2e; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0),segFN=3Dseg= ments_6,generation=3D6} [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.272; org.apache.solr.core.= SolrDeletionPolicy; newest commit generation =3D 6 [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.280; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@37e64c3a main [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.281; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.282; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@37e64c3a main{Stan= dardDirectoryReader(segments_6:3:nrt _0(4.4):C4)} [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.284; org.apache.solr.updat= e.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:10279/co= llection1/, StdNode: http://127.0.0.1:40396/collection1/, StdNode: http://1= 27.0.0.1:13369/collection1/] params:commit_end_point=3Dtrue&commit=3Dtrue&s= oftCommit=3Dfalse&waitSearcher=3Dtrue&expungeDeletes=3Dfalse [junit4:junit4] 1> INFO - 2013-04-30 21:29:25.288; 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-04-30 21:29:25.288; 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-04-30 21:29:25.288; 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-04-30 2 [...truncated too long message...] 3778561528889344}, {id=3D209, _version_=3D1433778560220266496}, {id=3D101, = _version_=3D1433778558202806272}, {id=3D167, _version_=3D143377855942964019= 2}, {id=3D51, _version_=3D1433778557209804800}, {id=3D166, _version_=3D1433= 778559411814400}, {id=3D170, _version_=3D1433778559485214720}, {id=3D73, _v= ersion_=3D1433778557676421120}, {id=3D214, _version_=3D1433778560314638336}= , {id=3D260, _version_=3D1433778561144061952}, {id=3D92, _version_=3D143377= 8558028742656}, {id=3D118, _version_=3D1433778558490116096}, {id=3D140, _ve= rsion_=3D1433778558912692224}, {id=3D161, _version_=3D1433778559316393984},= {id=3D38, _version_=3D1433778556924592128}, {id=3D65, _version_=3D14337785= 57510746112}, {id=3D284, _version_=3D1433778561579220992}, {id=3D86, _versi= on_=3D1433778557912350720}, {id=3D27, _version_=3D1433778556664545280}, {id= =3D105, _version_=3D1433778558274109440}, {id=3D96, _version_=3D14337785581= 06337280}, {id=3D212, _version_=3D1433778560277938176}, {id=3D102, _version= _=3D1433778558220632064}, {id=3D35, _version_=3D1433778556850143232}, {id= =3D192, _version_=3D1433778559882625024}, {id=3D304, _version_=3D1433778561= 901133824}, {id=3D172, _version_=3D1433778559522963456}, {id=3D215, _versio= n_=3D1433778560332464128}, {id=3D259, _version_=3D1433778561123090432}, {id= =3D87, _version_=3D1433778557933322240}, {id=3D295, _version_=3D14337785617= 55381760}, {id=3D30, _version_=3D1433778556734799872}, {id=3D158, _version_= =3D1433778559258722304}, {id=3D33, _version_=3D1433778556802957312}] [junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=3DSyncSlice= Test -Dtests.method=3DtestDistribSearch -Dtests.seed=3D281FAD1599F56F49 -Dt= ests.multiplier=3D3 -Dtests.slow=3Dtrue -Dtests.locale=3Dlt_LT -Dtests.time= zone=3DAmerica/Hermosillo -Dtests.file.encoding=3DUS-ASCII [junit4:junit4] FAILURE 846s J0 | SyncSliceTest.testDistribSearch <<< [junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not = consistent. Got 305 from http://127.0.0.1:40396/collection1lastClient and = got 5 from http://127.0.0.1:13369/collection1 [junit4:junit4] > =09at __randomizedtesting.SeedInfo.seed([281FAD1599F56= F49:A9F9230DEEAA0F75]:0) [junit4:junit4] > =09at org.apache.solr.cloud.AbstractFullDistribZkTestB= ase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963) [junit4:junit4] > =09at org.apache.solr.cloud.SyncSliceTest.doTest(SyncS= liceTest.java:238) [junit4:junit4] > =09at org.apache.solr.BaseDistributedSearchTestCase.te= stDistribSearch(BaseDistributedSearchTestCase.java:815) [junit4:junit4] > =09at java.lang.Thread.run(Thread.java:722) [junit4:junit4] 1> INFO - 2013-04-30 21:43:00.050; org.apache.solr.SolrT= estCaseJ4; ###deleteCore [junit4:junit4] 1> WARN - 2013-04-30 21:43:00.945; org.apache.solr.commo= n.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to= ZK [junit4:junit4] 1> INFO - 2013-04-30 21:43:00.945; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 1) [junit4:junit4] 1> WARN - 2013-04-30 21:43:00.946; org.apache.solr.commo= n.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to= ZK [junit4:junit4] 1> WARN - 2013-04-30 21:43:27.518; org.apache.solr.updat= e.PeerSync; PeerSync: core=3Dcollection1 url=3Dhttp://127.0.0.1:40396 coul= dn't connect to http://127.0.0.1:22849/collection1/, counting as success [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.519; org.apache.solr.updat= e.PeerSync; PeerSync: core=3Dcollection1 url=3Dhttp://127.0.0.1:40396 DONE.= sync succeeded [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.519; org.apache.solr.cloud= .SyncStrategy; We have been closed, won't attempt to sync replicas back to = leader [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.520; org.apache.solr.cloud= .ShardLeaderElectionContext; Not rejoining election because CoreContainer i= s shutdown [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.520; org.apache.solr.core.= SolrCore; [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@6d9= 7768d [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.523; org.apache.solr.updat= e.DirectUpdateHandler2; closing DirectUpdateHandler2{commits=3D51,autocommi= ts=3D0,soft autocommits=3D0,optimizes=3D0,rollbacks=3D0,expungeDeletes=3D0,= docsPending=3D0,adds=3D0,deletesById=3D0,deletesByQuery=3D0,errors=3D0,cumu= lative_adds=3D5,cumulative_deletesById=3D0,cumulative_deletesByQuery=3D1,cu= mulative_errors=3D0} [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.524; org.apache.solr.updat= e.SolrCoreState; Closing SolrCoreState [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.524; org.apache.solr.updat= e.DefaultSolrCoreState; SolrCoreState ref count has reached 0 - closing Ind= exWriter [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.525; org.apache.solr.updat= e.DefaultSolrCoreState; closing IndexWriter with IndexWriterCloser [junit4:junit4] 1> ERROR - 2013-04-30 21:43:27.525; org.apache.solr.updat= e.TransactionLog; Error: Forcing close of tlog{file=3D./org.apache.solr.clo= ud.SyncSliceTest-1367357334551/jetty3/tlog/tlog.0000000000000000005 refcoun= t=3D2} [junit4:junit4] 1> ERROR - 2013-04-30 21:43:27.526; org.apache.solr.updat= e.TransactionLog; Error: Forcing close of tlog{file=3D./org.apache.solr.clo= ud.SyncSliceTest-1367357334551/jetty3/tlog/tlog.0000000000000000002 refcoun= t=3D2} [junit4:junit4] 1> ERROR - 2013-04-30 21:43:27.526; org.apache.solr.updat= e.TransactionLog; Error: Forcing close of tlog{file=3D./org.apache.solr.clo= ud.SyncSliceTest-1367357334551/jetty3/tlog/tlog.0000000000000000001 refcoun= t=3D2} [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.529; org.apache.solr.core.= SolrCore; [collection1] Closing main searcher on request. [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.530; org.apache.solr.core.= CachingDirectoryFactory; Closing NRTCachingDirectoryFactory - 2 directories= currently being tracked [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.531; org.apache.solr.core.= CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/wor= kspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.= solr.cloud.SyncSliceTest-1367357334551/jetty3/index.20130430143639534 [Cach= edDir<>] [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.531; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/w= orkspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apach= e.solr.cloud.SyncSliceTest-1367357334551/jetty3/index.20130430143639534 [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.532; org.apache.solr.core.= CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/wor= kspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.= solr.cloud.SyncSliceTest-1367357334551/jetty3 [CachedDir<>] [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.532; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/w= orkspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apach= e.solr.cloud.SyncSliceTest-1367357334551/jetty3 [junit4:junit4] 1> WARN - 2013-04-30 21:43:27.532; org.apache.solr.commo= n.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to= ZK [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.533; 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> WARN - 2013-04-30 21:43:27.533; org.apache.solr.commo= n.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to= ZK [junit4:junit4] 1> INFO - 2013-04-30 21:43:27.533; 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> WARN - 2013-04-30 21:43:27.534; org.apache.solr.commo= n.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to= ZK [junit4:junit4] 2> NOTE: test params are: codec=3DAsserting, sim=3DDefaul= tSimilarity, locale=3Dlt_LT, timezone=3DAmerica/Hermosillo [junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Oracle Corporation 1.7= .0_17 (64-bit)/cpus=3D16,threads=3D3,free=3D87634800,total=3D153092096 [junit4:junit4] 2> NOTE: All tests run in this JVM: [OutputWriterTest, Si= gnatureUpdateProcessorFactoryTest, CoreContainerCoreInitFailuresTest, SyncS= liceTest] [junit4:junit4] Completed on J0 in 873.59s, 1 test, 1 failure <<< FAILURES! [...truncated 716 lines...] BUILD FAILED /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/build.x= ml:384: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/build.x= ml:364: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/build.x= ml:39: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/bu= ild.xml:181: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/co= mmon-build.xml:437: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/lucene/= common-build.xml:1243: The following error occurred while executing this li= ne: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/lucene/= common-build.xml:887: There were test failures: 294 suites, 1222 tests, 1 f= ailure, 27 ignored (8 assumptions) Total time: 53 minutes 37 seconds Build step 'Invoke Ant' marked build as failure Archiving artifacts Recording test results Email was triggered for: Failure Sending email for trigger: Failure ------=_Part_6598_2006511544.1367359323600 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_6598_2006511544.1367359323600--