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 E0CCBF761 for ; Sat, 13 Apr 2013 18:49:17 +0000 (UTC) Received: (qmail 16301 invoked by uid 500); 13 Apr 2013 18:49:16 -0000 Delivered-To: apmail-lucene-dev-archive@lucene.apache.org Received: (qmail 16233 invoked by uid 500); 13 Apr 2013 18:49:16 -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 16057 invoked by uid 99); 13 Apr 2013 18:49:15 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Sat, 13 Apr 2013 18:49:15 +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; Sat, 13 Apr 2013 18:49:06 +0000 Received: from aegis.apache.org (localhost [127.0.0.1]) by aegis.apache.org (Postfix) with ESMTP id 28076C0071 for ; Sat, 13 Apr 2013 18:48:46 +0000 (UTC) Date: Sat, 13 Apr 2013 18:48:28 +0000 (UTC) From: Apache Jenkins Server To: dev@lucene.apache.org Message-ID: <1337330254.2256.1365878926149.JavaMail.hudson@aegis> Subject: [JENKINS] Lucene-Solr-NightlyTests-4.x - Build # 231 - Failure MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----=_Part_2255_112164329.1365878908528" X-Jenkins-Job: Lucene-Solr-NightlyTests-4.x X-Jenkins-Result: FAILURE X-Virus-Checked: Checked by ClamAV on apache.org ------=_Part_2255_112164329.1365878908528 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-4.x/231/ 1 tests failed. REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSea= rch Error Message: Wrong doc count on shard1_1 expected:<49> but was:<50> Stack Trace: java.lang.AssertionError: Wrong doc count on shard1_1 expected:<49> but was= :<50> =09at __randomizedtesting.SeedInfo.seed([A785E86F181BE2F6:266366776F4482CA]= :0) =09at org.junit.Assert.fail(Assert.java:93) =09at org.junit.Assert.failNotEquals(Assert.java:647) =09at org.junit.Assert.assertEquals(Assert.java:128) =09at org.junit.Assert.assertEquals(Assert.java:472) =09at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeySha= rdSplitTest.java:274) =09at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseD= istributedSearchTestCase.java:806) =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:616) =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:679) Build Log: [...truncated 9308 lines...] [junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest [junit4:junit4] 1> INFO - 2013-04-13 18:46:03.916; org.apache.solr.BaseD= istributedSearchTestCase; Setting hostContext system property: / [junit4:junit4] 1> INFO - 2013-04-13 18:46:03.920; org.apache.solr.SolrT= estCaseJ4; ###Starting testDistribSearch [junit4:junit4] 1> INFO - 2013-04-13 18:46:03.921; 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-13 18:46:03.921; org.apache.solr.cloud= .ZkTestServer$ZKServerMain; Starting server [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.022; org.apache.solr.cloud= .ZkTestServer; start zk server on port:29280 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.023; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.027; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@3c299c45 name:ZooKeeperConnection Watcher:127.0.0.1:29280 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.027; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.028; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /solr [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.043; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.045; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@5ccd8418 name:ZooKeeperConnection Watcher:127.0.0.1:29280/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.045; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.045; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.056; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/shards [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.058; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.060; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/shards [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.069; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/so= lrconfig-tlog.xml to /configs/conf1/solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.070; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.086; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/sc= hema.xml to /configs/conf1/schema.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.087; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.190; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/st= opwords.txt to /configs/conf1/stopwords.txt [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.191; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.193; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/pr= otwords.txt to /configs/conf1/protwords.txt [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.194; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.205; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/cu= rrency.xml to /configs/conf1/currency.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.206; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.209; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/op= en-exchange-rates.json to /configs/conf1/open-exchange-rates.json [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.209; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.212; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/ma= pping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.213; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.216; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/ol= d_synonyms.txt to /configs/conf1/old_synonyms.txt [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.216; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.224; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/sy= nonyms.txt to /configs/conf1/synonyms.txt [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.224; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.423; org.eclipse.jetty.ser= ver.Server; jetty-8.1.8.v20121106 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.427; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:16351 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.428; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.428; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.429; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-136587= 8764228 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.429; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/tes= t/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1365878= 764228/solr.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.430; org.apache.solr.core.= CoreContainer; New CoreContainer 2129100747 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.431; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/= J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-136587876= 4228/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.431; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/t= est/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-13658= 78764228/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.483; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.484; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.484; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.485; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.485; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.486; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.486; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.487; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.487; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.488; 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-13 18:46:04.506; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.524; org.apache.solr.core.= CoreContainer; Zookeeper client=3D127.0.0.1:29280/solr [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.525; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.526; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.529; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@7f46a18d name:ZooKeeperConnection Watcher:127.0.0.1:29280 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.530; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.539; 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-13 18:46:04.549; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.551; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@54716e87 name:ZooKeeperConnection Watcher:127.0.0.1:29280/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.551; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.553; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/queue [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.562; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/collection-queue-work [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.570; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.571; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:163= 51_ [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.573; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:16351_ [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.583; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer_elect/election [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.598; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer_elect/leader [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.600; org.apache.solr.cloud= .Overseer; Overseer (id=3D89514230672588803-127.0.0.1:16351_-n_0000000000) = starting [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.610; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/queue-work [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.622; org.apache.solr.cloud= .OverseerCollectionProcessor; Process current queue of collection creations [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.622; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /clusterstate.json [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.624; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /aliases.json [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.632; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.635; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Starting to work on the main queue [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.638; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr= -core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljett= y-1365878764228/collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.639; org.apache.solr.cloud= .ZkController; Check for collection zkNode:control_collection [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.639; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.639; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/control_collection [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.641; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/t= est/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-13658= 78764228/collection1/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.642; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.clo= ud.ChaosMonkeyShardSplitTest-controljetty-1365878764228/collection1/lib/REA= DME' to classloader [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.643; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.clo= ud.ChaosMonkeyShardSplitTest-controljetty-1365878764228/collection1/lib/cla= sses/' to classloader [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.689; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_43 [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.747; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.848; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:04.854; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.461; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.474; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.479; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.489; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.492; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.495; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-13 18:46:05.495; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-13 18:46:05.495; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.496; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-13 18:46:05.496; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-13 18:46:05.496; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.497; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.497; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1365878764228/co= llection1/, dataDir=3D./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-136= 5878763920/control/data/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.497; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@5253c3f5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.497; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.498; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/control/data [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.499; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ChaosMonkeyShardSplitTest-1365878763920/control/data/index/ [junit4:junit4] 1> WARN - 2013-04-13 18:46:05.499; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Chaos= MonkeyShardSplitTest-1365878763920/control/data/index' doesn't exist. Creat= ing new index... [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.500; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/control/data/in= dex [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.504; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/control/data/index lockFactory=3Dorg.apache.= lucene.store.NativeFSLockFactory@62b1fb50; maxCacheMB=3D48.0 maxMergeSizeMB= =3D4.0),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.504; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.506; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.506; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.507; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.507; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.507; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.508; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.508; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.508; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.508; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.513; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.518; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@2f5c610 main [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.519; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.519; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.521; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@2f5c610 main{Stand= ardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.522; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-13 18:46:05.522; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.138; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.139; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":null, [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:16351_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:16351"} [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.139; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Create collection control_collection with nu= mShards 1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.139; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.171; 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-13 18:46:06.525; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.525; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :16351 collection:control_collection shard:shard1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.526; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elec= t/shard1/election [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.551; org.apache.solr.cloud= .ShardLeaderElectionContext; Running the leader process. [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.554; org.apache.solr.cloud= .ShardLeaderElectionContext; Enough replicas found to continue. [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.554; org.apache.solr.cloud= .ShardLeaderElectionContext; I may be the new leader - try and sync [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.554; org.apache.solr.cloud= .SyncStrategy; Sync replicas to http://127.0.0.1:16351/collection1/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.554; org.apache.solr.cloud= .SyncStrategy; Sync Success - now sync replicas to me [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.555; org.apache.solr.cloud= .SyncStrategy; http://127.0.0.1:16351/collection1/ has no replicas [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.555; org.apache.solr.cloud= .ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:16351/co= llection1/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:06.555; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/sha= rd1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.682; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.697; 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-13 18:46:07.733; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:16351/collection1/ and leader is htt= p://127.0.0.1:16351/collection1/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.733; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:16351 [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.733; org.apache.solr.cloud= .ZkController; I am the leader, no recovery necessary [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.733; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.734; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.735; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.736; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.737; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.737; 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-13 18:46:07.751; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config: [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.752; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.754; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@10091bf2 name:ZooKeeperConnection Watcher:127.0.0.1:29280/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.754; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.755; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.757; org.apache.solr.cloud= .ChaosMonkey; monkey: init - expire sessions:true cause connection loss:tru= e [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.954; org.eclipse.jetty.ser= ver.Server; jetty-8.1.8.v20121106 [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.957; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:11449 [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.957; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.958; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.958; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-136587876775= 8 [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.959; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/tes= t/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365878767758= /solr.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.959; org.apache.solr.core.= CoreContainer; New CoreContainer 265714354 [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.960; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/= J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365878767758/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:07.960; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/t= est/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-13658787677= 58/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.012; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.013; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.013; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.014; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.014; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.015; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.015; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.016; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.016; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.017; 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-13 18:46:08.037; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.055; org.apache.solr.core.= CoreContainer; Zookeeper client=3D127.0.0.1:29280/solr [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.055; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.056; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.059; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@339726c8 name:ZooKeeperConnection Watcher:127.0.0.1:29280 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.060; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.061; 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-13 18:46:08.073; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.074; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@63917066 name:ZooKeeperConnection Watcher:127.0.0.1:29280/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.075; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:08.086; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.089; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:114= 49_ [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.091; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:11449_ [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.094; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.094; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.094; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.094; 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-13 18:46:09.110; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr= -core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365= 878767758/collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.110; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.111; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.111; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.113; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/t= est/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-13658787677= 58/collection1/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.114; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.clo= ud.ChaosMonkeyShardSplitTest-jetty1-1365878767758/collection1/lib/classes/'= to classloader [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.114; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.clo= ud.ChaosMonkeyShardSplitTest-jetty1-1365878767758/collection1/lib/README' t= o classloader [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.161; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_43 [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.207; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.208; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"127.0.0.1:16351__collection1", [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:16351_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:16351"} [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.218; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.221; 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-13 18:46:09.221; 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-13 18:46:09.221; 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-13 18:46:09.222; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.228; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.828; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.839; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.844; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.855; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.860; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.864; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-13 18:46:09.865; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-13 18:46:09.866; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.866; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-13 18:46:09.867; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-13 18:46:09.867; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.867; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.868; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365878767758/collecti= on1/, dataDir=3D./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-136587876= 3920/jetty1/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.868; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@5253c3f5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.869; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.869; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.870; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty1/index/ [junit4:junit4] 1> WARN - 2013-04-13 18:46:09.871; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Chaos= MonkeyShardSplitTest-1365878763920/jetty1/index' doesn't exist. Creating ne= w index... [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.871; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty1/index [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.877; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty1/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@ac90383; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0)= ,segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.877; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.880; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.880; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.881; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.881; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.882; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.882; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.882; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.883; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.883; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.890; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.898; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@1184cd94 main [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.899; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.899; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.903; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@1184cd94 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.909; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-13 18:46:09.910; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.725; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.726; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":null, [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:11449_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11449"} [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.726; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Create collection collection1 with numShards= 2 [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.726; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.747; 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-13 18:46:10.747; 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-13 18:46:10.747; 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-13 18:46:10.913; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.913; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :11449 collection:collection1 shard:shard1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.914; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard= 1/election [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.929; org.apache.solr.cloud= .ShardLeaderElectionContext; Running the leader process. [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.931; org.apache.solr.cloud= .ShardLeaderElectionContext; Enough replicas found to continue. [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.932; org.apache.solr.cloud= .ShardLeaderElectionContext; I may be the new leader - try and sync [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.932; org.apache.solr.cloud= .SyncStrategy; Sync replicas to http://127.0.0.1:11449/collection1/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.932; org.apache.solr.cloud= .SyncStrategy; Sync Success - now sync replicas to me [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.932; org.apache.solr.cloud= .SyncStrategy; http://127.0.0.1:11449/collection1/ has no replicas [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.933; org.apache.solr.cloud= .ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:11449/co= llection1/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:10.933; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.261; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.305; 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-13 18:46:12.305; 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-13 18:46:12.305; 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-13 18:46:12.315; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:11449/collection1/ and leader is htt= p://127.0.0.1:11449/collection1/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.315; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:11449 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.315; org.apache.solr.cloud= .ZkController; I am the leader, no recovery necessary [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.315; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.316; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.317; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.318; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.319; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.319; 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-13 18:46:12.528; org.eclipse.jetty.ser= ver.Server; jetty-8.1.8.v20121106 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.532; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:11458 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.533; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.533; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.534; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-136587877233= 2 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.534; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/tes= t/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365878772332= /solr.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.535; org.apache.solr.core.= CoreContainer; New CoreContainer 636150971 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.535; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/= J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365878772332/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.536; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/t= est/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-13658787723= 32/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.588; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.588; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.589; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.589; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.590; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.590; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.591; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.591; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.592; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.592; 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-13 18:46:12.610; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.628; org.apache.solr.core.= CoreContainer; Zookeeper client=3D127.0.0.1:29280/solr [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.629; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.630; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.658; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@534284ce name:ZooKeeperConnection Watcher:127.0.0.1:29280 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.658; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.678; 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-13 18:46:12.687; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.689; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@7ce3742a name:ZooKeeperConnection Watcher:127.0.0.1:29280/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.689; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:12.700; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.703; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:114= 58_ [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.705; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:11458_ [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.707; 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-13 18:46:13.708; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.708; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.708; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.708; 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-13 18:46:13.709; 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-13 18:46:13.727; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.732; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr= -core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365= 878772332/collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.733; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.733; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.733; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.734; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/t= est/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-13658787723= 32/collection1/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.736; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.clo= ud.ChaosMonkeyShardSplitTest-jetty2-1365878772332/collection1/lib/classes/'= to classloader [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.736; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.clo= ud.ChaosMonkeyShardSplitTest-jetty2-1365878772332/collection1/lib/README' t= o classloader [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.783; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_43 [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.816; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.817; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"127.0.0.1:11449__collection1", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:11449_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11449"} [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.835; 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-13 18:46:13.835; 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-13 18:46:13.835; 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-13 18:46:13.835; 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-13 18:46:13.842; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.942; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:13.947; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.528; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.536; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.539; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.549; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.552; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.555; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-13 18:46:14.556; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-13 18:46:14.556; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.556; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-13 18:46:14.557; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-13 18:46:14.557; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.557; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.558; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365878772332/collecti= on1/, dataDir=3D./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-136587876= 3920/jetty2/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.558; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@5253c3f5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.558; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.559; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty2 [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.559; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty2/index/ [junit4:junit4] 1> WARN - 2013-04-13 18:46:14.560; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Chaos= MonkeyShardSplitTest-1365878763920/jetty2/index' doesn't exist. Creating ne= w index... [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.560; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty2/index [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.585; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty2/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@2856c9b2; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.585; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.587; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.587; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.587; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.588; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.588; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.588; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.589; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.589; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.589; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.594; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.599; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@16fdd29b main [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.599; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.600; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.603; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@16fdd29b main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.604; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-13 18:46:14.604; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.339; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.340; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":null, [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:11458_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11458"} [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.340; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D2 [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.340; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard2 [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.379; 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-13 18:46:15.379; 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-13 18:46:15.379; 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-13 18:46:15.379; 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-13 18:46:15.606; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.606; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :11458 collection:collection1 shard:shard2 [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.607; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard= 2/election [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.621; org.apache.solr.cloud= .ShardLeaderElectionContext; Running the leader process. [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.624; org.apache.solr.cloud= .ShardLeaderElectionContext; Enough replicas found to continue. [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.624; org.apache.solr.cloud= .ShardLeaderElectionContext; I may be the new leader - try and sync [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.624; org.apache.solr.cloud= .SyncStrategy; Sync replicas to http://127.0.0.1:11458/collection1/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.624; org.apache.solr.cloud= .SyncStrategy; Sync Success - now sync replicas to me [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.625; org.apache.solr.cloud= .SyncStrategy; http://127.0.0.1:11458/collection1/ has no replicas [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.625; org.apache.solr.cloud= .ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:11458/co= llection1/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:15.625; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2 [junit4:junit4] 1> INFO - 2013-04-13 18:46:16.883; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:16.903; 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-13 18:46:16.903; 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-13 18:46:16.903; 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-13 18:46:16.903; 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-13 18:46:16.955; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:11458/collection1/ and leader is htt= p://127.0.0.1:11458/collection1/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:16.955; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:11458 [junit4:junit4] 1> INFO - 2013-04-13 18:46:16.955; org.apache.solr.cloud= .ZkController; I am the leader, no recovery necessary [junit4:junit4] 1> INFO - 2013-04-13 18:46:16.955; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-13 18:46:16.956; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-13 18:46:16.957; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:16.958; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:16.959; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-13 18:46:16.959; 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-13 18:46:17.170; org.eclipse.jetty.ser= ver.Server; jetty-8.1.8.v20121106 [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.172; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:11462 [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.173; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.174; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.174; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-136587877697= 3 [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.175; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/tes= t/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365878776973= /solr.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.175; org.apache.solr.core.= CoreContainer; New CoreContainer 624666723 [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.176; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/= J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365878776973/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.176; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/t= est/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-13658787769= 73/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.228; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.229; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.229; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.230; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.230; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.231; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.231; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.232; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.232; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.232; 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-13 18:46:17.251; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.269; org.apache.solr.core.= CoreContainer; Zookeeper client=3D127.0.0.1:29280/solr [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.270; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.271; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.273; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@8f7b922 name:ZooKeeperConnection Watcher:127.0.0.1:29280 got event W= atchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.274; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.290; 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-13 18:46:17.301; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.303; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@1302be2 name:ZooKeeperConnection Watcher:127.0.0.1:29280/solr got ev= ent WatchedEvent state:SyncConnected type:None path:null path:null type:Non= e [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.303; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:17.312; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.315; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:114= 62_ [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.317; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:11462_ [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.371; 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-13 18:46:18.372; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.372; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.372; 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-13 18:46:18.372; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.372; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.372; 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-13 18:46:18.373; 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-13 18:46:18.374; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.379; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr= -core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365= 878776973/collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.380; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.380; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.380; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.382; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/t= est/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-13658787769= 73/collection1/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.383; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.clo= ud.ChaosMonkeyShardSplitTest-jetty3-1365878776973/collection1/lib/classes/'= to classloader [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.384; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.clo= ud.ChaosMonkeyShardSplitTest-jetty3-1365878776973/collection1/lib/README' t= o classloader [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.415; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.416; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"127.0.0.1:11458__collection1", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard2", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:11458_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11458"} [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.431; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_43 [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.487; 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-13 18:46:18.487; 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-13 18:46:18.488; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.487; 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-13 18:46:18.487; 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-13 18:46:18.487; 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-13 18:46:18.661; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:18.666; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.265; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.277; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.281; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.292; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.297; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.301; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-13 18:46:19.302; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-13 18:46:19.303; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.303; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-13 18:46:19.304; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-13 18:46:19.304; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.305; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.305; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365878776973/collecti= on1/, dataDir=3D./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-136587876= 3920/jetty3/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.305; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@5253c3f5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.306; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.307; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty3 [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.307; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty3/index/ [junit4:junit4] 1> WARN - 2013-04-13 18:46:19.308; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Chaos= MonkeyShardSplitTest-1365878763920/jetty3/index' doesn't exist. Creating ne= w index... [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.309; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty3/index [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.342; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty3/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@71413b85; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.343; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.345; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.345; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.346; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.347; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.347; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.347; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.348; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.348; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.349; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.356; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.363; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@739cbfb9 main [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.364; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.364; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.368; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@739cbfb9 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.369; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-13 18:46:19.370; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.063; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.064; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":null, [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:11462_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11462"} [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.064; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D2 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.064; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.079; 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-13 18:46:20.079; 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-13 18:46:20.079; 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-13 18:46:20.079; 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-13 18:46:20.079; 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-13 18:46:20.373; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.373; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :11462 collection:collection1 shard:shard1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.413; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:11462/collection1/ and leader is htt= p://127.0.0.1:11449/collection1/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.414; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:11462 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.414; org.apache.solr.cloud= .ZkController; Core needs to recover:collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.414; org.apache.solr.updat= e.DefaultSolrCoreState; Running recovery - first canceling any ongoing reco= very [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.415; org.apache.solr.cloud= .RecoveryStrategy; Starting recovery process. core=3Dcollection1 recoverin= gAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.416; org.apache.solr.cloud= .RecoveryStrategy; ###### startupVersions=3D[] [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.416; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.416; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Drecovering [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.416; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.417; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.417; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.418; 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-13 18:46:20.418; 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-13 18:46:20.438; org.apache.solr.handl= er.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:11462_= _collection1, state: recovering, checkLive: true, onlyIfLeader: true [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.635; org.eclipse.jetty.ser= ver.Server; jetty-8.1.8.v20121106 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.638; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:11466 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.639; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.639; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.640; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-136587878043= 7 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.640; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/tes= t/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365878780437= /solr.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.641; org.apache.solr.core.= CoreContainer; New CoreContainer 934193490 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.642; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/= J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365878780437/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.642; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/t= est/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-13658787804= 37/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.695; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.695; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.696; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.696; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.697; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.697; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.698; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.698; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.699; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.699; 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-13 18:46:20.718; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.736; org.apache.solr.core.= CoreContainer; Zookeeper client=3D127.0.0.1:29280/solr [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.737; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.738; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.741; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@2fa90103 name:ZooKeeperConnection Watcher:127.0.0.1:29280 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.741; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.743; 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-13 18:46:20.753; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.755; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@18a3e9e8 name:ZooKeeperConnection Watcher:127.0.0.1:29280/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.755; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:20.767; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.583; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.584; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"127.0.0.1:11462__collection1", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"recovering", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:11462_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11462"} [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.601; 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-13 18:46:21.601; 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-13 18:46:21.601; 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-13 18:46:21.601; 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-13 18:46:21.601; 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-13 18:46:21.601; 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-13 18:46:21.770; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:114= 66_ [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.772; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:11466_ [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.774; 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-13 18:46:21.774; 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-13 18:46:21.774; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.774; 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-13 18:46:21.775; 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-13 18:46:21.774; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.776; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.774; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.776; 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-13 18:46:21.776; 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-13 18:46:21.782; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.789; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.794; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr= -core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365= 878780437/collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.794; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.795; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.795; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.796; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/t= est/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-13658787804= 37/collection1/' [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.797; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.clo= ud.ChaosMonkeyShardSplitTest-jetty4-1365878780437/collection1/lib/classes/'= to classloader [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.798; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.clo= ud.ChaosMonkeyShardSplitTest-jetty4-1365878780437/collection1/lib/README' t= o classloader [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.844; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_43 [junit4:junit4] 1> INFO - 2013-04-13 18:46:21.901; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.002; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.007; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.441; org.apache.solr.handl= er.admin.CoreAdminHandler; Waited coreNodeName: 127.0.0.1:11462__collection= 1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds. [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.441; org.apache.solr.servl= et.SolrDispatchFilter; [admin] webapp=3Dnull path=3D/admin/cores params=3D{= coreNodeName=3D127.0.0.1:11462__collection1&state=3Drecovering&nodeName=3D1= 27.0.0.1:11462_&action=3DPREPRECOVERY&checkLive=3Dtrue&core=3Dcollection1&w= t=3Djavabin&onlyIfLeader=3Dtrue&version=3D2} status=3D0 QTime=3D2003=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.600; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.611; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.615; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.627; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.631; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.636; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-13 18:46:22.637; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-13 18:46:22.637; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.637; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-13 18:46:22.638; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-13 18:46:22.639; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.639; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.639; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365878780437/collecti= on1/, dataDir=3D./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-136587876= 3920/jetty4/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.639; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@5253c3f5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.640; org.apache.solr.core.= SolrCore; solr.NRTCachingDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.641; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty4 [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.641; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty4/index/ [junit4:junit4] 1> WARN - 2013-04-13 18:46:22.642; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Chaos= MonkeyShardSplitTest-1365878763920/jetty4/index' doesn't exist. Creating ne= w index... [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.643; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty4/index [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.648; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty4/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@2abc73c9; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.648; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.651; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.651; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.651; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.652; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.653; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.653; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.653; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.654; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.654; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.661; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.667; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@1033edfe main [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.668; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.669; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.672; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@1033edfe main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.674; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-13 18:46:22.674; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.106; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.107; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":null, [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:11466_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11466"} [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.107; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D2 [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.107; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard2 [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.111; 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-13 18:46:23.111; 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-13 18:46:23.111; 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-13 18:46:23.111; 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-13 18:46:23.111; 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-13 18:46:23.111; 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-13 18:46:23.676; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.676; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :11466 collection:collection1 shard:shard2 [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.709; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:11466/collection1/ and leader is htt= p://127.0.0.1:11458/collection1/ [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.709; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:11466 [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.709; org.apache.solr.cloud= .ZkController; Core needs to recover:collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.709; org.apache.solr.updat= e.DefaultSolrCoreState; Running recovery - first canceling any ongoing reco= very [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.710; org.apache.solr.cloud= .RecoveryStrategy; Starting recovery process. core=3Dcollection1 recoverin= gAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.710; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.711; org.apache.solr.cloud= .RecoveryStrategy; ###### startupVersions=3D[] [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.711; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Drecovering [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.711; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.712; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.713; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.713; 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-13 18:46:23.731; 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-13 18:46:23.731; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.732; org.apache.solr.cloud= .AbstractFullDistribZkTestBase; Wait for recoveries to finish - wait 15 for= each attempt [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.733; org.apache.solr.cloud= .AbstractDistribZkTestBase; Wait for recoveries to finish - collection: col= lection1 failOnTimeout:true timeout (sec):15 [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.734; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:23.741; org.apache.solr.handl= er.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:11466_= _collection1, state: recovering, checkLive: true, onlyIfLeader: true [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.443; org.apache.solr.cloud= .RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:11449/colle= ction1/ core=3Dcollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.443; org.apache.solr.updat= e.PeerSync; PeerSync: core=3Dcollection1 url=3Dhttp://127.0.0.1:11462 START= replicas=3D[http://127.0.0.1:11449/collection1/] nUpdates=3D100 [junit4:junit4] 1> WARN - 2013-04-13 18:46:24.443; org.apache.solr.updat= e.PeerSync; no frame of reference to tell of we've missed updates [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.444; org.apache.solr.cloud= .RecoveryStrategy; PeerSync Recovery was not successful - trying replicatio= n. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.444; org.apache.solr.cloud= .RecoveryStrategy; Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.444; org.apache.solr.cloud= .RecoveryStrategy; Begin buffering updates. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.445; org.apache.solr.updat= e.UpdateLog; Starting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog= =3Dnull} [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.445; org.apache.solr.cloud= .RecoveryStrategy; Attempting to replicate from http://127.0.0.1:11449/coll= ection1/. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.445; 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-13 18:46:24.450; 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-13 18:46:24.455; 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-13 18:46:24.460; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty1/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@ac90383; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0)= ,segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.460; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.495; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty1/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@ac90383; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0)= ,segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty1/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@ac90383; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0)= ,segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.495; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 2[segments_2] [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.496; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@223cc532 realtime [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.497; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.497; 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 42 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.498; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.498; org.apache.solr.handl= er.SnapPuller; No value set for 'pollInterval'. Timer Task not started. [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.500; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.500; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{command=3Di= ndexversion&qt=3D/replication&wt=3Djavabin&version=3D2} status=3D0 QTime=3D= 1=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.501; org.apache.solr.handl= er.SnapPuller; Master's generation: 2 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.501; org.apache.solr.handl= er.SnapPuller; Slave's generation: 1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.501; org.apache.solr.handl= er.SnapPuller; Starting replication process [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.504; 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-13 18:46:24.504; org.apache.solr.handl= er.SnapPuller; Number of files in latest index in master: 1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.505; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty3/index.20= 130414044624505 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.506; org.apache.solr.handl= er.SnapPuller; Starting download to NRTCachingDirectory(org.apache.lucene.s= tore.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Nig= htlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonke= yShardSplitTest-1365878763920/jetty3/index.20130414044624505 lockFactory=3D= org.apache.lucene.store.NativeFSLockFactory@2fd3aa96; maxCacheMB=3D48.0 max= MergeSizeMB=3D4.0) fullCopy=3Dfalse [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.510; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{file=3Dsegm= ents_2&command=3Dfilecontent&checksum=3Dtrue&wt=3Dfilestream&qt=3D/replicat= ion&generation=3D2} status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.511; org.apache.solr.handl= er.SnapPuller; Total time taken for download : 0 secs [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.513; org.apache.solr.updat= e.DefaultSolrCoreState; Creating new IndexWriter... [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.514; org.apache.solr.updat= e.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=3Dcolle= ction1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.517; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty3/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@71413b85; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty3/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@71413b85; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.518; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 2[segments_2] [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.519; org.apache.solr.updat= e.DefaultSolrCoreState; New IndexWriter is ready to be used. [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.519; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@309ee064 main [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.520; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@309ee064 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.521; org.apache.solr.core.= CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/wor= kspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apache= .solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty3/index.2013041404= 4624505 [CachedDir<>] [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.521; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/w= orkspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apac= he.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty3/index.20130414= 044624505 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.521; org.apache.solr.core.= CachingDirectoryFactory; Removing directory before core close: /usr/home/hu= dson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-co= re/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/je= tty3/index.20130414044624505 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.522; org.apache.solr.cloud= .RecoveryStrategy; No replay needed. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.522; org.apache.solr.cloud= .RecoveryStrategy; Replication Recovery was successful - registering as Act= ive. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.523; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.523; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.524; org.apache.solr.cloud= .RecoveryStrategy; Finished recovery process. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.626; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.627; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"127.0.0.1:11466__collection1", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard2", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"recovering", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:11466_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11466"} [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.655; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"127.0.0.1:11462__collection1", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:11462_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11462"} [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.667; 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-13 18:46:24.667; 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-13 18:46:24.667; 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-13 18:46:24.667; 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-13 18:46:24.667; 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-13 18:46:24.667; 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-13 18:46:24.736; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.743; org.apache.solr.handl= er.admin.CoreAdminHandler; Waited coreNodeName: 127.0.0.1:11466__collection= 1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds. [junit4:junit4] 1> INFO - 2013-04-13 18:46:24.743; org.apache.solr.servl= et.SolrDispatchFilter; [admin] webapp=3Dnull path=3D/admin/cores params=3D{= coreNodeName=3D127.0.0.1:11466__collection1&state=3Drecovering&nodeName=3D1= 27.0.0.1:11466_&action=3DPREPRECOVERY&checkLive=3Dtrue&core=3Dcollection1&w= t=3Djavabin&onlyIfLeader=3Dtrue&version=3D2} status=3D0 QTime=3D1002=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:25.738; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.740; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.745; org.apache.solr.cloud= .RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:11458/colle= ction1/ core=3Dcollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.745; org.apache.solr.updat= e.PeerSync; PeerSync: core=3Dcollection1 url=3Dhttp://127.0.0.1:11466 START= replicas=3D[http://127.0.0.1:11458/collection1/] nUpdates=3D100 [junit4:junit4] 1> WARN - 2013-04-13 18:46:26.745; org.apache.solr.updat= e.PeerSync; no frame of reference to tell of we've missed updates [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.746; org.apache.solr.cloud= .RecoveryStrategy; PeerSync Recovery was not successful - trying replicatio= n. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.746; org.apache.solr.cloud= .RecoveryStrategy; Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.746; org.apache.solr.cloud= .RecoveryStrategy; Begin buffering updates. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.746; org.apache.solr.updat= e.UpdateLog; Starting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog= =3Dnull} [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.747; org.apache.solr.cloud= .RecoveryStrategy; Attempting to replicate from http://127.0.0.1:11458/coll= ection1/. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.747; 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-13 18:46:26.756; 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=3D1=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.761; 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-13 18:46:26.765; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty2/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@2856c9b2; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.766; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.770; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty2/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@2856c9b2; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty2/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@2856c9b2; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.770; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 2[segments_2] [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.771; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@1215f4de realtime [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.772; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.772; 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 11 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.773; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.773; org.apache.solr.handl= er.SnapPuller; No value set for 'pollInterval'. Timer Task not started. [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.774; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.775; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{command=3Di= ndexversion&qt=3D/replication&wt=3Djavabin&version=3D2} status=3D0 QTime=3D= 1=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.775; org.apache.solr.handl= er.SnapPuller; Master's generation: 2 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.775; org.apache.solr.handl= er.SnapPuller; Slave's generation: 1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.776; org.apache.solr.handl= er.SnapPuller; Starting replication process [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.778; 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=3D0=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.779; org.apache.solr.handl= er.SnapPuller; Number of files in latest index in master: 1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.780; org.apache.solr.core.= CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-s= lave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/or= g.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty4/index.20= 130414044626779 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.781; org.apache.solr.handl= er.SnapPuller; Starting download to NRTCachingDirectory(org.apache.lucene.s= tore.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Nig= htlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonke= yShardSplitTest-1365878763920/jetty4/index.20130414044626779 lockFactory=3D= org.apache.lucene.store.NativeFSLockFactory@6241df7a; maxCacheMB=3D48.0 max= MergeSizeMB=3D4.0) fullCopy=3Dfalse [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.784; org.apache.solr.core.= SolrCore; [collection1] webapp=3D path=3D/replication params=3D{file=3Dsegm= ents_2&command=3Dfilecontent&checksum=3Dtrue&wt=3Dfilestream&qt=3D/replicat= ion&generation=3D2} status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.785; org.apache.solr.handl= er.SnapPuller; Total time taken for download : 0 secs [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.787; org.apache.solr.updat= e.DefaultSolrCoreState; Creating new IndexWriter... [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.787; org.apache.solr.updat= e.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=3Dcolle= ction1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.791; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty4/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@2abc73c9; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty4/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@2abc73c9; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.792; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 2[segments_2] [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.792; org.apache.solr.updat= e.DefaultSolrCoreState; New IndexWriter is ready to be used. [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.793; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@5ee6dac2 main [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.794; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@5ee6dac2 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.794; org.apache.solr.core.= CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/wor= kspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apache= .solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty4/index.2013041404= 4626779 [CachedDir<>] [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.795; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/w= orkspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apac= he.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty4/index.20130414= 044626779 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.795; org.apache.solr.core.= CachingDirectoryFactory; Removing directory before core close: /usr/home/hu= dson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-co= re/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/je= tty4/index.20130414044626779 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.796; org.apache.solr.cloud= .RecoveryStrategy; No replay needed. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.796; org.apache.solr.cloud= .RecoveryStrategy; Replication Recovery was successful - registering as Act= ive. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.796; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.796; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-13 18:46:26.798; org.apache.solr.cloud= .RecoveryStrategy; Finished recovery process. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.683; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.684; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"127.0.0.1:11466__collection1", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard2", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:11466_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11466"} [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.697; 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-13 18:46:27.697; 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-13 18:46:27.697; 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-13 18:46:27.697; 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-13 18:46:27.697; 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-13 18:46:27.697; 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-13 18:46:27.742; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.743; org.apache.solr.cloud= .AbstractDistribZkTestBase; Recoveries finished - collection: collection1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.752; 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-13 18:46:27.757; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/control/data/index lockFactory=3Dorg.apache.= lucene.store.NativeFSLockFactory@62b1fb50; maxCacheMB=3D48.0 maxMergeSizeMB= =3D4.0),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.758; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.762; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/control/data/index lockFactory=3Dorg.apache.= lucene.store.NativeFSLockFactory@62b1fb50; maxCacheMB=3D48.0 maxMergeSizeMB= =3D4.0),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/control/data/index lockFactory=3Dorg.apache.= lucene.store.NativeFSLockFactory@62b1fb50; maxCacheMB=3D48.0 maxMergeSizeMB= =3D4.0),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.762; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 2[segments_2] [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.764; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@4b32470e main [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.765; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.765; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@4b32470e main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.766; 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 14 [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.775; 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-13 18:46:27.788; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty1/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@ac90383; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0)= ,segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty1/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@ac90383; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0)= ,segFN=3Dsegments_3,generation=3D3,filenames=3D[segments_3] [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.788; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 3[segments_3] [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.789; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@3cf774bc main [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.790; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.790; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@3cf774bc main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.791; org.apache.solr.updat= e.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:11462/co= llection1/, StdNode: http://127.0.0.1:11458/collection1/, StdNode: http://1= 27.0.0.1:11466/collection1/] params:commit_end_point=3Dtrue&commit=3Dtrue&s= oftCommit=3Dfalse&waitSearcher=3Dtrue&expungeDeletes=3Dfalse [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.795; 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-13 18:46:27.805; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty2/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@2856c9b2; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty2/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@2856c9b2; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_3,generation=3D3,filenames=3D[segments_3] [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.806; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 3[segments_3] [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.807; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@492b4605 main [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.807; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.808; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@492b4605 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.808; 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-13 18:46:27.808; 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 14 [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.808; 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-13 18:46:27.822; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty3/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@71413b85; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty3/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@71413b85; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_3,generation=3D3,filenames=3D[segments_3] [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.823; 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-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty4/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@2abc73c9; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> =09commit{dir=3DNRTCachingDirectory(org.apache.lucene.= store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Ni= ghtlyTests-4.x/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365878763920/jetty4/index lockFactory=3Dorg.apache.lucene= .store.NativeFSLockFactory@2abc73c9; maxCacheMB=3D48.0 maxMergeSizeMB=3D4.0= ),segFN=3Dsegments_3,generation=3D3,filenames=3D[segments_3] [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.823; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 3[segments_3] [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.823; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 3[segments_3] [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.825; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@1167eb80 main [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.825; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@4d79d2b1 main [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.826; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.826; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@1167eb80 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.827; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@4d79d2b1 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.827; 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 19 [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.826; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.828; 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 20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.828; 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 53 [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.829; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:27.831; 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-13 18:46:27.833; 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-13 18:46:27.834; 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-13 18:46:27.836; 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-13 18:46:29.837; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-13 18:46:29.840; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@3dbdabce name:ZooKeeperConnection Watcher:127.0.0.1:29280 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-13 18:46:29.840; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> / (2) [junit4:junit4] 1> DATA: [junit4:junit4] 1> =20 [junit4:junit4] 1> /solr (7) [junit4:junit4] 1> /solr/configs (1) [junit4:junit4] 1> /solr/configs/conf1 (9) [junit4:junit4] 1> /solr/configs/conf1/mapping-ISOLatin1Accent.txt (0= ) [junit4:junit4] 1> DATA: ...supressed... [junit4:junit4] 1> /solr/configs/conf1/currency.xml (0) [junit4:junit4] 1> DATA: ...supressed... [junit4:junit4] 1> /solr/configs/conf1/protwords.txt (0) [junit4:junit4] 1> DATA: ...supressed... [junit4:junit4] 1> /solr/configs/conf1/synonyms.txt (0) [junit4:junit4] 1> DATA: ...supressed... [junit4:junit4] 1> /solr/configs/conf1/old_synonyms.txt (0) [junit4:junit4] 1> DATA: ...supressed... [junit4:junit4] 1> /solr/configs/conf1/solrconfig.xml (0) [junit4:junit4] 1> DATA: ...supressed... [junit4:junit4] 1> /solr/configs/conf1/stopwords.txt (0) [junit4:junit4] 1> DATA: ...supressed... [junit4:junit4] 1> /solr/configs/conf1/open-exchange-rates.json (0) [junit4:junit4] 1> DATA: [junit4:junit4] 1> { [junit4:junit4] 1> "disclaimer": "This data is not real, it was= synthetically created to match currency.xml. It is modeled after the data= format available from openexchangerates.org. See https://openexchangerate= s.org/documentation for details", [junit4:junit4] 1> "license": "http://www.apache.org/licenses/L= ICENSE-2.0", [junit4:junit4] 1> "timestamp": 1332070464, [junit4:junit4] 1> =20 [junit4:junit4] 1> =20 [junit4:junit4] 1> "IMPORTANT NOTE": "In order for tests to wor= k, this data must be kept in sync with ./currency.xml", [junit4:junit4] 1> =20 [junit4:junit4] 1> =20 [junit4:junit4] 1> "base": "USD", [junit4:junit4] 1> "rates": { [junit4:junit4] 1> "USD": 1, [junit4:junit4] 1> "JPY": 81.29, [junit4:junit4] 1> "EUR": 2.5, [junit4:junit4] 1> "GBP": 0.5, [junit4:junit4] 1> "MXN": 2.0 [junit4:junit4] 1> } [junit4:junit4] 1> } [junit4:junit4] 1> =20 [junit4:junit4] 1> /solr/configs/conf1/schema.xml (0) [junit4:junit4] 1> DATA: ...supressed... [junit4:junit4] 1> /solr/clusterstate.json (0) [junit4:junit4] 1> DATA: [junit4:junit4] 1> { [junit4:junit4] 1> "collection1":{ [junit4:junit4] 1> "shards":{ [junit4:junit4] 1> "shard1":{ [junit4:junit4] 1> "range":"80000000-ffffffff", [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "replicas":{ [junit4:junit4] 1> "127.0.0.1:11449__collection1":{ [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "node_name":"127.0.0.1:11449_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11449", [junit4:junit4] 1> "leader":"true"}, [junit4:junit4] 1> "127.0.0.1:11462__collection1":{ [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "node_name":"127.0.0.1:11462_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11462"}= }}, [junit4:junit4] 1> "shard2":{ [junit4:junit4] 1> "range":"0-7fffffff", [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "replicas":{ [junit4:junit4] 1> "127.0.0.1:11458__collection1":{ [junit4:junit4] 1> "shard":"shard2", [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "node_name":"127.0.0.1:11458_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11458", [junit4:junit4] 1> "leader":"true"}, [junit4:junit4] 1> "127.0.0.1:11466__collection1":{ [junit4:junit4] 1> "shard":"shard2", [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "node_name":"127.0.0.1:11466_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11466"}= }}}, [junit4:junit4] 1> "router":"compositeId"}, [junit4:junit4] 1> "control_collection":{ [junit4:junit4] 1> "shards":{"shard1":{ [junit4:junit4] 1> "range":"80000000-7fffffff", [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "replicas":{"127.0.0.1:16351__collection= 1":{ [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"control_collection", [junit4:junit4] 1> "node_name":"127.0.0.1:16351_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:16351", [junit4:junit4] 1> "leader":"true"}}}}, [junit4:junit4] 1> "router":"compositeId"}} [junit4:junit4] 1> /solr/aliases.json (0) [junit4:junit4] 1> /solr/live_nodes (5) [junit4:junit4] 1> /solr/live_nodes/127.0.0.1:11466_ (0) [junit4:junit4] 1> /solr/live_nodes/127.0.0.1:11458_ (0) [junit4:junit4] 1> /solr/live_nodes/127.0.0.1:16351_ (0) [junit4:junit4] 1> /solr/live_nodes/127.0.0.1:11462_ (0) [junit4:junit4] 1> /solr/live_nodes/127.0.0.1:11449_ (0) [junit4:junit4] 1> /solr/overseer (3) [junit4:junit4] 1> DATA: [junit4:junit4] 1> =20 [junit4:junit4] 1> /solr/overseer/queue (0) [junit4:junit4] 1> /solr/overseer/queue-work (0) [junit4:junit4] 1> /solr/overseer/collection-queue-work (0) [junit4:junit4] 1> /solr/collections (2) [junit4:junit4] 1> /solr/collections/collection1 (3) [junit4:junit4] 1> DATA: [junit4:junit4] 1> {"configName":"conf1"} [junit4:junit4] 1> /solr/collections/collection1/shards (0) [junit4:junit4] 1> /solr/collections/collection1/leader_elect (2) [junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1= (1) [junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard= 1/election (2) [junit4:junit4] 1> /solr/collections/collection1/leader_elect/shar= d1/election/89514230672588806-127.0.0.1:11449__collection1-n_0000000000 (0) [junit4:junit4] 1> /solr/collections/collection1/leader_elect/shar= d1/election/89514230672588810-127.0.0.1:11462__collection1-n_0000000001 (0) [junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard2= (1) [junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard= 2/election (2) [junit4:junit4] 1> /solr/collections/collection1/leader_elect/shar= d2/election/89514230672588808-127.0.0.1:11458__collection1-n_0000000000 (0) [junit4:junit4] 1> /solr/collections/collection1/leader_elect/shar= d2/election/89514230672588812-127.0.0.1:11466__collection1-n_0000000001 (0) [junit4:junit4] 1> /solr/collections/collection1/leaders (2) [junit4:junit4] 1> /solr/collections/collection1/leaders/shard1 (0) [junit4:junit4] 1> DATA: [junit4:junit4] 1> { [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "node_name":"127.0.0.1:11449_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11449"} [junit4:junit4] 1> /solr/collections/collection1/leaders/shard2 (0) [junit4:junit4] 1> DATA: [junit4:junit4] 1> { [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "node_name":"127.0.0.1:11458_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:11458"} [junit4:junit4] 1> /solr/collections/control_collection (3) [junit4:junit4] 1> DATA: [junit4:junit4] 1> {"configName":"conf1"} [junit4:junit4] 1> /solr/collections/control_collection/shards (0) [junit4:junit4] 1> /solr/collections/control_collection/leader_elect = (1) [junit4:junit4] 1> /solr/collections/control_collection/leader_elect= /shard1 (1) [junit4:junit4] 1> /solr/collections/control_collection/leader_elec= t/shard1/election (1) [junit4:junit4] 1> /solr/collections/control_collection/leader_ele= ct/shard1/election/89514230672588803-127.0.0.1:16351__collection1-n_0000000= 000 (0) [junit4:junit4] 1> /solr/collections/control_collection/leaders (1) [junit4:junit4] 1> /solr/collections/control_collection/leaders/shar= d1 (0) [junit4:junit4] 1> DATA: [junit4:junit4] 1> { [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "node_name":"127.0.0.1:16351_", [junit4:junit4] 1> "base_url":"http://127.0.0.1:16351"} [junit4:junit4] 1> /solr/overseer_elect (2) [junit4:junit4] 1> /solr/overseer_elect/election (5) [junit4:junit4] 1> /solr/overseer_elect/election/89514230672588810-12= 7.0.0.1:11462_-n_0000000003 (0) [junit4:junit4] 1> /solr/overseer_elect/election/89514230672588803-12= 7.0.0.1:16351_-n_0000000000 (0) [junit4:junit4] 1> /solr/overseer_elect/election/89514230672588806-12= 7.0.0.1:11449_-n_0000000001 (0) [junit4:junit4] 1> /solr/overseer_elect/election/89514230672588812-12= 7.0.0.1:11466_-n_0000000004 (0) [junit4:junit4] 1> /solr/overseer_elect/election/89514230672588808-12= 7.0.0.1:11458_-n_0000000002 (0) [junit4:junit4] 1> /solr/overseer_elect/leader (0) [junit4:junit4] 1> DATA: [junit4:junit4] 1> {"id":"89514230672588803-127.0.0.1:16351_-n_000= 0000000"} [junit4:junit4] 1> /zookeeper (1) [junit4:junit4] 1> DATA: [junit4:junit4] 1> =20 [junit4:junit4] 1>=20 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.004; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{update.distrib=3DFROMLEADER&_version_=3D-1432227718101991424&update.f= rom=3Dhttp://127.0.0.1:11449/collection1/&wt=3Djavabin&version=3D2} {delete= ByQuery=3D*:* (-1432227718101991424)} 0 1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.008; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{update.distrib=3DFROMLEADER&_version_=3D-1432227718106185728&update.f= rom=3Dhttp://127.0.0.1:11458/collection1/&wt=3Djavabin&version=3D2} {delete= ByQuery=3D*:* (-1432227718106185728)} 0 1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.009; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{update.distrib=3DTOLEADER&wt=3Djavabin&version=3D2} {deleteByQuery=3D= *:* (-1432227718106185728)} 0 6 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.009; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {deleteByQuery=3D*:* (-1432227718101991424)= } 0 10 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.014; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[0 (1432227718115622912)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.021; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11449/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[0 (1432227718120865792)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.022; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[0 (1432227718120865792)]} 0 5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.024; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[1 (1432227718128205824)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.029; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11449/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[1 (1432227718131351552)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.030; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[1 (1432227718131351552)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.032; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[2 (1432227718136594432)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.038; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11458/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[2 (1432227718138691584)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.039; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[2 (1432227718138691584)]} 0 6 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.041; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[3 (1432227718146031616)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.048; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11458/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[3 (1432227718151274496)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.049; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11449/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[3 (1432227718151274496)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.049; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[3]} 0 5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.052; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[4 (1432227718157565952)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.057; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11449/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[4 (1432227718160711680)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.058; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[4 (1432227718160711680)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.060; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[5 (1432227718165954560)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.065; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11458/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[5 (1432227718169100288)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.066; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[5 (1432227718169100288)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.068; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[6 (1432227718174343168)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.075; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11458/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[6 (1432227718179586048)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.076; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11449/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[6 (1432227718179586048)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.076; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[6]} 0 5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.079; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[7 (1432227718185877504)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.084; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11458/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[7 (1432227718189023232)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.085; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[7 (1432227718189023232)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.087; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[8 (1432227718194266112)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.093; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11449/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[8 (1432227718198460416)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.094; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11458/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[8 (1432227718198460416)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.094; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[8]} 0 4 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.097; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[9 (1432227718204751872)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.102; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11458/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[9 (1432227718207897600)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.103; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[9 (1432227718207897600)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.105; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[10 (1432227718213140480)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.112; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11449/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[10 (1432227718218383360)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.113; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11458/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[10 (1432227718218383360)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.113; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[10]} 0 5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.116; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[11 (1432227718224674816)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.123; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11449/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[11 (1432227718229917696)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.124; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11458/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[11 (1432227718229917696)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.124; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[11]} 0 5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.127; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[12 (1432227718236209152)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.134; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11449/collection1/&update.distrib=3DF= ROMLEADER&wt=3Djavabin&version=3D2} {add=3D[12 (1432227718241452032)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.135; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{distrib.from=3Dhttp://127.0.0.1:11458/collection1/&update.distrib=3DT= OLEADER&wt=3Djavabin&version=3D2} {add=3D[12 (1432227718241452032)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.135; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt=3Djavabin&version=3D2} {add=3D[12]} 0 5 [junit4:junit4] 1> INFO - 2013-04-13 18:46:30.138; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D path=3D/update para= ms=3D{wt [...truncated too long message...] ; Closing NRTCachingDirectoryFactory - 2 directories currently being tracke= d [junit4:junit4] 1> INFO - 2013-04-13 18:48:03.024; org.apache.solr.core.= CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/wor= kspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apache= .solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty4 [CachedDir<>] [junit4:junit4] 1> INFO - 2013-04-13 18:48:03.024; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/w= orkspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apac= he.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty4 [junit4:junit4] 1> INFO - 2013-04-13 18:48:03.025; org.apache.solr.core.= CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/wor= kspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apache= .solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty4/index [CachedDir= <>] [junit4:junit4] 1> INFO - 2013-04-13 18:48:03.025; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/w= orkspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/org.apac= he.solr.cloud.ChaosMonkeyShardSplitTest-1365878763920/jetty4/index [junit4:junit4] 1> INFO - 2013-04-13 18:48:03.026; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; According to ZK I (id=3D89514230672588812-12= 7.0.0.1:11466_-n_0000000004) am no longer a leader. [junit4:junit4] 1> INFO - 2013-04-13 18:48:03.027; 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-13 18:48:03.027; org.apache.solr.commo= n.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to= ZK [junit4:junit4] 1> INFO - 2013-04-13 18:48:03.027; org.eclipse.jetty.ser= ver.handler.ContextHandler; stopped o.e.j.s.ServletContextHandler{/,null} [junit4:junit4] 1> WARN - 2013-04-13 18:48:03.027; org.apache.solr.commo= n.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to= ZK [junit4:junit4] 1> INFO - 2013-04-13 18:48:03.144; org.apache.solr.SolrT= estCaseJ4; ###Ending testDistribSearch [junit4:junit4] 1> INFO - 2013-04-13 18:48:03.148; org.apache.solr.cloud= .ZkTestServer; connecting to 127.0.0.1:29280 29280 [junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/worksp= ace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solrtest-Ch= aosMonkeyShardSplitTest-1365878763920 [junit4:junit4] 2> check const of shard1 [junit4:junit4] 2> client0 [junit4:junit4] 2> PROPS:127.0.0.1:11449__collection1:{"shard":"shard1","= state":"down","core":"collection1","collection":"collection1","node_name":"= 127.0.0.1:11449_","base_url":"http://127.0.0.1:11449"} [junit4:junit4] 2> error contacting client: IOException occured when talk= ing to server at: http://127.0.0.1:11449/collection1 [junit4:junit4] 2>=20 [junit4:junit4] 2> client1 [junit4:junit4] 2> PROPS:127.0.0.1:11462__collection1:{"shard":"shard1","= state":"active","core":"collection1","collection":"collection1","node_name"= :"127.0.0.1:11462_","base_url":"http://127.0.0.1:11462"} [junit4:junit4] 2> live:true [junit4:junit4] 2> num:56 [junit4:junit4] 2>=20 [junit4:junit4] 2> check const of shard2 [junit4:junit4] 2> client0 [junit4:junit4] 2> PROPS:127.0.0.1:11458__collection1:{"shard":"shard2","= state":"active","core":"collection1","collection":"collection1","node_name"= :"127.0.0.1:11458_","base_url":"http://127.0.0.1:11458","leader":"true"} [junit4:junit4] 2> live:true [junit4:junit4] 2> num:44 [junit4:junit4] 2>=20 [junit4:junit4] 2> client1 [junit4:junit4] 2> PROPS:127.0.0.1:11466__collection1:{"shard":"shard2","= state":"active","core":"collection1","collection":"collection1","node_name"= :"127.0.0.1:11466_","base_url":"http://127.0.0.1:11466"} [junit4:junit4] 2> live:true [junit4:junit4] 2> num:44 [junit4:junit4] 2>=20 [junit4:junit4] 2> NOTE: download the large Jenkins line-docs file by run= ning 'ant get-jenkins-line-docs' in the lucene directory. [junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=3DChaosMonk= eyShardSplitTest -Dtests.method=3DtestDistribSearch -Dtests.seed=3DA785E86F= 181BE2F6 -Dtests.multiplier=3D2 -Dtests.nightly=3Dtrue -Dtests.slow=3Dtrue = -Dtests.linedocsfile=3D/home/hudson/lucene-data/enwiki.random.lines.txt -Dt= ests.locale=3Dhr -Dtests.timezone=3DAustralia/Lindeman -Dtests.file.encodin= g=3DUS-ASCII [junit4:junit4] FAILURE 119s J1 | ChaosMonkeyShardSplitTest.testDistribSea= rch <<< [junit4:junit4] > Throwable #1: java.lang.AssertionError: Wrong doc coun= t on shard1_1 expected:<49> but was:<50> [junit4:junit4] > =09at __randomizedtesting.SeedInfo.seed([A785E86F181BE= 2F6:266366776F4482CA]:0) [junit4:junit4] > =09at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.= doTest(ChaosMonkeyShardSplitTest.java:274) [junit4:junit4] > =09at org.apache.solr.BaseDistributedSearchTestCase.te= stDistribSearch(BaseDistributedSearchTestCase.java:806) [junit4:junit4] > =09at java.lang.Thread.run(Thread.java:679) [junit4:junit4] 1> INFO - 2013-04-13 18:48:03.323; org.apache.solr.SolrT= estCaseJ4; ###deleteCore [junit4:junit4] 2> 119411 T4424 ccr.ThreadLeakControl.checkThreadLeaks WA= RNING Will linger awaiting termination of 1 leaked thread(s). [junit4:junit4] 2> NOTE: test params are: codec=3DAppending, sim=3DRandom= SimilarityProvider(queryNorm=3Dfalse,coord=3Dyes): {}, locale=3Dhr, timezon= e=3DAustralia/Lindeman [junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. = 1.6.0_32 (64-bit)/cpus=3D16,threads=3D2,free=3D230626192,total=3D407175168 [junit4:junit4] 2> NOTE: All tests run in this JVM: [ChaosMonkeySafeLeade= rTest, HighlighterTest, TestUpdate, DocumentAnalysisRequestHandlerTest, Tes= tIndexSearcher, SpellCheckComponentTest, ZkNodePropsTest, CachingDirectoryF= actoryTest, TestRangeQuery, TestCollationField, PreAnalyzedUpdateProcessorT= est, ZkSolrClientTest, SolrPluginUtilsTest, URLClassifyProcessorTest, TestS= olrQueryParserResource, HighlighterConfigTest, SignatureUpdateProcessorFact= oryTest, StatsComponentTest, BasicZkTest, TestAtomicUpdateErrorCases, TestB= inaryResponseWriter, RequestHandlersTest, TestDynamicFieldCollectionResourc= e, UpdateParamsTest, SortByFunctionTest, TestFieldTypeResource, BasicDistri= butedZk2Test, TestSchemaNameResource, TestBinaryField, FileUtilsTest, TestS= hardHandlerFactory, JSONWriterTest, TestJmxMonitoredMap, TestJmxIntegration= , LeaderElectionIntegrationTest, SolrRequestParserTest, TermVectorComponent= DistributedTest, DebugComponentTest, CopyFieldTest, TestDefaultSimilarityFa= ctory, TestCSVResponseWriter, FieldAnalysisRequestHandlerTest, TestDFRSimil= arityFactory, SpellCheckCollatorTest, TestQuerySenderNoQuery, TestElisionMu= ltitermQuery, TestUtils, SimplePostToolTest, XsltUpdateRequestHandlerTest, = TestOmitPositions, TestDefaultSearchFieldResource, DocValuesMultiTest, Test= MultiCoreConfBootstrap, PingRequestHandlerTest, DateMathParserTest, Suggest= erWFSTTest, TestCodecSupport, TestSuggestSpellingConverter, TestFastOutputS= tream, TestSolrQueryParserDefaultOperatorResource, TestSolrJ, CurrencyField= OpenExchangeTest, OpenExchangeRatesOrgProviderTest, TestAnalyzedSuggestions= , NotRequiredUniqueKeyTest, TestComponentsName, TestReload, UnloadDistribut= edZkTest, SyncSliceTest, OverseerTest, ShardRoutingTest, TestReplicationHan= dler, SolrCmdDistributorTest, PeerSyncTest, ConvertedLegacyTest, BasicFunct= ionalityTest, TestLazyCores, OverseerCollectionProcessorTest, CurrencyField= XmlFileTest, TestCoreDiscovery, AnalysisAfterCoreReloadTest, TestFoldingMul= titermQuery, SuggesterTSTTest, TestTrie, TestCSVLoader, SchemaVersionSpecif= icBehaviorTest, SolrCoreCheckLockOnStartupTest, TestWordDelimiterFilterFact= ory, DefaultValueUpdateProcessorTest, SolrInfoMBeanTest, IndexBasedSpellChe= ckerTest, DirectSolrSpellCheckerTest, FileBasedSpellCheckerTest, TestValueS= ourceCache, TestIndexingPerformance, TestSolrQueryParser, IndexSchemaRuntim= eFieldTest, QueryParsingTest, UniqFieldsUpdateProcessorFactoryTest, TestPar= tialUpdateDeduplication, CoreContainerCoreInitFailuresTest, TestQuerySender= Listener, AlternateDirectoryTest, TestStressRecovery, ChaosMonkeyShardSplit= Test] [junit4:junit4] Completed on J1 in 120.18s, 1 test, 1 failure <<< FAILURES! [...truncated 10 lines...] BUILD FAILED /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.= xml:388: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.= xml:361: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.= xml:39: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/b= uild.xml:183: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/c= ommon-build.xml:438: The following error occurred while executing this line= : /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene= /common-build.xml:1234: The following error occurred while executing this l= ine: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene= /common-build.xml:878: There were test failures: 290 suites, 1203 tests, 1 = failure, 25 ignored (6 assumptions) Total time: 104 minutes 0 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_2255_112164329.1365878908528 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_2255_112164329.1365878908528--