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 601FD1081D for ; Mon, 15 Apr 2013 03:54:05 +0000 (UTC) Received: (qmail 60899 invoked by uid 500); 15 Apr 2013 03:54:03 -0000 Delivered-To: apmail-lucene-dev-archive@lucene.apache.org Received: (qmail 60642 invoked by uid 500); 15 Apr 2013 03:54:03 -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 60578 invoked by uid 99); 15 Apr 2013 03:54:01 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 15 Apr 2013 03:54:01 +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; Mon, 15 Apr 2013 03:53:52 +0000 Received: from aegis.apache.org (localhost [127.0.0.1]) by aegis.apache.org (Postfix) with ESMTP id 9DCB7C0071 for ; Mon, 15 Apr 2013 03:53:31 +0000 (UTC) Date: Mon, 15 Apr 2013 03:53:15 +0000 (UTC) From: Apache Jenkins Server To: dev@lucene.apache.org Message-ID: <65832481.2484.1365998011644.JavaMail.hudson@aegis> In-Reply-To: <81408885.2444.1365976019938.JavaMail.hudson@aegis> References: <81408885.2444.1365976019938.JavaMail.hudson@aegis> Subject: [JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1511 - Still Failing MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----=_Part_2483_1324406348.1365997995126" X-Jenkins-Job: Lucene-Solr-Tests-4.x-Java6 X-Jenkins-Result: FAILURE X-Virus-Checked: Checked by ClamAV on apache.org ------=_Part_2483_1324406348.1365997995126 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1511/ 1 tests failed. FAILED: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch Error Message: Wrong doc count on shard1_1 expected:<322> but was:<323> Stack Trace: java.lang.AssertionError: Wrong doc count on shard1_1 expected:<322> but wa= s:<323> =09at __randomizedtesting.SeedInfo.seed([32D28CFFA5436A68:B33402E7D21C0A54]= :0) =09at org.junit.Assert.fail(Assert.java:93) =09at org.junit.Assert.failNotEquals(Assert.java:647) =09at org.junit.Assert.assertEquals(Assert.java:128) =09at org.junit.Assert.assertEquals(Assert.java:472) =09at org.apache.solr.cloud.ShardSplitTest.checkDocCountsAndShardStates(Sha= rdSplitTest.java:155) =09at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeySha= rdSplitTest.java:154) =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 9174 lines...] [junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.072; org.apache.solr.BaseD= istributedSearchTestCase; Setting hostContext system property: /jj/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.075; org.apache.solr.SolrT= estCaseJ4; ###Starting testDistribSearch [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.076; 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-15 03:45:26.077; org.apache.solr.cloud= .ZkTestServer$ZKServerMain; Starting server [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.178; org.apache.solr.cloud= .ZkTestServer; start zk server on port:18952 [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.179; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.182; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@71636e40 name:ZooKeeperConnection Watcher:127.0.0.1:18952 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.182; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.183; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /solr [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.197; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.221; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@149329ac name:ZooKeeperConnection Watcher:127.0.0.1:18952/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.221; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.221; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.242; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/shards [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.245; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.257; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/shards [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.260; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/sol= rconfig-tlog.xml to /configs/conf1/solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.261; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.323; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/sch= ema.xml to /configs/conf1/schema.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.324; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.428; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/sto= pwords.txt to /configs/conf1/stopwords.txt [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.429; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.446; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/pro= twords.txt to /configs/conf1/protwords.txt [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.447; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.450; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/cur= rency.xml to /configs/conf1/currency.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.450; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.458; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/ope= n-exchange-rates.json to /configs/conf1/open-exchange-rates.json [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.459; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.467; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/map= ping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.469; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.494; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old= _synonyms.txt to /configs/conf1/old_synonyms.txt [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.495; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.499; org.apache.solr.cloud= .AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/syn= onyms.txt to /configs/conf1/synonyms.txt [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.499; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.745; org.eclipse.jetty.ser= ver.Server; jetty-8.1.8.v20121106 [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.753; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:18955 [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.754; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.755; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.755; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/tes= t/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1365997= 526526 [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.756; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test= /J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-13659975= 26526/solr.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.765; org.apache.solr.core.= CoreContainer; New CoreContainer 100689678 [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.766; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J= 1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1365997526= 526/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.766; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-136599= 7526526/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.832; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.832; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.833; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.833; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.834; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.834; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.835; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.835; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.836; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.836; 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-15 03:45:26.856; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.875; org.apache.solr.core.= CoreContainer; Zookeeper client=3D127.0.0.1:18952/solr [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.876; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.877; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.888; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@4438487f name:ZooKeeperConnection Watcher:127.0.0.1:18952 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.888; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.891; 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-15 03:45:26.901; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.905; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@2fb28819 name:ZooKeeperConnection Watcher:127.0.0.1:18952/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.905; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.914; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/queue [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.925; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/collection-queue-work [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.935; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.937; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:189= 55_jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.939; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:18955_jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:26.983; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer_elect/election [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.080; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer_elect/leader [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.084; org.apache.solr.cloud= .Overseer; Overseer (id=3D89522013869309955-127.0.0.1:18955_jj-n_0000000000= ) starting [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.114; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /overseer/queue-work [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.151; org.apache.solr.cloud= .OverseerCollectionProcessor; Process current queue of collection creations [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.152; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /clusterstate.json [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.201; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /aliases.json [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.203; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.205; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Starting to work on the main queue [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.207; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-= core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty= -1365997526526/collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.208; org.apache.solr.cloud= .ZkController; Check for collection zkNode:control_collection [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.208; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.209; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/control_collection [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.210; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-136599= 7526526/collection1/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.211; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.clou= d.ChaosMonkeyShardSplitTest-controljetty-1365997526526/collection1/lib/READ= ME' to classloader [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.212; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.clou= d.ChaosMonkeyShardSplitTest-controljetty-1365997526526/collection1/lib/clas= ses/' to classloader [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.260; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_43 [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.319; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.421; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:27.428; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.041; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.052; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.057; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.076; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.081; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.085; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-15 03:45:28.086; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-15 03:45:28.086; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.087; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-15 03:45:28.088; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-15 03:45:28.088; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.088; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.089; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org= .apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1365997526526/col= lection1/, dataDir=3D./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365= 997526076/control/data/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.089; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@4c29d65b [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.089; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.090; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.C= haosMonkeyShardSplitTest-1365997526076/control/data [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.090; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ChaosMonkeyShardSplitTest-1365997526076/control/data/index/ [junit4:junit4] 1> WARN - 2013-04-15 03:45:28.091; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Chaos= MonkeyShardSplitTest-1365997526076/control/data/index' doesn't exist. Creat= ing new index... [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.091; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.C= haosMonkeyShardSplitTest-1365997526076/control/data/index [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.095; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@51cc7fbc lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@495d56fd),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.095; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.113; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.113; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.114; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.114; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.115; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.115; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.115; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.116; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.116; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.123; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.129; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@18b46bac main [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.130; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Cha= osMonkeyShardSplitTest-1365997526076/control/data/tlog [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.131; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.131; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.134; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@18b46bac main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.136; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.136; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.708; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.709; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"1", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"control_collection", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:18955_jj", [junit4:junit4] 1> "base_url":"http://127.0.0.1:18955/jj"} [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.709; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Create collection control_collection with nu= mShards 1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.710; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:28.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: 1) [junit4:junit4] 1> INFO - 2013-04-15 03:45:29.142; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:29.142; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :18955/jj collection:control_collection shard:shard1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:29.143; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elec= t/shard1/election [junit4:junit4] 1> INFO - 2013-04-15 03:45:29.180; org.apache.solr.cloud= .ShardLeaderElectionContext; Running the leader process. [junit4:junit4] 1> INFO - 2013-04-15 03:45:29.189; org.apache.solr.cloud= .ShardLeaderElectionContext; Enough replicas found to continue. [junit4:junit4] 1> INFO - 2013-04-15 03:45:29.190; org.apache.solr.cloud= .ShardLeaderElectionContext; I may be the new leader - try and sync [junit4:junit4] 1> INFO - 2013-04-15 03:45:29.190; org.apache.solr.cloud= .SyncStrategy; Sync replicas to http://127.0.0.1:18955/jj/collection1/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:29.190; org.apache.solr.cloud= .SyncStrategy; Sync Success - now sync replicas to me [junit4:junit4] 1> INFO - 2013-04-15 03:45:29.190; org.apache.solr.cloud= .SyncStrategy; http://127.0.0.1:18955/jj/collection1/ has no replicas [junit4:junit4] 1> INFO - 2013-04-15 03:45:29.191; org.apache.solr.cloud= .ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:18955/jj= /collection1/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:29.191; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/sha= rd1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.313; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.335; 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-15 03:45:30.382; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:18955/jj/collection1/ and leader is = http://127.0.0.1:18955/jj/collection1/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.382; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:18955/jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.382; org.apache.solr.cloud= .ZkController; I am the leader, no recovery necessary [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.382; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.383; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.384; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.385; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.386; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.386; 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-15 03:45:30.395; org.apache.solr.clien= t.solrj.impl.HttpClientUtil; Creating new http client, config: [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.397; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.399; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@2408e9ff name:ZooKeeperConnection Watcher:127.0.0.1:18952/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.399; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.401; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.403; org.apache.solr.cloud= .ChaosMonkey; monkey: init - expire sessions:true cause connection loss:tru= e [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.536; org.eclipse.jetty.ser= ver.Server; jetty-8.1.8.v20121106 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.538; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:18959 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.539; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.539; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.539; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/tes= t/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365997530403 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.540; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test= /J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365997530403/= solr.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.540; org.apache.solr.core.= CoreContainer; New CoreContainer 388934360 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.540; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J= 1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365997530403/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.541; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-136599753040= 3/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.577; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.578; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.578; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.578; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.579; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.579; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.579; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.580; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.580; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.580; 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-15 03:45:30.594; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.606; org.apache.solr.core.= CoreContainer; Zookeeper client=3D127.0.0.1:18952/solr [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.607; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.608; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.614; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@39406765 name:ZooKeeperConnection Watcher:127.0.0.1:18952 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.614; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.715; 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-15 03:45:30.723; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.725; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@67c19bf2 name:ZooKeeperConnection Watcher:127.0.0.1:18952/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.726; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:30.813; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.816; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:189= 59_jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.819; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:18959_jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.822; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeChildrenChanged path:/live_nodes, has occurred - updating..= . (live nodes size: 1) [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.822; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.822; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.823; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (2) [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.839; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-= core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-13659= 97530403/collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.839; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.840; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.840; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.840; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.841; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D1 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"1", [junit4:junit4] 1> "numShards":"1", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"control_collection", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:18955_jj", [junit4:junit4] 1> "base_url":"http://127.0.0.1:18955/jj"} [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.841; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-136599753040= 3/collection1/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.843; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.clou= d.ChaosMonkeyShardSplitTest-jetty1-1365997530403/collection1/lib/classes/' = to classloader [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.843; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.clou= d.ChaosMonkeyShardSplitTest-jetty1-1365997530403/collection1/lib/README' to= classloader [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.872; 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-15 03:45:31.872; 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-15 03:45:31.872; 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-15 03:45:31.899; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_43 [junit4:junit4] 1> INFO - 2013-04-15 03:45:31.962; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.063; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.069; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.675; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.686; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.690; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.702; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.707; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.711; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-15 03:45:32.712; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-15 03:45:32.712; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.713; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-15 03:45:32.713; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-15 03:45:32.714; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.714; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.714; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org= .apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1365997530403/collectio= n1/, dataDir=3D./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365997526= 076/jetty1/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.715; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@4c29d65b [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.715; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.716; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.C= haosMonkeyShardSplitTest-1365997526076/jetty1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.716; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ChaosMonkeyShardSplitTest-1365997526076/jetty1/index/ [junit4:junit4] 1> WARN - 2013-04-15 03:45:32.716; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Chaos= MonkeyShardSplitTest-1365997526076/jetty1/index' doesn't exist. Creating ne= w index... [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.717; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.C= haosMonkeyShardSplitTest-1365997526076/jetty1/index [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.722; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@2506007a lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@1d980059),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.723; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.739; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.739; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.740; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.740; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.741; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.741; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.742; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.742; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.743; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.750; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.757; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@73e5f8bc main [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.757; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Cha= osMonkeyShardSplitTest-1365997526076/jetty1/tlog [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.758; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.758; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.762; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@73e5f8bc main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.764; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-15 03:45:32.764; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.412; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.413; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"2", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:18959_jj", [junit4:junit4] 1> "base_url":"http://127.0.0.1:18959/jj"} [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.413; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Create collection collection1 with numShards= 2 [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.414; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.431; 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-15 03:45:33.431; 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-15 03:45:33.431; 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-15 03:45:33.767; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.767; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :18959/jj collection:collection1 shard:shard1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.768; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard= 1/election [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.807; org.apache.solr.cloud= .ShardLeaderElectionContext; Running the leader process. [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.818; org.apache.solr.cloud= .ShardLeaderElectionContext; Enough replicas found to continue. [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.818; org.apache.solr.cloud= .ShardLeaderElectionContext; I may be the new leader - try and sync [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.819; org.apache.solr.cloud= .SyncStrategy; Sync replicas to http://127.0.0.1:18959/jj/collection1/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.819; org.apache.solr.cloud= .SyncStrategy; Sync Success - now sync replicas to me [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.819; org.apache.solr.cloud= .SyncStrategy; http://127.0.0.1:18959/jj/collection1/ has no replicas [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.819; org.apache.solr.cloud= .ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:18959/jj= /collection1/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:33.819; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:34.939; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:34.985; 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-15 03:45:34.985; 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-15 03:45:34.985; 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-15 03:45:35.020; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:18959/jj/collection1/ and leader is = http://127.0.0.1:18959/jj/collection1/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.020; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:18959/jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.020; org.apache.solr.cloud= .ZkController; I am the leader, no recovery necessary [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.020; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.020; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.022; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.023; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.023; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.024; 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-15 03:45:35.187; org.eclipse.jetty.ser= ver.Server; jetty-8.1.8.v20121106 [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.190; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:18962 [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.190; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.191; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.191; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/tes= t/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365997535033 [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.191; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test= /J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365997535033/= solr.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.192; org.apache.solr.core.= CoreContainer; New CoreContainer 673303715 [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.192; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J= 1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365997535033/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.192; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-136599753503= 3/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.228; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.229; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.229; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.229; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.230; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.230; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.230; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.231; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.231; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.231; 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-15 03:45:35.244; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.256; org.apache.solr.core.= CoreContainer; Zookeeper client=3D127.0.0.1:18952/solr [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.257; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.258; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.261; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@35b7f804 name:ZooKeeperConnection Watcher:127.0.0.1:18952 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.262; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.281; 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-15 03:45:35.291; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.294; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@3e235306 name:ZooKeeperConnection Watcher:127.0.0.1:18952/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.294; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:35.309; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.312; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:189= 62_jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.316; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:18962_jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.324; 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-15 03:45:36.325; 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-15 03:45:36.325; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.325; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.326; 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-15 03:45:36.326; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.332; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (3) [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.335; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-= core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-13659= 97535033/collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.336; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.336; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.336; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.338; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-136599753503= 3/collection1/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.339; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.clou= d.ChaosMonkeyShardSplitTest-jetty2-1365997535033/collection1/lib/README' to= classloader [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.339; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.clou= d.ChaosMonkeyShardSplitTest-jetty2-1365997535033/collection1/lib/classes/' = to classloader [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.388; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_43 [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.448; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.499; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.500; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"2", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:18959_jj", [junit4:junit4] 1> "base_url":"http://127.0.0.1:18959/jj"} [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.523; 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-15 03:45:36.523; 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-15 03:45:36.523; 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-15 03:45:36.549; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:36.549; 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-15 03:45:36.556; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.210; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.226; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.230; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.243; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.247; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.250; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-15 03:45:37.250; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-15 03:45:37.251; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.251; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-15 03:45:37.252; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-15 03:45:37.252; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.253; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.253; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org= .apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1365997535033/collectio= n1/, dataDir=3D./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365997526= 076/jetty2/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.253; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@4c29d65b [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.253; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.254; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.C= haosMonkeyShardSplitTest-1365997526076/jetty2 [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.254; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ChaosMonkeyShardSplitTest-1365997526076/jetty2/index/ [junit4:junit4] 1> WARN - 2013-04-15 03:45:37.254; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Chaos= MonkeyShardSplitTest-1365997526076/jetty2/index' doesn't exist. Creating ne= w index... [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.255; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.C= haosMonkeyShardSplitTest-1365997526076/jetty2/index [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.257; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@4259d58d lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@538e56b7),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.257; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.291; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.292; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.292; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.292; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.293; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.293; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.293; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.294; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.294; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.298; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.302; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@6e7ebdf3 main [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.303; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Cha= osMonkeyShardSplitTest-1365997526076/jetty2/tlog [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.303; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.304; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.311; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@6e7ebdf3 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.312; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-15 03:45:37.313; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.027; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.028; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"3", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:18962_jj", [junit4:junit4] 1> "base_url":"http://127.0.0.1:18962/jj"} [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.029; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D2 [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.029; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard2 [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.078; 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-15 03:45:38.078; 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-15 03:45:38.078; 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-15 03:45:38.078; 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-15 03:45:38.357; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.357; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :18962/jj collection:collection1 shard:shard2 [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.358; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard= 2/election [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.400; org.apache.solr.cloud= .ShardLeaderElectionContext; Running the leader process. [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.418; org.apache.solr.cloud= .ShardLeaderElectionContext; Enough replicas found to continue. [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.418; org.apache.solr.cloud= .ShardLeaderElectionContext; I may be the new leader - try and sync [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.419; org.apache.solr.cloud= .SyncStrategy; Sync replicas to http://127.0.0.1:18962/jj/collection1/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.419; org.apache.solr.cloud= .SyncStrategy; Sync Success - now sync replicas to me [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.419; org.apache.solr.cloud= .SyncStrategy; http://127.0.0.1:18962/jj/collection1/ has no replicas [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.420; org.apache.solr.cloud= .ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:18962/jj= /collection1/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:38.420; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.582; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.648; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.648; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.648; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.648; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 3) [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.672; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:18962/jj/collection1/ and leader is = http://127.0.0.1:18962/jj/collection1/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.672; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:18962/jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.672; org.apache.solr.cloud= .ZkController; I am the leader, no recovery necessary [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.672; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.673; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.675; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.676; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.676; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.677; 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-15 03:45:39.841; org.eclipse.jetty.ser= ver.Server; jetty-8.1.8.v20121106 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.844; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:18965 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.845; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.845; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.845; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/tes= t/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365997539686 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.846; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test= /J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365997539686/= solr.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.846; org.apache.solr.core.= CoreContainer; New CoreContainer 2092836234 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.847; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J= 1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365997539686/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.847; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-136599753968= 6/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.884; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.884; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.885; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.885; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.885; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.886; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.886; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.886; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.887; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.887; 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-15 03:45:39.900; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.912; org.apache.solr.core.= CoreContainer; Zookeeper client=3D127.0.0.1:18952/solr [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.913; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.914; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.916; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@154726f3 name:ZooKeeperConnection Watcher:127.0.0.1:18952 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.917; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.941; 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-15 03:45:39.947; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.949; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@62629553 name:ZooKeeperConnection Watcher:127.0.0.1:18952/solr got e= vent WatchedEvent state:SyncConnected type:None path:null path:null type:No= ne [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.950; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:39.981; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:40.984; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:189= 65_jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:40.986; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:18965_jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:40.989; 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-15 03:45:40.989; 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-15 03:45:40.990; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-15 03:45:40.990; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-15 03:45:40.990; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-15 03:45:40.990; 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-15 03:45:40.991; 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-15 03:45:40.991; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-15 03:45:40.998; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (4) [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.003; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-= core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-13659= 97539686/collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.003; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.004; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.004; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.005; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-136599753968= 6/collection1/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.006; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.clou= d.ChaosMonkeyShardSplitTest-jetty3-1365997539686/collection1/lib/README' to= classloader [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.007; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.clou= d.ChaosMonkeyShardSplitTest-jetty3-1365997539686/collection1/lib/classes/' = to classloader [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.054; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_43 [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.111; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.177; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.178; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"3", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard2", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:18962_jj", [junit4:junit4] 1> "base_url":"http://127.0.0.1:18962/jj"} [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.197; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.197; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.197; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.197; org.apache.solr.commo= n.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncCon= nected type:NodeDataChanged path:/clusterstate.json, has occurred - updatin= g... (live nodes size: 4) [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.212; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.212; 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-15 03:45:41.218; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.854; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.866; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.870; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.882; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.887; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.891; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-15 03:45:41.892; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-15 03:45:41.893; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.894; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-15 03:45:41.895; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-15 03:45:41.895; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.895; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.895; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org= .apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1365997539686/collectio= n1/, dataDir=3D./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365997526= 076/jetty3/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.896; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@4c29d65b [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.896; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.897; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.C= haosMonkeyShardSplitTest-1365997526076/jetty3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.897; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ChaosMonkeyShardSplitTest-1365997526076/jetty3/index/ [junit4:junit4] 1> WARN - 2013-04-15 03:45:41.898; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Chaos= MonkeyShardSplitTest-1365997526076/jetty3/index' doesn't exist. Creating ne= w index... [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.898; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.C= haosMonkeyShardSplitTest-1365997526076/jetty3/index [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.901; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@6ba65089 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@415c85ad),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.901; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.925; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.925; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.926; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.926; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.927; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.927; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.927; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.928; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.928; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.935; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.941; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@282e4840 main [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.941; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Cha= osMonkeyShardSplitTest-1365997526076/jetty3/tlog [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.943; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.943; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.947; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@282e4840 main{Stan= dardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.949; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-15 03:45:41.949; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.701; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.702; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"4", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:18965_jj", [junit4:junit4] 1> "base_url":"http://127.0.0.1:18965/jj"} [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.702; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D2 [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.703; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.725; 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-15 03:45:42.725; 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-15 03:45:42.726; 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-15 03:45:42.725; 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-15 03:45:42.725; 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-15 03:45:42.989; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.989; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :18965/jj collection:collection1 shard:shard1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.995; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:18965/jj/collection1/ and leader is = http://127.0.0.1:18959/jj/collection1/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.995; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:18965/jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.995; org.apache.solr.cloud= .ZkController; Core needs to recover:collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.996; org.apache.solr.updat= e.DefaultSolrCoreState; Running recovery - first canceling any ongoing reco= very [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.996; org.apache.solr.cloud= .RecoveryStrategy; Starting recovery process. core=3Dcollection1 recoverin= gAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.996; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.997; org.apache.solr.cloud= .RecoveryStrategy; ###### startupVersions=3D[] [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.997; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Drecovering [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.998; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.998; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.999; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-15 03:45:42.999; 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-15 03:45:42.999; 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-15 03:45:43.014; org.apache.solr.handl= er.admin.CoreAdminHandler; Going to wait for coreNodeName: 4, state: recove= ring, checkLive: true, onlyIfLeader: true [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.232; org.eclipse.jetty.ser= ver.Server; jetty-8.1.8.v20121106 [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.236; org.eclipse.jetty.ser= ver.AbstractConnector; Started SocketConnector@127.0.0.1:18969 [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.236; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.237; org.apache.solr.core.= SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx) [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.237; org.apache.solr.core.= SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/= hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/tes= t/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365997543012 [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.238; org.apache.solr.core.= CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test= /J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365997543012/= solr.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.238; org.apache.solr.core.= CoreContainer; New CoreContainer 1169555301 [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.239; org.apache.solr.core.= CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hud= son-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J= 1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365997543012/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.239; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-136599754301= 2/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.294; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000 [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.295; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting urlScheme to: http:// [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.295; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting connTimeout to: 15000 [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.296; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.296; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting corePoolSize to: 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.297; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 214748364= 7 [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.297; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.298; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.298; org.apache.solr.handl= er.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.299; 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-15 03:45:43.318; org.apache.solr.core.= CoreContainer; Registering Log Listener [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.336; org.apache.solr.core.= CoreContainer; Zookeeper client=3D127.0.0.1:18952/solr [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.337; org.apache.solr.cloud= .ZkController; zkHost includes chroot [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.338; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.346; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@33cbbc62 name:ZooKeeperConnection Watcher:127.0.0.1:18952 got event = WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.347; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.376; 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-15 03:45:43.385; org.apache.solr.commo= n.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.387; org.apache.solr.commo= n.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionM= anager@7268f48 name:ZooKeeperConnection Watcher:127.0.0.1:18952/solr got ev= ent WatchedEvent state:SyncConnected type:None path:null path:null type:Non= e [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.388; org.apache.solr.commo= n.cloud.ConnectionManager; Client is connected to ZooKeeper [junit4:junit4] 1> INFO - 2013-04-15 03:45:43.414; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cluster state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.229; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.230; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"4", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"recovering", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:18965_jj", [junit4:junit4] 1> "base_url":"http://127.0.0.1:18965/jj"} [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.280; 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-15 03:45:44.280; 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-15 03:45:44.281; 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-15 03:45:44.280; 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-15 03:45:44.280; 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-15 03:45:44.280; 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-15 03:45:44.417; org.apache.solr.cloud= .ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:189= 69_jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.419; org.apache.solr.commo= n.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:18969_jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.433; 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-15 03:45:44.433; 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-15 03:45:44.433; 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-15 03:45:44.433; 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-15 03:45:44.434; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.435; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.434; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.435; 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-15 03:45:44.435; 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-15 03:45:44.436; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.437; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.437; org.apache.solr.commo= n.cloud.ZkStateReader$3; Updating live nodes... (5) [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.441; org.apache.solr.core.= CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home= /hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-= core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-13659= 97543012/collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.442; org.apache.solr.cloud= .ZkController; Check for collection zkNode:collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.442; org.apache.solr.cloud= .ZkController; Collection zkNode exists [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.442; org.apache.solr.cloud= .ZkController; Load collection config from:/collections/collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.444; org.apache.solr.core.= SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson= /hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/te= st/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-136599754301= 2/collection1/' [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.445; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.clou= d.ChaosMonkeyShardSplitTest-jetty4-1365997543012/collection1/lib/classes/' = to classloader [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.446; org.apache.solr.core.= SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.clou= d.ChaosMonkeyShardSplitTest-jetty4-1365997543012/collection1/lib/README' to= classloader [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.498; org.apache.solr.core.= SolrConfig; Using Lucene MatchVersion: LUCENE_43 [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.554; org.apache.solr.core.= SolrConfig; Loaded SolrConfig: solrconfig.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.655; org.apache.solr.schem= a.IndexSchema; Reading Solr Schema from schema.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:44.661; org.apache.solr.schem= a.IndexSchema; Schema name=3Dtest [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.016; org.apache.solr.handl= er.admin.CoreAdminHandler; Waited coreNodeName: 4, state: recovering, check= Live: true, onlyIfLeader: true for: 2 seconds. [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.016; org.apache.solr.servl= et.SolrDispatchFilter; [admin] webapp=3Dnull path=3D/admin/cores params=3D{= coreNodeName=3D4&state=3Drecovering&nodeName=3D127.0.0.1:18965_jj&action=3D= PREPRECOVERY&checkLive=3Dtrue&core=3Dcollection1&wt=3Djavabin&onlyIfLeader= =3Dtrue&version=3D2} status=3D0 QTime=3D2002=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.271; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Initialized with rates=3Dopen-exchange-rate= s.json, refreshInterval=3D1440. [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.282; org.apache.solr.schem= a.IndexSchema; default search field in schema is text [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.286; org.apache.solr.schem= a.IndexSchema; unique key field: id [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.298; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.302; org.apache.solr.schem= a.FileExchangeRateProvider; Reloading exchange rates from file currency.xml [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.306; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-15 03:45:45.307; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-15 03:45:45.308; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.308; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange= -rates.json [junit4:junit4] 1> WARN - 2013-04-15 03:45:45.309; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOT= E [junit4:junit4] 1> WARN - 2013-04-15 03:45:45.309; org.apache.solr.schem= a.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.310; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.310; org.apache.solr.core.= SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-sla= ve/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org= .apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1365997543012/collectio= n1/, dataDir=3D./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365997526= 076/jetty4/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.310; org.apache.solr.core.= JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Serve= r: com.sun.jmx.mbeanserver.JmxMBeanServer@4c29d65b [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.311; org.apache.solr.core.= SolrCore; org.apache.solr.core.MockDirectoryFactory [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.311; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.C= haosMonkeyShardSplitTest-1365997526076/jetty4 [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.312; org.apache.solr.core.= SolrCore; New index directory detected: old=3Dnull new=3D./org.apache.solr.= cloud.ChaosMonkeyShardSplitTest-1365997526076/jetty4/index/ [junit4:junit4] 1> WARN - 2013-04-15 03:45:45.312; org.apache.solr.core.= SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.Chaos= MonkeyShardSplitTest-1365997526076/jetty4/index' doesn't exist. Creating ne= w index... [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.312; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.C= haosMonkeyShardSplitTest-1365997526076/jetty4/index [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.315; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@16e3da96 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@1086cdc2),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.315; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.324; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "dedupe" [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.325; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "stored_sig" [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.325; org.apache.solr.updat= e.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcess= orFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit= " [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.326; org.apache.solr.core.= RequestHandlers; created standard: solr.StandardRequestHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.326; org.apache.solr.core.= RequestHandlers; created /get: solr.RealTimeGetHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.327; org.apache.solr.core.= RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.327; org.apache.solr.core.= RequestHandlers; created /replication: solr.ReplicationHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.328; org.apache.solr.core.= RequestHandlers; created /update: solr.UpdateRequestHandler [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.328; org.apache.solr.core.= RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandle= rs [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.335; org.apache.solr.handl= er.loader.XMLLoader; xsltCacheLifetimeSeconds=3D60 [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.341; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@b76b62f main [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.341; org.apache.solr.updat= e.UpdateHandler; Clearing tlog files, tlogDir=3D./org.apache.solr.cloud.Cha= osMonkeyShardSplitTest-1365997526076/jetty4/tlog [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.342; org.apache.solr.updat= e.CommitTracker; Hard AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.343; org.apache.solr.updat= e.CommitTracker; Soft AutoCommit: disabled [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.347; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@b76b62f main{Stand= ardDirectoryReader(segments_1:1)} [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.348; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Ddown [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.349; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.790; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.791; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"5", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":null, [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"down", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:18969_jj", [junit4:junit4] 1> "base_url":"http://127.0.0.1:18969/jj"} [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.792; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Collection already exists with numShards=3D2 [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.792; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Assigning new node to shard=3Dshard2 [junit4:junit4] 1> INFO - 2013-04-15 03:45:45.813; 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-15 03:45:45.813; 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-15 03:45:45.813; 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-15 03:45:45.813; 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-15 03:45:45.813; 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-15 03:45:45.813; 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-15 03:45:46.352; org.apache.solr.core.= CoreContainer; registering core: collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.352; org.apache.solr.cloud= .ZkController; Register replica - core:collection1 address:http://127.0.0.1= :18969/jj collection:collection1 shard:shard2 [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.361; org.apache.solr.cloud= .ZkController; We are http://127.0.0.1:18969/jj/collection1/ and leader is = http://127.0.0.1:18962/jj/collection1/ [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.362; org.apache.solr.cloud= .ZkController; No LogReplay needed for core=3Dcollection1 baseURL=3Dhttp://= 127.0.0.1:18969/jj [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.362; org.apache.solr.cloud= .ZkController; Core needs to recover:collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.362; org.apache.solr.updat= e.DefaultSolrCoreState; Running recovery - first canceling any ongoing reco= very [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.363; org.apache.solr.cloud= .RecoveryStrategy; Starting recovery process. core=3Dcollection1 recoverin= gAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.364; org.apache.solr.cloud= .RecoveryStrategy; ###### startupVersions=3D[] [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.364; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.364; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Drecovering [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.365; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.365; org.apache.solr.servl= et.SolrDispatchFilter; user.dir=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.366; org.apache.solr.servl= et.SolrDispatchFilter; SolrDispatchFilter.init() done [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.367; 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-15 03:45:46.417; 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-15 03:45:46.417; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.419; org.apache.solr.cloud= .AbstractFullDistribZkTestBase; Wait for recoveries to finish - wait 15 for= each attempt [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.419; org.apache.solr.cloud= .AbstractDistribZkTestBase; Wait for recoveries to finish - collection: col= lection1 failOnTimeout:true timeout (sec):15 [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.420; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:46.428; org.apache.solr.handl= er.admin.CoreAdminHandler; Going to wait for coreNodeName: 5, state: recove= ring, checkLive: true, onlyIfLeader: true [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.018; org.apache.solr.cloud= .RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:18959/jj/co= llection1/ core=3Dcollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.018; org.apache.solr.updat= e.PeerSync; PeerSync: core=3Dcollection1 url=3Dhttp://127.0.0.1:18965/jj ST= ART replicas=3D[http://127.0.0.1:18959/jj/collection1/] nUpdates=3D100 [junit4:junit4] 1> WARN - 2013-04-15 03:45:47.019; org.apache.solr.updat= e.PeerSync; no frame of reference to tell of we've missed updates [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.020; org.apache.solr.cloud= .RecoveryStrategy; PeerSync Recovery was not successful - trying replicatio= n. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.020; org.apache.solr.cloud= .RecoveryStrategy; Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.020; org.apache.solr.cloud= .RecoveryStrategy; Begin buffering updates. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.020; org.apache.solr.updat= e.UpdateLog; Starting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog= =3Dnull} [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.021; org.apache.solr.cloud= .RecoveryStrategy; Attempting to replicate from http://127.0.0.1:18959/jj/c= ollection1/. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.021; 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-15 03:45:47.026; org.apache.solr.core.= SolrCore; [collection1] webapp=3D/jj path=3D/get params=3D{getVersions=3D10= 0&distrib=3Dfalse&wt=3Djavabin&qt=3D/get&version=3D2} status=3D0 QTime=3D0= =20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.033; 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-15 03:45:47.097; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@2506007a lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@1d980059),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.097; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.098; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@2506007a lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@1d980059),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@2506007a lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@1d980059),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.098; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 2[segments_2] [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.099; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@24edda22 realtime [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.099; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.100; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{waitSearcher=3Dtrue&openSearcher=3Dfalse&commit=3Dtrue&wt=3Djavabi= n&commit_end_point=3Dtrue&version=3D2&softCommit=3Dfalse} {commit=3D} 0 67 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.101; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.101; org.apache.solr.handl= er.SnapPuller; No value set for 'pollInterval'. Timer Task not started. [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.103; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.103; org.apache.solr.core.= SolrCore; [collection1] webapp=3D/jj path=3D/replication params=3D{command= =3Dindexversion&qt=3D/replication&wt=3Djavabin&version=3D2} status=3D0 QTim= e=3D1=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.104; org.apache.solr.handl= er.SnapPuller; Master's generation: 2 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.104; org.apache.solr.handl= er.SnapPuller; Slave's generation: 1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.104; org.apache.solr.handl= er.SnapPuller; Starting replication process [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.107; org.apache.solr.core.= SolrCore; [collection1] webapp=3D/jj path=3D/replication params=3D{command= =3Dfilelist&qt=3D/replication&wt=3Djavabin&generation=3D2&version=3D2} stat= us=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.107; org.apache.solr.handl= er.SnapPuller; Number of files in latest index in master: 1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.109; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.C= haosMonkeyShardSplitTest-1365997526076/jetty3/index.20130415104547108 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.109; org.apache.solr.handl= er.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.= RAMDirectory@2815a96a lockFactory=3Dorg.apache.lucene.store.NativeFSLockFac= tory@13f9703) fullCopy=3Dfalse [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.112; org.apache.solr.core.= SolrCore; [collection1] webapp=3D/jj path=3D/replication params=3D{file=3Ds= egments_2&command=3Dfilecontent&checksum=3Dtrue&wt=3Dfilestream&qt=3D/repli= cation&generation=3D2} status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.113; org.apache.solr.handl= er.SnapPuller; Total time taken for download : 0 secs [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.113; org.apache.solr.updat= e.DefaultSolrCoreState; Creating new IndexWriter... [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.114; org.apache.solr.updat= e.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=3Dcolle= ction1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.135; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@6ba65089 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@415c85ad),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@6ba65089 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@415c85ad),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.136; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 2[segments_2] [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.136; org.apache.solr.updat= e.DefaultSolrCoreState; New IndexWriter is ready to be used. [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.136; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@41a1ee2a main [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.137; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@41a1ee2a main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.138; org.apache.solr.core.= CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365997526076/jetty3/index.20130415104547108 [CachedDir<>] [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.138; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMo= nkeyShardSplitTest-1365997526076/jetty3/index.20130415104547108 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.138; org.apache.solr.core.= CachingDirectoryFactory; Removing directory before core close: ./org.apache= .solr.cloud.ChaosMonkeyShardSplitTest-1365997526076/jetty3/index.2013041510= 4547108 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.138; org.apache.solr.cloud= .RecoveryStrategy; No replay needed. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.138; org.apache.solr.cloud= .RecoveryStrategy; Replication Recovery was successful - registering as Act= ive. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.138; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.139; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.169; org.apache.solr.cloud= .RecoveryStrategy; Finished recovery process. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.318; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.319; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"5", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard2", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"recovering", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:18969_jj", [junit4:junit4] 1> "base_url":"http://127.0.0.1:18969/jj"} [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.345; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"4", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard1", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:18965_jj", [junit4:junit4] 1> "base_url":"http://127.0.0.1:18965/jj"} [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.383; 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-15 03:45:47.384; 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-15 03:45:47.383; 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-15 03:45:47.384; 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-15 03:45:47.383; 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-15 03:45:47.383; 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-15 03:45:47.422; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.429; org.apache.solr.handl= er.admin.CoreAdminHandler; Waited coreNodeName: 5, state: recovering, check= Live: true, onlyIfLeader: true for: 1 seconds. [junit4:junit4] 1> INFO - 2013-04-15 03:45:47.429; org.apache.solr.servl= et.SolrDispatchFilter; [admin] webapp=3Dnull path=3D/admin/cores params=3D{= coreNodeName=3D5&state=3Drecovering&nodeName=3D127.0.0.1:18969_jj&action=3D= PREPRECOVERY&checkLive=3Dtrue&core=3Dcollection1&wt=3Djavabin&onlyIfLeader= =3Dtrue&version=3D2} status=3D0 QTime=3D1001=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:48.424; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.426; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.431; org.apache.solr.cloud= .RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:18962/jj/co= llection1/ core=3Dcollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.431; org.apache.solr.updat= e.PeerSync; PeerSync: core=3Dcollection1 url=3Dhttp://127.0.0.1:18969/jj ST= ART replicas=3D[http://127.0.0.1:18962/jj/collection1/] nUpdates=3D100 [junit4:junit4] 1> WARN - 2013-04-15 03:45:49.431; org.apache.solr.updat= e.PeerSync; no frame of reference to tell of we've missed updates [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.432; org.apache.solr.cloud= .RecoveryStrategy; PeerSync Recovery was not successful - trying replicatio= n. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.432; org.apache.solr.cloud= .RecoveryStrategy; Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.432; org.apache.solr.cloud= .RecoveryStrategy; Begin buffering updates. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.433; org.apache.solr.updat= e.UpdateLog; Starting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog= =3Dnull} [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.433; org.apache.solr.cloud= .RecoveryStrategy; Attempting to replicate from http://127.0.0.1:18962/jj/c= ollection1/. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.433; 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-15 03:45:49.438; org.apache.solr.core.= SolrCore; [collection1] webapp=3D/jj path=3D/get params=3D{getVersions=3D10= 0&distrib=3Dfalse&wt=3Djavabin&qt=3D/get&version=3D2} status=3D0 QTime=3D0= =20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.444; 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-15 03:45:49.494; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@4259d58d lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@538e56b7),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.495; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.496; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@4259d58d lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@538e56b7),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@4259d58d lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@538e56b7),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.496; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 2[segments_2] [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.497; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@254cd7b2 realtime [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.497; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.498; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{waitSearcher=3Dtrue&openSearcher=3Dfalse&commit=3Dtrue&wt=3Djavabi= n&commit_end_point=3Dtrue&version=3D2&softCommit=3Dfalse} {commit=3D} 0 54 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.498; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.499; org.apache.solr.handl= er.SnapPuller; No value set for 'pollInterval'. Timer Task not started. [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.500; org.apache.solr.handl= er.ReplicationHandler; Commits will be reserved for 10000 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.500; org.apache.solr.core.= SolrCore; [collection1] webapp=3D/jj path=3D/replication params=3D{command= =3Dindexversion&qt=3D/replication&wt=3Djavabin&version=3D2} status=3D0 QTim= e=3D0=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.501; org.apache.solr.handl= er.SnapPuller; Master's generation: 2 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.501; org.apache.solr.handl= er.SnapPuller; Slave's generation: 1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.501; org.apache.solr.handl= er.SnapPuller; Starting replication process [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.503; org.apache.solr.core.= SolrCore; [collection1] webapp=3D/jj path=3D/replication params=3D{command= =3Dfilelist&qt=3D/replication&wt=3Djavabin&generation=3D2&version=3D2} stat= us=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.503; org.apache.solr.handl= er.SnapPuller; Number of files in latest index in master: 1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.504; org.apache.solr.core.= CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.C= haosMonkeyShardSplitTest-1365997526076/jetty4/index.20130415104549504 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.505; org.apache.solr.handl= er.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.= RAMDirectory@220ce59a lockFactory=3Dorg.apache.lucene.store.NativeFSLockFac= tory@202a029) fullCopy=3Dfalse [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.507; org.apache.solr.core.= SolrCore; [collection1] webapp=3D/jj path=3D/replication params=3D{file=3Ds= egments_2&command=3Dfilecontent&checksum=3Dtrue&wt=3Dfilestream&qt=3D/repli= cation&generation=3D2} status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.508; org.apache.solr.handl= er.SnapPuller; Total time taken for download : 0 secs [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.508; org.apache.solr.updat= e.DefaultSolrCoreState; Creating new IndexWriter... [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.508; org.apache.solr.updat= e.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=3Dcolle= ction1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.558; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@16e3da96 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@1086cdc2),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@16e3da96 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@1086cdc2),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.558; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 2[segments_2] [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.559; org.apache.solr.updat= e.DefaultSolrCoreState; New IndexWriter is ready to be used. [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.559; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@3ab241de main [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.560; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@3ab241de main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.560; org.apache.solr.core.= CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ChaosMonk= eyShardSplitTest-1365997526076/jetty4/index.20130415104549504 [CachedDir<>] [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.560; org.apache.solr.core.= CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ChaosMo= nkeyShardSplitTest-1365997526076/jetty4/index.20130415104549504 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.560; org.apache.solr.core.= CachingDirectoryFactory; Removing directory before core close: ./org.apache= .solr.cloud.ChaosMonkeyShardSplitTest-1365997526076/jetty4/index.2013041510= 4549504 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.561; org.apache.solr.cloud= .RecoveryStrategy; No replay needed. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.561; org.apache.solr.cloud= .RecoveryStrategy; Replication Recovery was successful - registering as Act= ive. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.561; org.apache.solr.cloud= .ZkController; publishing core=3Dcollection1 state=3Dactive [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.561; org.apache.solr.cloud= .ZkController; numShards not found on descriptor - reading it from system p= roperty [junit4:junit4] 1> INFO - 2013-04-15 03:45:49.562; org.apache.solr.cloud= .RecoveryStrategy; Finished recovery process. core=3Dcollection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:50.418; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:50.419; org.apache.solr.cloud= .Overseer$ClusterStateUpdater; Update state numShards=3D2 message=3D{ [junit4:junit4] 1> "operation":"state", [junit4:junit4] 1> "core_node_name":"5", [junit4:junit4] 1> "numShards":"2", [junit4:junit4] 1> "shard":"shard2", [junit4:junit4] 1> "roles":null, [junit4:junit4] 1> "state":"active", [junit4:junit4] 1> "shard_state":"active", [junit4:junit4] 1> "core":"collection1", [junit4:junit4] 1> "collection":"collection1", [junit4:junit4] 1> "shard_range":null, [junit4:junit4] 1> "node_name":"127.0.0.1:18969_jj", [junit4:junit4] 1> "base_url":"http://127.0.0.1:18969/jj"} [junit4:junit4] 1> INFO - 2013-04-15 03:45:50.469; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:50.480; 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-15 03:45:50.480; 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-15 03:45:50.480; 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-15 03:45:50.480; 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-15 03:45:50.480; 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-15 03:45:50.480; 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-15 03:45:51.471; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.472; org.apache.solr.cloud= .AbstractDistribZkTestBase; Recoveries finished - collection: collection1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.481; 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-15 03:45:51.504; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=3D1 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@51cc7fbc lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@495d56fd),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.505; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 1[segments_1] [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.506; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@51cc7fbc lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@495d56fd),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1] [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@51cc7fbc lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@495d56fd),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.506; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 2[segments_2] [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.507; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@2c89edf9 main [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.507; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.508; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@2c89edf9 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.509; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{waitSearcher=3Dtrue&commit=3Dtrue&wt=3Djavabin&version=3D2&softCom= mit=3Dfalse} {commit=3D} 0 28 [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.519; 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-15 03:45:51.520; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@4259d58d lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@538e56b7),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@4259d58d lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@538e56b7),segFN=3Dsegments_3,generation=3D3,filenames=3D[segments_3] [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.521; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 3[segments_3] [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.521; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@2266495a main [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.522; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.522; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@2266495a main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.523; org.apache.solr.updat= e.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:18959/jj= /collection1/, StdNode: http://127.0.0.1:18965/jj/collection1/, StdNode: ht= tp://127.0.0.1:18969/jj/collection1/] params:commit_end_point=3Dtrue&commit= =3Dtrue&softCommit=3Dfalse&waitSearcher=3Dtrue&expungeDeletes=3Dfalse [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.525; 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-15 03:45:51.526; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@2506007a lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@1d980059),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@2506007a lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@1d980059),segFN=3Dsegments_3,generation=3D3,filenames=3D[segments_3] [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.527; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 3[segments_3] [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.527; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@491bcad7 main [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.527; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.528; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@491bcad7 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.528; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{waitSearcher=3Dtrue&commit=3Dtrue&wt=3Djavabin&expungeDeletes=3Dfa= lse&commit_end_point=3Dtrue&version=3D2&softCommit=3Dfalse} {commit=3D} 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.529; 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-15 03:45:51.530; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@6ba65089 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@415c85ad),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@6ba65089 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@415c85ad),segFN=3Dsegments_3,generation=3D3,filenames=3D[segments_3] [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.531; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 3[segments_3] [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.531; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@3242214f main [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.531; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.532; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@3242214f main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.532; 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-15 03:45:51.532; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{waitSearcher=3Dtrue&commit=3Dtrue&wt=3Djavabin&expungeDeletes=3Dfa= lse&commit_end_point=3Dtrue&version=3D2&softCommit=3Dfalse} {commit=3D} 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.533; org.apache.solr.core.= SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@16e3da96 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@1086cdc2),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2] [junit4:junit4] 1> =09commit{dir=3DMockDirWrapper(org.apache.lucene.store= .RAMDirectory@16e3da96 lockFactory=3Dorg.apache.lucene.store.NativeFSLockFa= ctory@1086cdc2),segFN=3Dsegments_3,generation=3D3,filenames=3D[segments_3] [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.533; org.apache.solr.core.= SolrDeletionPolicy; newest commit =3D 3[segments_3] [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.534; org.apache.solr.searc= h.SolrIndexSearcher; Opening Searcher@64ff2225 main [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.534; org.apache.solr.updat= e.DirectUpdateHandler2; end_commit_flush [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.535; org.apache.solr.core.= SolrCore; [collection1] Registered new searcher Searcher@64ff2225 main{Stan= dardDirectoryReader(segments_2:1:nrt)} [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.535; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{waitSearcher=3Dtrue&commit=3Dtrue&wt=3Djavabin&expungeDeletes=3Dfa= lse&commit_end_point=3Dtrue&version=3D2&softCommit=3Dfalse} {commit=3D} 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.536; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{waitSearcher=3Dtrue&commit=3Dtrue&wt=3Djavabin&version=3D2&softCom= mit=3Dfalse} {commit=3D} 0 17 [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.537; org.apache.solr.commo= n.cloud.ZkStateReader; Updating cloud state from ZooKeeper...=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.539; org.apache.solr.core.= SolrCore; [collection1] webapp=3D/jj path=3D/select params=3D{tests=3Dcheck= ShardConsistency&q=3D*:*&distrib=3Dfalse&wt=3Djavabin&version=3D2&rows=3D0}= hits=3D0 status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.541; org.apache.solr.core.= SolrCore; [collection1] webapp=3D/jj path=3D/select params=3D{tests=3Dcheck= ShardConsistency&q=3D*:*&distrib=3Dfalse&wt=3Djavabin&version=3D2&rows=3D0}= hits=3D0 status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.542; org.apache.solr.core.= SolrCore; [collection1] webapp=3D/jj path=3D/select params=3D{tests=3Dcheck= ShardConsistency&q=3D*:*&distrib=3Dfalse&wt=3Djavabin&version=3D2&rows=3D0}= hits=3D0 status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:51.544; org.apache.solr.core.= SolrCore; [collection1] webapp=3D/jj path=3D/select params=3D{tests=3Dcheck= ShardConsistency&q=3D*:*&distrib=3Dfalse&wt=3Djavabin&version=3D2&rows=3D0}= hits=3D0 status=3D0 QTime=3D0=20 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.553; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {deleteByQuery=3D*:* (-14323522507080990= 72)} 0 6 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.569; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{update.distrib=3DFROMLEADER&_version_=3D-1432352250716487680&updat= e.from=3Dhttp://127.0.0.1:18959/jj/collection1/&wt=3Djavabin&version=3D2} {= deleteByQuery=3D*:* (-1432352250716487680)} 0 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.594; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{update.distrib=3DFROMLEADER&_version_=3D-1432352250725924864&updat= e.from=3Dhttp://127.0.0.1:18962/jj/collection1/&wt=3Djavabin&version=3D2} {= deleteByQuery=3D*:* (-1432352250725924864)} 0 24 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.594; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{update.distrib=3DTOLEADER&wt=3Djavabin&version=3D2} {deleteByQuery= =3D*:* (-1432352250725924864)} 0 30 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.595; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {deleteByQuery=3D*:* (-14323522507164876= 80)} 0 40 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.599; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[0 (1432352250761576448)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.605; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[0 (1432352250764722176)]}= 0 1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.605; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[0 (1432352250764722176)]} 0 4 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.608; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[1 (1432352250772062208)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.613; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[1 (1432352250775207936)]}= 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.614; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[1 (1432352250775207936)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.616; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[2 (1432352250780450816)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.623; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[2 (1432352250783596544)]}= 0 1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.623; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[2 (1432352250783596544)]} 0 4 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.626; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[3 (1432352250790936576)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.633; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[3 (1432352250796179456)]}= 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.634; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[3 (1432352250796179456)]} 0= 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.634; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[3]} 0 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.637; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[4 (1432352250802470912)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.645; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[4 (1432352250807713792)]}= 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.646; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[4 (1432352250807713792)]} 0= 4 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.646; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[4]} 0 6 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.649; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[5 (1432352250815053824)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.655; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[5 (1432352250818199552)]}= 0 1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.655; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[5 (1432352250818199552)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.658; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[6 (1432352250824491008)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.663; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[6 (1432352250827636736)]}= 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.664; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[6 (1432352250827636736)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.666; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[7 (1432352250832879616)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.671; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[7 (1432352250836025344)]}= 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.672; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[7 (1432352250836025344)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.674; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[8 (1432352250841268224)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.679; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[8 (1432352250844413952)]}= 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.681; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[8 (1432352250844413952)]} 0 4 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.683; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[9 (1432352250850705408)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.688; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[9 (1432352250853851136)]}= 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.689; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[9 (1432352250853851136)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.691; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[10 (1432352250859094016)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.698; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[10 (1432352250864336896)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.699; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[10 (1432352250864336896)]} = 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.699; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[10]} 0 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.702; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[11 (1432352250870628352)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.707; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[11 (1432352250873774080)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.708; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[11 (1432352250873774080)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.710; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[12 (1432352250879016960)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.715; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[12 (1432352250882162688)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.716; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[12 (1432352250882162688)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.718; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[13 (1432352250887405568)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.724; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[13 (1432352250890551296)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.725; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[13 (1432352250890551296)]} 0 4 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.727; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[14 (1432352250896842752)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.734; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[14 (1432352250902085632)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.735; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[14 (1432352250902085632)]} = 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.736; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[14]} 0 6 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.738; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[15 (1432352250908377088)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.745; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[15 (1432352250913619968)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.746; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[15 (1432352250913619968)]} = 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.746; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[15]} 0 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.749; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[16 (1432352250919911424)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.755; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[16 (1432352250923057152)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.756; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[16 (1432352250923057152)]} 0 4 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.758; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[17 (1432352250929348608)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.765; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[17 (1432352250933542912)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.766; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[17 (1432352250933542912)]} = 0 4 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.767; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[17]} 0 7 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.770; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[18 (1432352250941931520)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.775; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[18 (1432352250945077248)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.776; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[18 (1432352250945077248)]} 0 2 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.778; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[19 (1432352250950320128)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.782; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[19 (1432352250952417280)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.783; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[19 (1432352250952417280)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.786; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[20 (1432352250957660160)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.793; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[20 (1432352250963951616)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.794; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[20 (1432352250963951616)]} = 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.794; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[20]} 0 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.796; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[21 (1432352250969194496)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.803; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[21 (1432352250973388800)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.804; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[21 (1432352250973388800)]} = 0 4 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.804; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[21]} 0 6 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.806; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[22 (1432352250979680256)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.812; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[22 (1432352250983874560)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.813; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[22 (1432352250983874560)]} = 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.813; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[22]} 0 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.815; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[23 (1432352250989117440)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.822; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[23 (1432352250994360320)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.823; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[23 (1432352250994360320)]} = 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.823; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[23]} 0 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.826; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[24 (1432352251000651776)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.833; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[24 (1432352251005894656)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.834; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[24 (1432352251005894656)]} = 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.834; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[24]} 0 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.836; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[25 (1432352251011137536)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.842; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[25 (1432352251015331840)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.843; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[25 (1432352251015331840)]} = 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.843; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[25]} 0 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.846; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[26 (1432352251021623296)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.850; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[26 (1432352251023720448)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.851; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[26 (1432352251023720448)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.853; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[27 (1432352251028963328)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.860; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[27 (1432352251034206208)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.861; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[27 (1432352251034206208)]} = 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.861; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[27]} 0 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.864; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[28 (1432352251039449088)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.871; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[28 (1432352251045740544)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.872; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[28 (1432352251045740544)]} = 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.872; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[28]} 0 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.875; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[29 (1432352251052032000)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.881; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[29 (1432352251056226304)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.882; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[29 (1432352251056226304)]} = 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.882; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[29]} 0 5 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.885; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[30 (1432352251062517760)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.890; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[30 (1432352251064614912)]= } 0 1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.891; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[30 (1432352251064614912)]} 0 4 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.893; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[31 (1432352251070906368)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.901; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18962/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[31 (1432352251076149248)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.902; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DTOLEADER&wt=3Djavabin&version=3D2} {add=3D[31 (1432352251076149248)]} = 0 4 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.902; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[31]} 0 6 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.906; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[32 (1432352251083489280)]} 0 1 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.910; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{distrib.from=3Dhttp://127.0.0.1:18959/jj/collection1/&update.distr= ib=3DFROMLEADER&wt=3Djavabin&version=3D2} {add=3D[32 (1432352251086635008)]= } 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.911; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[32 (1432352251086635008)]} 0 3 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.913; org.apache.solr.updat= e.processor.LogUpdateProcessor; [collection1] webapp=3D/jj path=3D/update p= arams=3D{wt=3Djavabin&version=3D2} {add=3D[33 (1432352251091877888)]} 0 0 [junit4:junit4] 1> INFO - 2013-04-15 03:45:53.918; org.apache.solr.updat= e.processor.Lo [...truncated too long message...] rg.apache.solr.SolrTestCaseJ4; ###Ending testDistribSearch [junit4:junit4] 1> INFO - 2013-04-15 03:49:09.501; org.apache.solr.cloud= .ZkTestServer; connecting to 127.0.0.1:18952 18952 [junit4:junit4] 1> INFO - 2013-04-15 03:49:09.777; org.apache.solr.cloud= .ChaosMonkey; monkey: stop shard! 18955 [junit4:junit4] 1> INFO - 2013-04-15 03:49:09.784; org.apache.solr.SolrT= estCaseJ4; ###Ending testDistribSearch [junit4:junit4] 1> INFO - 2013-04-15 03:49:09.785; org.apache.solr.cloud= .ZkTestServer; connecting to 127.0.0.1:18952 18952 [junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/worksp= ace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./solrtest-Cha= osMonkeyShardSplitTest-1365997526076 [junit4:junit4] 2> check const of shard1 [junit4:junit4] 2> client0 [junit4:junit4] 2> PROPS:2:{"shard":"shard1","state":"down","core":"colle= ction1","collection":"collection1","node_name":"127.0.0.1:18959_jj","base_u= rl":"http://127.0.0.1:18959/jj"} [junit4:junit4] 2> error contacting client: IOException occured when talk= ing to server at: http://127.0.0.1:18959/jj/collection1 [junit4:junit4] 2>=20 [junit4:junit4] 2> client1 [junit4:junit4] 2> PROPS:4:{"shard":"shard1","state":"active","core":"col= lection1","collection":"collection1","node_name":"127.0.0.1:18965_jj","base= _url":"http://127.0.0.1:18965/jj"} [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:3:{"shard":"shard2","state":"active","core":"col= lection1","collection":"collection1","node_name":"127.0.0.1:18962_jj","base= _url":"http://127.0.0.1:18962/jj","leader":"true"} [junit4:junit4] 2> live:true [junit4:junit4] 2> num:44 [junit4:junit4] 2>=20 [junit4:junit4] 2> client1 [junit4:junit4] 2> PROPS:5:{"shard":"shard2","state":"active","core":"col= lection1","collection":"collection1","node_name":"127.0.0.1:18969_jj","base= _url":"http://127.0.0.1:18969/jj"} [junit4:junit4] 2> live:true [junit4:junit4] 2> num:44 [junit4:junit4] 2>=20 [junit4:junit4] 2> !!!! WARNING: best effort to remove /usr/home/hudson/h= udson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test= /J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1365997526076 FAILED = !!!!! [junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=3DChaosMonk= eyShardSplitTest -Dtests.method=3DtestDistribSearch -Dtests.seed=3D32D28CFF= A5436A68 -Dtests.multiplier=3D3 -Dtests.slow=3Dtrue -Dtests.locale=3Dzh_SG = -Dtests.timezone=3DAsia/Novokuznetsk -Dtests.file.encoding=3DISO-8859-1 [junit4:junit4] FAILURE 224s J1 | ChaosMonkeyShardSplitTest.testDistribSea= rch <<< [junit4:junit4] > Throwable #1: java.lang.AssertionError: Wrong doc coun= t on shard1_1 expected:<322> but was:<323> [junit4:junit4] > =09at __randomizedtesting.SeedInfo.seed([32D28CFFA5436= A68:B33402E7D21C0A54]:0) [junit4:junit4] > =09at org.apache.solr.cloud.ShardSplitTest.checkDocCou= ntsAndShardStates(ShardSplitTest.java:155) [junit4:junit4] > =09at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.= doTest(ChaosMonkeyShardSplitTest.java:154) [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-15 03:49:09.807; org.apache.solr.SolrT= estCaseJ4; ###deleteCore [junit4:junit4] 2> 223745 T3970 ccr.ThreadLeakControl.checkThreadLeaks WA= RNING Will linger awaiting termination of 2 leaked thread(s). [junit4:junit4] 2> NOTE: test params are: codec=3DLucene42: {timestamp=3D= Pulsing41(freqCutoff=3D16 minBlockSize=3D35 maxBlockSize=3D157), range_face= t_l=3DPulsing41(freqCutoff=3D16 minBlockSize=3D35 maxBlockSize=3D157), id= =3DPostingsFormat(name=3DNestedPulsing), range_facet_sl=3DPostingsFormat(na= me=3DMemory doPackFST=3D false), range_facet_si=3DPostingsFormat(name=3DMoc= kSep), _version_=3DPulsing41(freqCutoff=3D16 minBlockSize=3D35 maxBlockSize= =3D157), multiDefault=3DPostingsFormat(name=3DMockSep), rnd_b=3DPostingsFor= mat(name=3DNestedPulsing), intDefault=3DPulsing41(freqCutoff=3D16 minBlockS= ize=3D35 maxBlockSize=3D157)}, docValues:{}, sim=3DDefaultSimilarity, local= e=3Dzh_SG, timezone=3DAsia/Novokuznetsk [junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. = 1.6.0_32 (64-bit)/cpus=3D16,threads=3D2,free=3D261827640,total=3D468320256 [junit4:junit4] 2> NOTE: All tests run in this JVM: [NumericFieldsTest, T= imeZoneUtilsTest, SolrCoreCheckLockOnStartupTest, OpenExchangeRatesOrgProvi= derTest, FullSolrCloudDistribCmdsTest, TestCollationField, ZkSolrClientTest= , TestDefaultSimilarityFactory, UniqFieldsUpdateProcessorFactoryTest, TestA= rbitraryIndexDir, NotRequiredUniqueKeyTest, TestRTGBase, SpellCheckCollator= Test, TestCodecSupport, TestJmxMonitoredMap, ConvertedLegacyTest, TestCompo= nentsName, PreAnalyzedUpdateProcessorTest, TestMergePolicyConfig, JSONWrite= rTest, TestFastOutputStream, BadIndexSchemaTest, TestDFRSimilarityFactory, = TestSolr4Spatial, TestReload, TestWordDelimiterFilterFactory, TestDistribut= edSearch, TestCoreDiscovery, EchoParamsTest, TestUniqueKeyFieldResource, No= CacheHeaderTest, StatsComponentTest, TestIndexSearcher, TestRandomFaceting,= SignatureUpdateProcessorFactoryTest, SolrRequestParserTest, TestRangeQuery= , TestCopyFieldCollectionResource, TermVectorComponentDistributedTest, Basi= cZkTest, SortByFunctionTest, TestSolrQueryParserResource, IndexReaderFactor= yTest, SuggesterWFSTTest, IndexSchemaRuntimeFieldTest, DocValuesMultiTest, = BasicDistributedZk2Test, TestAtomicUpdateErrorCases, TestOmitPositions, Tes= tFoldingMultitermQuery, DocumentAnalysisRequestHandlerTest, CurrencyFieldOp= enExchangeTest, TestShardHandlerFactory, TestCSVLoader, StandardRequestHand= lerTest, SpellCheckComponentTest, TestZkChroot, SpellPossibilityIteratorTes= t, DOMUtilTest, TestFieldTypeResource, PathHierarchyTokenizerFactoryTest, T= estSolrJ, TestAnalyzedSuggestions, TestIndexingPerformance, OpenCloseCoreSt= ressTest, HighlighterConfigTest, TestRecovery, CollectionsAPIDistributedZkT= est, TestMultiCoreConfBootstrap, RequestHandlersTest, SimplePostToolTest, C= haosMonkeySafeLeaderTest, SyncSliceTest, ShardRoutingCustomTest, TestDistri= butedGrouping, TestStressReorder, TestStressVersions, HardAutoCommitTest, D= istributedTermsComponentTest, TestCoreContainer, SimpleFacetsTest, SolrCore= Test, TestGroupingSearch, TestFunctionQuery, BasicFunctionalityTest, TestLa= zyCores, DirectUpdateHandlerTest, OverseerCollectionProcessorTest, Highligh= terTest, ShowFileRequestHandlerTest, DistributedQueryElevationComponentTest= , CurrencyFieldXmlFileTest, SolrIndexSplitterTest, TestExtendedDismaxParser= , SuggesterFSTTest, DocValuesTest, SuggesterTSTTest, SuggesterTest, TestStr= essLucene, TestTrie, SchemaVersionSpecificBehaviorTest, TestPseudoReturnFie= lds, TestUpdate, FieldMutatingUpdateProcessorTest, DirectUpdateHandlerOptim= izeTest, DefaultValueUpdateProcessorTest, TestRemoteStreaming, DistanceFunc= tionTest, SolrInfoMBeanTest, XsltUpdateRequestHandlerTest, DebugComponentTe= st, CacheHeaderTest, IndexBasedSpellCheckerTest, DisMaxRequestHandlerTest, = TestWriterPerf, DirectSolrSpellCheckerTest, TestReversedWildcardFilterFacto= ry, TestQueryTypes, PrimitiveFieldTypeTest, FileBasedSpellCheckerTest, Term= sComponentTest, XmlUpdateRequestHandlerTest, DocumentBuilderTest, MoreLikeT= hisHandlerTest, RequiredFieldsTest, FieldAnalysisRequestHandlerTest, FastVe= ctorHighlighterTest, SolrPluginUtilsTest, TestJmxIntegration, UpdateRequest= ProcessorFactoryTest, TestCSVResponseWriter, JsonLoaderTest, TestPartialUpd= ateDeduplication, PingRequestHandlerTest, CSVRequestHandlerTest, SearchHand= lerTest, CoreContainerCoreInitFailuresTest, TestBinaryResponseWriter, TestP= ropInject, TestQuerySenderListener, UpdateParamsTest, TestSolrIndexConfig, = TestQuerySenderNoQuery, CopyFieldTest, SolrIndexConfigTest, BadComponentTes= t, TestStressRecovery, TestSolrDeletionPolicy2, MultiTermTest, SampleTest, = TestBinaryField, TestSearchPerf, TestElisionMultitermQuery, TestConfig, Out= putWriterTest, TestFuzzyAnalyzedSuggestions, ExternalFileFieldSortTest, Tes= tPostingsSolrHighlighter, DirectSolrConnectionTest, TestLuceneMatchVersion,= TestSweetSpotSimilarityFactory, TestNumberUtils, TestLMJelinekMercerSimila= rityFactory, TestIBSimilarityFactory, TestBM25SimilarityFactory, ResourceLo= aderTest, ScriptEngineTest, URLClassifyProcessorTest, TestFastLRUCache, Dat= eMathParserTest, TestSolrXMLSerializer, TestSystemIdResolver, PrimUtilsTest= , TestSuggestSpellingConverter, ClusterStateTest, TestLRUCache, TestUtils, = TestDocumentBuilder, ZkNodePropsTest, SystemInfoHandlerTest, FileUtilsTest,= CircularListTest, SolrTestCaseJ4Test, AliasIntegrationTest, ChaosMonkeySha= rdSplitTest] [junit4:junit4] Completed on J1 in 224.03s, 1 test, 1 failure <<< FAILURES! [...truncated 51 lines...] BUILD FAILED /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.x= ml:381: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.x= ml:361: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.x= ml:39: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/bu= ild.xml:183: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/co= mmon-build.xml:438: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/= common-build.xml:1234: The following error occurred while executing this li= ne: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/= common-build.xml:878: There were test failures: 290 suites, 1204 tests, 1 f= ailure, 27 ignored (8 assumptions) Total time: 57 minutes 40 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_2483_1324406348.1365997995126 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_2483_1324406348.1365997995126--