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 283DFE392 for ; Thu, 14 Mar 2013 15:10:54 +0000 (UTC) Received: (qmail 46620 invoked by uid 500); 14 Mar 2013 15:10:52 -0000 Delivered-To: apmail-lucene-dev-archive@lucene.apache.org Received: (qmail 46562 invoked by uid 500); 14 Mar 2013 15:10:52 -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 46531 invoked by uid 99); 14 Mar 2013 15:10:51 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 14 Mar 2013 15:10:51 +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; Thu, 14 Mar 2013 15:10:26 +0000 Received: from aegis.apache.org (localhost [127.0.0.1]) by aegis.apache.org (Postfix) with ESMTP id C6EB6C00CA for ; Thu, 14 Mar 2013 15:10:03 +0000 (UTC) Date: Thu, 14 Mar 2013 15:09:48 +0000 (UTC) From: Apache Jenkins Server To: dev@lucene.apache.org Message-ID: <241197821.4314.1363273803254.JavaMail.hudson@aegis> In-Reply-To: <500543326.4230.1363240406385.JavaMail.hudson@aegis> References: <500543326.4230.1363240406385.JavaMail.hudson@aegis> Subject: [JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1420 - Still Failing MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----=_Part_4313_1869662082.1363273788812" X-Jenkins-Job: Lucene-Solr-Tests-4.x-Java6 X-Jenkins-Result: FAILURE X-Virus-Checked: Checked by ClamAV on apache.org ------=_Part_4313_1869662082.1363273788812 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1420/ 2 tests failed. REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch Error Message: Stack Trace: java.lang.AssertionError =09at __randomizedtesting.SeedInfo.seed([60EC721D15B9797D:E10AFC0562E61941]= :0) =09at org.junit.Assert.fail(Assert.java:92) =09at org.junit.Assert.assertTrue(Assert.java:43) =09at org.junit.Assert.assertTrue(Assert.java:54) =09at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:196) =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) FAILED: org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearch Error Message: No registered leader was found, collection:collection1 slice:shard1 Stack Trace: org.apache.solr.common.SolrException: No registered leader was found, colle= ction:collection1 slice:shard1 =09at __randomizedtesting.SeedInfo.seed([60EC721D15B9797D:E10AFC0562E61941]= :0) =09at org.apache.solr.common.cloud.ZkStateReader.getLeaderRetry(ZkStateRead= er.java:484) =09at org.apache.solr.cloud.BasicDistributedZk2Test.brindDownShardIndexSome= DocsAndRecover(BasicDistributedZk2Test.java:291) =09at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributed= Zk2Test.java:116) =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 8508 lines...] [junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test [junit4:junit4] 2> 0 T350 oas.BaseDistributedSearchTestCase.initHostConte= xt Setting hostContext system property: /muhkb/mb [junit4:junit4] 2> 4 T350 oas.SolrTestCaseJ4.setUp ###Starting testDistri= bSearch [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-Bas= icDistributedZk2Test-1363272769278 [junit4:junit4] 2> 5 T350 oasc.ZkTestServer.run STARTING ZK TEST SERVER [junit4:junit4] 2> 6 T351 oasc.ZkTestServer$ZKServerMain.runFromConfig St= arting server [junit4:junit4] 2> 8 T351 oazs.ZooKeeperServer.setTickTime tickTime set t= o 1000 [junit4:junit4] 2> 9 T351 oazs.ZooKeeperServer.setMinSessionTimeout minSe= ssionTimeout set to -1 [junit4:junit4] 2> 9 T351 oazs.ZooKeeperServer.setMaxSessionTimeout maxSe= ssionTimeout set to -1 [junit4:junit4] 2> 9 T351 oazs.NIOServerCnxnFactory.configure binding to = port 0.0.0.0/0.0.0.0:0 [junit4:junit4] 2> 10 T351 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to= /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/b= uild/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1363= 272769277/zookeeper/server1/data/version-2/snapshot.0 [junit4:junit4] 2> 106 T350 oasc.ZkTestServer.run start zk server on port= :38144 [junit4:junit4] 2> 106 T350 oaz.ZooKeeper. Initiating client connec= tion, connectString=3D127.0.0.1:38144 sessionTimeout=3D10000 watcher=3Dorg.= apache.solr.common.cloud.ConnectionManager@1ebf98fa [junit4:junit4] 2> 107 T350 oascc.ConnectionManager.waitForConnected Wait= ing for client to connect to ZooKeeper [junit4:junit4] 2> 108 T356 oaz.ClientCnxn$SendThread.logStartConnect Ope= ning socket connection to server localhost/127.0.0.1:38144. Will not attemp= t to authenticate using SASL (access denied (javax.security.auth.AuthPermis= sion getLoginConfiguration)) [junit4:junit4] 2> 108 T356 oaz.ClientCnxn$SendThread.primeConnection Soc= ket connection established to localhost/127.0.0.1:38144, initiating session [junit4:junit4] 2> 109 T352 oazs.NIOServerCnxnFactory.run Accepted socket= connection from /140.211.11.196:38145 [junit4:junit4] 2> 109 T352 oazs.ZooKeeperServer.processConnectRequest Cl= ient attempting to establish new session at /140.211.11.196:38145 [junit4:junit4] 2> 109 T354 oazsp.FileTxnLog.append Creating new log file= : log.1 [junit4:junit4] 2> 112 T354 oazs.ZooKeeperServer.finishSessionInit Establ= ished session 0x13d69639f040000 with negotiated timeout 10000 for client /1= 40.211.11.196:38145 [junit4:junit4] 2> 112 T356 oaz.ClientCnxn$SendThread.onConnected Session= establishment complete on server localhost/127.0.0.1:38144, sessionid =3D = 0x13d69639f040000, negotiated timeout =3D 10000 [junit4:junit4] 2> 112 T357 oascc.ConnectionManager.process Watcher org.a= pache.solr.common.cloud.ConnectionManager@1ebf98fa name:ZooKeeperConnection= Watcher:127.0.0.1:38144 got event WatchedEvent state:SyncConnected type:No= ne path:null path:null type:None [junit4:junit4] 2> 113 T350 oascc.ConnectionManager.waitForConnected Clie= nt is connected to ZooKeeper [junit4:junit4] 2> 113 T350 oascc.SolrZkClient.makePath makePath: /solr [junit4:junit4] 2> 117 T355 oazs.PrepRequestProcessor.pRequest2Txn Proces= sed session termination for sessionid: 0x13d69639f040000 [junit4:junit4] 2> 129 T357 oaz.ClientCnxn$EventThread.run EventThread sh= ut down [junit4:junit4] 2> 129 T352 oazs.NIOServerCnxn.closeSock Closed socket co= nnection for client /140.211.11.196:38145 which had sessionid 0x13d69639f04= 0000 [junit4:junit4] 2> 129 T350 oaz.ZooKeeper.close Session: 0x13d69639f04000= 0 closed [junit4:junit4] 2> 130 T350 oaz.ZooKeeper. Initiating client connec= tion, connectString=3D127.0.0.1:38144/solr sessionTimeout=3D10000 watcher= =3Dorg.apache.solr.common.cloud.ConnectionManager@765b98f1 [junit4:junit4] 2> 131 T350 oascc.ConnectionManager.waitForConnected Wait= ing for client to connect to ZooKeeper [junit4:junit4] 2> 131 T358 oaz.ClientCnxn$SendThread.logStartConnect Ope= ning socket connection to server localhost/127.0.0.1:38144. Will not attemp= t to authenticate using SASL (access denied (javax.security.auth.AuthPermis= sion getLoginConfiguration)) [junit4:junit4] 2> 131 T358 oaz.ClientCnxn$SendThread.primeConnection Soc= ket connection established to localhost/127.0.0.1:38144, initiating session [junit4:junit4] 2> 132 T352 oazs.NIOServerCnxnFactory.run Accepted socket= connection from /140.211.11.196:38146 [junit4:junit4] 2> 132 T352 oazs.ZooKeeperServer.processConnectRequest Cl= ient attempting to establish new session at /140.211.11.196:38146 [junit4:junit4] 2> 133 T354 oazs.ZooKeeperServer.finishSessionInit Establ= ished session 0x13d69639f040001 with negotiated timeout 10000 for client /1= 40.211.11.196:38146 [junit4:junit4] 2> 133 T358 oaz.ClientCnxn$SendThread.onConnected Session= establishment complete on server localhost/127.0.0.1:38144, sessionid =3D = 0x13d69639f040001, negotiated timeout =3D 10000 [junit4:junit4] 2> 134 T359 oascc.ConnectionManager.process Watcher org.a= pache.solr.common.cloud.ConnectionManager@765b98f1 name:ZooKeeperConnection= Watcher:127.0.0.1:38144/solr got event WatchedEvent state:SyncConnected ty= pe:None path:null path:null type:None [junit4:junit4] 2> 134 T350 oascc.ConnectionManager.waitForConnected Clie= nt is connected to ZooKeeper [junit4:junit4] 2> 134 T350 oascc.SolrZkClient.makePath makePath: /collec= tions/collection1 [junit4:junit4] 2> 139 T350 oascc.SolrZkClient.makePath makePath: /collec= tions/collection1/shards [junit4:junit4] 2> 143 T350 oascc.SolrZkClient.makePath makePath: /collec= tions/control_collection [junit4:junit4] 2> 146 T350 oascc.SolrZkClient.makePath makePath: /collec= tions/control_collection/shards [junit4:junit4] 2> 150 T350 oasc.AbstractZkTestCase.putConfig put /usr/ho= me/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/sol= r-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/con= f1/solrconfig.xml [junit4:junit4] 2> 152 T350 oascc.SolrZkClient.makePath makePath: /config= s/conf1/solrconfig.xml [junit4:junit4] 2> 160 T350 oasc.AbstractZkTestCase.putConfig put /usr/ho= me/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/sol= r-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema= .xml [junit4:junit4] 2> 163 T350 oascc.SolrZkClient.makePath makePath: /config= s/conf1/schema.xml [junit4:junit4] 2> 169 T350 oasc.AbstractZkTestCase.putConfig put /usr/ho= me/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/sol= r-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/sto= pwords.txt [junit4:junit4] 2> 170 T350 oascc.SolrZkClient.makePath makePath: /config= s/conf1/stopwords.txt [junit4:junit4] 2> 175 T350 oasc.AbstractZkTestCase.putConfig put /usr/ho= me/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/sol= r-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/pro= twords.txt [junit4:junit4] 2> 176 T350 oascc.SolrZkClient.makePath makePath: /config= s/conf1/protwords.txt [junit4:junit4] 2> 180 T350 oasc.AbstractZkTestCase.putConfig put /usr/ho= me/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/sol= r-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/curr= ency.xml [junit4:junit4] 2> 181 T350 oascc.SolrZkClient.makePath makePath: /config= s/conf1/currency.xml [junit4:junit4] 2> 186 T350 oasc.AbstractZkTestCase.putConfig put /usr/ho= me/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/sol= r-core/test-files/solr/collection1/conf/open-exchange-rates.json to /config= s/conf1/open-exchange-rates.json [junit4:junit4] 2> 187 T350 oascc.SolrZkClient.makePath makePath: /config= s/conf1/open-exchange-rates.json [junit4:junit4] 2> 191 T350 oasc.AbstractZkTestCase.putConfig put /usr/ho= me/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/sol= r-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /con= figs/conf1/mapping-ISOLatin1Accent.txt [junit4:junit4] 2> 192 T350 oascc.SolrZkClient.makePath makePath: /config= s/conf1/mapping-ISOLatin1Accent.txt [junit4:junit4] 2> 196 T350 oasc.AbstractZkTestCase.putConfig put /usr/ho= me/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/sol= r-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/= old_synonyms.txt [junit4:junit4] 2> 197 T350 oascc.SolrZkClient.makePath makePath: /config= s/conf1/old_synonyms.txt [junit4:junit4] 2> 205 T350 oasc.AbstractZkTestCase.putConfig put /usr/ho= me/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/sol= r-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/syno= nyms.txt [junit4:junit4] 2> 205 T350 oascc.SolrZkClient.makePath makePath: /config= s/conf1/synonyms.txt [junit4:junit4] 2> 213 T355 oazs.PrepRequestProcessor.pRequest2Txn Proces= sed session termination for sessionid: 0x13d69639f040001 [junit4:junit4] 2> 214 T352 oazs.NIOServerCnxn.closeSock Closed socket co= nnection for client /140.211.11.196:38146 which had sessionid 0x13d69639f04= 0001 [junit4:junit4] 2> 215 T359 oaz.ClientCnxn$EventThread.run EventThread sh= ut down [junit4:junit4] 2> 215 T350 oaz.ZooKeeper.close Session: 0x13d69639f04000= 1 closed [junit4:junit4] 2> 389 T350 oejs.Server.doStart jetty-8.1.8.v20121106 [junit4:junit4] 2> 403 T350 oejs.AbstractConnector.doStart Started Socket= Connector@127.0.0.1:38147 [junit4:junit4] 2> 404 T350 oass.SolrDispatchFilter.init SolrDispatchFilt= er.init() [junit4:junit4] 2> 404 T350 oasc.SolrResourceLoader.locateSolrHome JNDI n= ot configured for solr (NoInitialContextEx) [junit4:junit4] 2> 405 T350 oasc.SolrResourceLoader.locateSolrHome using = system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Luc= ene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.clo= ud.BasicDistributedZk2Test-controljetty-1363272769489 [junit4:junit4] 2> 405 T350 oasc.CoreContainer$Initializer.initialize loo= king for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-S= olr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Ba= sicDistributedZk2Test-controljetty-1363272769489/solr.xml [junit4:junit4] 2> 405 T350 oasc.CoreContainer. New CoreContainer 1= 639745438 [junit4:junit4] 2> 406 T350 oasc.CoreContainer.load Loading CoreContainer= using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Test= s-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistr= ibutedZk2Test-controljetty-1363272769489/' [junit4:junit4] 2> 406 T350 oasc.SolrResourceLoader. new SolrResour= ceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Basi= cDistributedZk2Test-controljetty-1363272769489/' [junit4:junit4] 2> 473 T350 oashc.HttpShardHandlerFactory.getParameter Se= tting socketTimeout to: 120000 [junit4:junit4] 2> 474 T350 oashc.HttpShardHandlerFactory.getParameter Se= tting urlScheme to: http:// [junit4:junit4] 2> 474 T350 oashc.HttpShardHandlerFactory.getParameter Se= tting connTimeout to: 15000 [junit4:junit4] 2> 475 T350 oashc.HttpShardHandlerFactory.getParameter Se= tting maxConnectionsPerHost to: 20 [junit4:junit4] 2> 475 T350 oashc.HttpShardHandlerFactory.getParameter Se= tting corePoolSize to: 0 [junit4:junit4] 2> 476 T350 oashc.HttpShardHandlerFactory.getParameter Se= tting maximumPoolSize to: 2147483647 [junit4:junit4] 2> 476 T350 oashc.HttpShardHandlerFactory.getParameter Se= tting maxThreadIdleTime to: 5 [junit4:junit4] 2> 477 T350 oashc.HttpShardHandlerFactory.getParameter Se= tting sizeOfQueue to: -1 [junit4:junit4] 2> 477 T350 oashc.HttpShardHandlerFactory.getParameter Se= tting fairnessPolicy to: false [junit4:junit4] 2> 478 T350 oascsi.HttpClientUtil.createClient Creating n= ew http client, config:maxConnectionsPerHost=3D20&maxConnections=3D10000&so= cketTimeout=3D120000&connTimeout=3D15000&retry=3Dfalse [junit4:junit4] 2> 510 T350 oasc.CoreContainer.load Registering Log Liste= ner [junit4:junit4] 2> 541 T350 oasc.CoreContainer.initZooKeeper Zookeeper cl= ient=3D127.0.0.1:38144/solr [junit4:junit4] 2> 542 T350 oasc.ZkController.checkChrootPath zkHost incl= udes chroot [junit4:junit4] 2> 543 T350 oaz.ZooKeeper. Initiating client connec= tion, connectString=3D127.0.0.1:38144 sessionTimeout=3D60000 watcher=3Dorg.= apache.solr.common.cloud.ConnectionManager@429bdb78 [junit4:junit4] 2> 544 T350 oascc.ConnectionManager.waitForConnected Wait= ing for client to connect to ZooKeeper [junit4:junit4] 2> 544 T369 oaz.ClientCnxn$SendThread.logStartConnect Ope= ning socket connection to server localhost/127.0.0.1:38144. Will not attemp= t to authenticate using SASL (access denied (javax.security.auth.AuthPermis= sion getLoginConfiguration)) [junit4:junit4] 2> 545 T369 oaz.ClientCnxn$SendThread.primeConnection Soc= ket connection established to localhost/127.0.0.1:38144, initiating session [junit4:junit4] 2> 546 T352 oazs.NIOServerCnxnFactory.run Accepted socket= connection from /140.211.11.196:38148 [junit4:junit4] 2> 546 T352 oazs.ZooKeeperServer.processConnectRequest Cl= ient attempting to establish new session at /140.211.11.196:38148 [junit4:junit4] 2> 548 T354 oazs.ZooKeeperServer.finishSessionInit Establ= ished session 0x13d69639f040002 with negotiated timeout 20000 for client /1= 40.211.11.196:38148 [junit4:junit4] 2> 549 T369 oaz.ClientCnxn$SendThread.onConnected Session= establishment complete on server localhost/127.0.0.1:38144, sessionid =3D = 0x13d69639f040002, negotiated timeout =3D 20000 [junit4:junit4] 2> 549 T370 oascc.ConnectionManager.process Watcher org.a= pache.solr.common.cloud.ConnectionManager@429bdb78 name:ZooKeeperConnection= Watcher:127.0.0.1:38144 got event WatchedEvent state:SyncConnected type:No= ne path:null path:null type:None [junit4:junit4] 2> 549 T350 oascc.ConnectionManager.waitForConnected Clie= nt is connected to ZooKeeper [junit4:junit4] 2> 551 T355 oazs.PrepRequestProcessor.pRequest2Txn Proces= sed session termination for sessionid: 0x13d69639f040002 [junit4:junit4] 2> 560 T370 oaz.ClientCnxn$EventThread.run EventThread sh= ut down [junit4:junit4] 2> 560 T352 oazs.NIOServerCnxn.closeSock Closed socket co= nnection for client /140.211.11.196:38148 which had sessionid 0x13d69639f04= 0002 [junit4:junit4] 2> 559 T350 oaz.ZooKeeper.close Session: 0x13d69639f04000= 2 closed [junit4:junit4] 2> 561 T350 oascsi.HttpClientUtil.createClient Creating n= ew http client, config:maxConnections=3D500&maxConnectionsPerHost=3D16&sock= etTimeout=3D120000&connTimeout=3D15000 [junit4:junit4] 2> 576 T350 oaz.ZooKeeper. Initiating client connec= tion, connectString=3D127.0.0.1:38144/solr sessionTimeout=3D30000 watcher= =3Dorg.apache.solr.common.cloud.ConnectionManager@3fc1058a [junit4:junit4] 2> 578 T350 oascc.ConnectionManager.waitForConnected Wait= ing for client to connect to ZooKeeper [junit4:junit4] 2> 578 T371 oaz.ClientCnxn$SendThread.logStartConnect Ope= ning socket connection to server localhost/127.0.0.1:38144. Will not attemp= t to authenticate using SASL (access denied (javax.security.auth.AuthPermis= sion getLoginConfiguration)) [junit4:junit4] 2> 579 T371 oaz.ClientCnxn$SendThread.primeConnection Soc= ket connection established to localhost/127.0.0.1:38144, initiating session [junit4:junit4] 2> 579 T352 oazs.NIOServerCnxnFactory.run Accepted socket= connection from /140.211.11.196:38149 [junit4:junit4] 2> 580 T352 oazs.ZooKeeperServer.processConnectRequest Cl= ient attempting to establish new session at /140.211.11.196:38149 [junit4:junit4] 2> 581 T354 oazs.ZooKeeperServer.finishSessionInit Establ= ished session 0x13d69639f040003 with negotiated timeout 20000 for client /1= 40.211.11.196:38149 [junit4:junit4] 2> 582 T371 oaz.ClientCnxn$SendThread.onConnected Session= establishment complete on server localhost/127.0.0.1:38144, sessionid =3D = 0x13d69639f040003, negotiated timeout =3D 20000 [junit4:junit4] 2> 582 T372 oascc.ConnectionManager.process Watcher org.a= pache.solr.common.cloud.ConnectionManager@3fc1058a name:ZooKeeperConnection= Watcher:127.0.0.1:38144/solr got event WatchedEvent state:SyncConnected ty= pe:None path:null path:null type:None [junit4:junit4] 2> 582 T350 oascc.ConnectionManager.waitForConnected Clie= nt is connected to ZooKeeper [junit4:junit4] 2> 585 T355 oazs.PrepRequestProcessor.pRequest Got user-l= evel KeeperException when processing sessionid:0x13d69639f040003 type:creat= e cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error= :KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 595 T350 oascc.SolrZkClient.makePath makePath: /live_n= odes [junit4:junit4] 2> 599 T350 oasc.ZkController.createEphemeralLiveNode Reg= ister node as live in ZooKeeper:/live_nodes/127.0.0.1:38147_muhkb%2Fmb [junit4:junit4] 2> 600 T355 oazs.PrepRequestProcessor.pRequest Got user-l= evel KeeperException when processing sessionid:0x13d69639f040003 type:delet= e cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127= .0.0.1:38147_muhkb%2Fmb Error:KeeperErrorCode =3D NoNode for /solr/live_nod= es/127.0.0.1:38147_muhkb%2Fmb [junit4:junit4] 2> 601 T350 oascc.SolrZkClient.makePath makePath: /live_n= odes/127.0.0.1:38147_muhkb%2Fmb [junit4:junit4] 2> 607 T350 oascc.SolrZkClient.makePath makePath: /overse= er_elect/election [junit4:junit4] 2> 622 T355 oazs.PrepRequestProcessor.pRequest Got user-l= evel KeeperException when processing sessionid:0x13d69639f040003 type:delet= e cxid:0x16 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elec= t/leader Error:KeeperErrorCode =3D NoNode for /solr/overseer_elect/leader [junit4:junit4] 2> 623 T350 oascc.SolrZkClient.makePath makePath: /overse= er_elect/leader [junit4:junit4] 2> 627 T350 oasc.Overseer.start Overseer (id=3D8934344420= 7796227-127.0.0.1:38147_muhkb%2Fmb-n_0000000000) starting [junit4:junit4] 2> 629 T355 oazs.PrepRequestProcessor.pRequest Got user-l= evel KeeperException when processing sessionid:0x13d69639f040003 type:creat= e cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Erro= r:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 630 T355 oazs.PrepRequestProcessor.pRequest Got user-l= evel KeeperException when processing sessionid:0x13d69639f040003 type:creat= e cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Erro= r:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 632 T355 oazs.PrepRequestProcessor.pRequest Got user-l= evel KeeperException when processing sessionid:0x13d69639f040003 type:creat= e cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Erro= r:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 641 T355 oazs.PrepRequestProcessor.pRequest Got user-l= evel KeeperException when processing sessionid:0x13d69639f040003 type:creat= e cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Erro= r:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 643 T374 oasc.OverseerCollectionProcessor.run Process = current queue of collection creations [junit4:junit4] 2> 644 T350 oascc.SolrZkClient.makePath makePath: /cluste= rstate.json [junit4:junit4] 2> 652 T350 oascc.SolrZkClient.makePath makePath: /aliase= s.json [junit4:junit4] 2> 656 T350 oascc.ZkStateReader.createClusterStateWatcher= sAndUpdate Updating cluster state from ZooKeeper...=20 [junit4:junit4] 2> 661 T373 oasc.Overseer$ClusterStateUpdater.run Startin= g to work on the main queue [junit4:junit4] 2> 680 T375 oasc.CoreContainer.create Creating SolrCore '= collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Luc= ene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.clo= ud.BasicDistributedZk2Test-controljetty-1363272769489/collection1 [junit4:junit4] 2> 681 T375 oasc.ZkController.createCollectionZkNode Chec= k for collection zkNode:control_collection [junit4:junit4] 2> 682 T375 oasc.ZkController.createCollectionZkNode Coll= ection zkNode exists [junit4:junit4] 2> 683 T375 oasc.ZkController.readConfigName Load collect= ion config from:/collections/control_collection [junit4:junit4] 2> 685 T375 oasc.SolrResourceLoader. new SolrResour= ceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Sol= r-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Basi= cDistributedZk2Test-controljetty-1363272769489/collection1/' [junit4:junit4] 2> 686 T375 oasc.SolrResourceLoader.replaceClassLoader Ad= ding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Ja= va6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2T= est-controljetty-1363272769489/collection1/lib/classes/' to classloader [junit4:junit4] 2> 687 T375 oasc.SolrResourceLoader.replaceClassLoader Ad= ding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Ja= va6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2T= est-controljetty-1363272769489/collection1/lib/README' to classloader [junit4:junit4] 2> 743 T375 oasc.SolrConfig. Using Lucene MatchVers= ion: LUCENE_43 [junit4:junit4] 2> 813 T375 oasc.SolrConfig. Loaded SolrConfig: sol= rconfig.xml [junit4:junit4] 2> 814 T375 oass.IndexSchema.readSchema Reading Solr Sche= ma [junit4:junit4] 2> 824 T375 oass.IndexSchema.readSchema Schema name=3Dtes= t [junit4:junit4] 2> 1516 T375 oass.OpenExchangeRatesOrgProvider.init Initi= alized with rates=3Dopen-exchange-rates.json, refreshInterval=3D1440. [junit4:junit4] 2> 1524 T375 oass.IndexSchema.readSchema default search f= ield in schema is text [junit4:junit4] 2> 1527 T375 oass.IndexSchema.readSchema unique key field= : id [junit4:junit4] 2> 1546 T375 oass.FileExchangeRateProvider.reload Reloadi= ng exchange rates from file currency.xml [junit4:junit4] 2> 1551 T375 oass.FileExchangeRateProvider.reload Reloadi= ng exchange rates from file currency.xml [junit4:junit4] 2> 1554 T375 oass.OpenExchangeRatesOrgProvider.reload Rel= oading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 1556 T375 oass.OpenExchangeRatesOrgProvider$OpenExchan= geRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 1556 T375 oass.OpenExchangeRatesOrgProvider$OpenExchan= geRates. WARNING Expected key, got STRING [junit4:junit4] 2> 1556 T375 oass.OpenExchangeRatesOrgProvider.reload Rel= oading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 1557 T375 oass.OpenExchangeRatesOrgProvider$OpenExchan= geRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 1558 T375 oass.OpenExchangeRatesOrgProvider$OpenExchan= geRates. WARNING Expected key, got STRING [junit4:junit4] 2> 1558 T375 oasc.SolrCore.initDirectoryFactory org.apach= e.solr.core.MockDirectoryFactory [junit4:junit4] 2> 1558 T375 oasc.SolrCore. [collection1] Opening n= ew SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.= x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistribut= edZk2Test-controljetty-1363272769489/collection1/, dataDir=3D./org.apache.s= olr.cloud.BasicDistributedZk2Test-1363272769277/control/data/ [junit4:junit4] 2> 1558 T375 oasc.JmxMonitoredMap. JMX monitoring i= s enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBe= anServer@3dbe8711 [junit4:junit4] 2> 1559 T375 oasc.SolrCore.initDirectoryFactory org.apach= e.solr.core.MockDirectoryFactory [junit4:junit4] 2> 1559 T375 oasc.CachingDirectoryFactory.get return new = directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363272769277= /control/data forceNew: false [junit4:junit4] 2> 1559 T375 oasc.SolrCore.getNewIndexDir New index direc= tory detected: old=3Dnull new=3D./org.apache.solr.cloud.BasicDistributedZk2= Test-1363272769277/control/data/index/ [junit4:junit4] 2> 1559 T375 oasc.SolrCore.initIndex WARNING [collection1= ] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-136= 3272769277/control/data/index' doesn't exist. Creating new index... [junit4:junit4] 2> 1560 T375 oasc.CachingDirectoryFactory.get return new = directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363272769277= /control/data/index forceNew: false [junit4:junit4] 2> 1563 T375 oasc.SolrDeletionPolicy.onCommit SolrDeletio= nPolicy.onCommit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@8f9c09e lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@6e045e81),segFN=3Dsegments_1,generation=3D1,filenames=3D[segm= ents_1] [junit4:junit4] 2> 1563 T375 oasc.SolrDeletionPolicy.updateCommits newest= commit =3D 1[segments_1] [junit4:junit4] 2> 1564 T375 oasup.UpdateRequestProcessorChain.init inser= ting DistributedUpdateProcessorFactory into updateRequestProcessorChain "de= dupe" [junit4:junit4] 2> 1565 T375 oasup.UpdateRequestProcessorChain.init inser= ting DistributedUpdateProcessorFactory into updateRequestProcessorChain "st= ored_sig" [junit4:junit4] 2> 1565 T375 oasup.UpdateRequestProcessorChain.init inser= ting DistributedUpdateProcessorFactory into updateRequestProcessorChain "di= strib-dup-test-chain-implicit" [junit4:junit4] 2> 1565 T375 oasc.RequestHandlers.initHandlersFromConfig = created standard: solr.StandardRequestHandler [junit4:junit4] 2> 1566 T375 oasc.RequestHandlers.initHandlersFromConfig = created /get: solr.RealTimeGetHandler [junit4:junit4] 2> 1566 T375 oasc.RequestHandlers.initHandlersFromConfig = adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 2> 1566 T375 oasc.RequestHandlers.initHandlersFromConfig = created /replication: solr.ReplicationHandler [junit4:junit4] 2> 1566 T375 oasc.RequestHandlers.initHandlersFromConfig = created /update: solr.UpdateRequestHandler [junit4:junit4] 2> 1567 T375 oasc.RequestHandlers.initHandlersFromConfig = created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4:junit4] 2> 1571 T375 oashl.XMLLoader.init xsltCacheLifetimeSecond= s=3D60 [junit4:junit4] 2> 1575 T375 oass.SolrIndexSearcher. Opening Search= er@64fbccad main [junit4:junit4] 2> 1575 T375 oasu.UpdateHandler.clearLog Clearing tlog fi= les, tlogDir=3D./org.apache.solr.cloud.BasicDistributedZk2Test-136327276927= 7/control/data/tlog [junit4:junit4] 2> 1576 T375 oasu.CommitTracker. Hard AutoCommit: d= isabled [junit4:junit4] 2> 1576 T375 oasu.CommitTracker. Soft AutoCommit: d= isabled [junit4:junit4] 2> 1578 T376 oasc.SolrCore.registerSearcher [collection1]= Registered new searcher Searcher@64fbccad main{StandardDirectoryReader(seg= ments_1:1)} [junit4:junit4] 2> 1579 T375 oasc.ZkController.publish publishing core=3D= collection1 state=3Ddown [junit4:junit4] 2> 1580 T375 oasc.ZkController.publish numShards not foun= d on descriptor - reading it from system property [junit4:junit4] 2> 1580 T355 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d69639f040003 type:crea= te cxid:0x55 zxid:0x2a txntype:-1 reqpath:n/a Error Path:/solr/overseer/que= ue Error:KeeperErrorCode =3D NoNode for /solr/overseer/queue [junit4:junit4] 2> 2169 T373 oascc.ZkStateReader.updateClusterState Updat= ing cloud state from ZooKeeper...=20 [junit4:junit4] 2> 2170 T373 oasc.Overseer$ClusterStateUpdater.updateStat= e Update state numShards=3D1 message=3D{ [junit4:junit4] 2> =09 "operation":"state", [junit4:junit4] 2> =09 "core_node_name":"1", [junit4:junit4] 2> =09 "numShards":"1", [junit4:junit4] 2> =09 "shard":null, [junit4:junit4] 2> =09 "roles":null, [junit4:junit4] 2> =09 "state":"down", [junit4:junit4] 2> =09 "core":"collection1", [junit4:junit4] 2> =09 "collection":"control_collection", [junit4:junit4] 2> =09 "node_name":"127.0.0.1:38147_muhkb%2Fmb", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:38147/muhkb/mb"} [junit4:junit4] 2> 2170 T373 oasc.Overseer$ClusterStateUpdater.createColl= ection Create collection control_collection with numShards 1 [junit4:junit4] 2> 2182 T373 oasc.Overseer$ClusterStateUpdater.updateStat= e Assigning new node to shard shard=3Dshard1 [junit4:junit4] 2> 2184 T355 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d69639f040003 type:crea= te cxid:0x5d zxid:0x2d txntype:-1 reqpath:n/a Error Path:/solr/overseer/que= ue-work Error:KeeperErrorCode =3D NoNode for /solr/overseer/queue-work [junit4:junit4] 2> 2205 T372 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 1) [junit4:junit4] 2> 2603 T375 oasc.CoreContainer.registerCore registering = core: collection1 [junit4:junit4] 2> 2603 T375 oasc.ZkController.register Register replica = - core:collection1 address:http://127.0.0.1:38147/muhkb/mb collection:contr= ol_collection shard:shard1 [junit4:junit4] 2> 2604 T375 oascc.SolrZkClient.makePath makePath: /colle= ctions/control_collection/leader_elect/shard1/election [junit4:junit4] 2> 2679 T355 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d69639f040003 type:dele= te cxid:0x77 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/collections/= control_collection/leaders Error:KeeperErrorCode =3D NoNode for /solr/colle= ctions/control_collection/leaders [junit4:junit4] 2> 2697 T375 oasc.ShardLeaderElectionContext.runLeaderPro= cess Running the leader process. [junit4:junit4] 2> 2698 T355 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d69639f040003 type:crea= te cxid:0x78 zxid:0x38 txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 2757 T375 oasc.ShardLeaderElectionContext.waitForRepli= casToComeUp Enough replicas found to continue. [junit4:junit4] 2> 2757 T375 oasc.ShardLeaderElectionContext.runLeaderPro= cess I may be the new leader - try and sync [junit4:junit4] 2> 2758 T375 oasc.SyncStrategy.sync Sync replicas to http= ://127.0.0.1:38147/muhkb/mb/collection1/ [junit4:junit4] 2> 2758 T375 oasc.SyncStrategy.syncReplicas Sync Success = - now sync replicas to me [junit4:junit4] 2> 2758 T375 oasc.SyncStrategy.syncToMe http://127.0.0.1:= 38147/muhkb/mb/collection1/ has no replicas [junit4:junit4] 2> 2758 T375 oasc.ShardLeaderElectionContext.runLeaderPro= cess I am the new leader: http://127.0.0.1:38147/muhkb/mb/collection1/ [junit4:junit4] 2> 2759 T375 oascc.SolrZkClient.makePath makePath: /colle= ctions/control_collection/leaders/shard1 [junit4:junit4] 2> 2766 T355 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d69639f040003 type:crea= te cxid:0x82 zxid:0x3c txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 3715 T373 oascc.ZkStateReader.updateClusterState Updat= ing cloud state from ZooKeeper...=20 [junit4:junit4] 2> 3769 T372 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 1) [junit4:junit4] 2> 3814 T375 oasc.ZkController.register We are http://127= .0.0.1:38147/muhkb/mb/collection1/ and leader is http://127.0.0.1:38147/muh= kb/mb/collection1/ [junit4:junit4] 2> 3814 T375 oasc.ZkController.register No LogReplay need= ed for core=3Dcollection1 baseURL=3Dhttp://127.0.0.1:38147/muhkb/mb [junit4:junit4] 2> 3814 T375 oasc.ZkController.checkRecovery I am the lea= der, no recovery necessary [junit4:junit4] 2> 3815 T375 oasc.ZkController.publish publishing core=3D= collection1 state=3Dactive [junit4:junit4] 2> 3815 T375 oasc.ZkController.publish numShards not foun= d on descriptor - reading it from system property [junit4:junit4] 2> 3818 T375 oascc.ZkStateReader.updateClusterState Updat= ing cloud state from ZooKeeper...=20 [junit4:junit4] 2> 3820 T350 oass.SolrDispatchFilter.init user.dir=3D/usr= /home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/= solr-core/test/J1 [junit4:junit4] 2> 3821 T350 oass.SolrDispatchFilter.init SolrDispatchFil= ter.init() done [junit4:junit4] 2> 3821 T350 oascsi.HttpClientUtil.createClient Creating = new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&fol= lowRedirects=3Dfalse [junit4:junit4] 2> 3843 T350 oascsi.HttpClientUtil.createClient Creating = new http client, config: [junit4:junit4] 2> 3850 T350 oaz.ZooKeeper. Initiating client conne= ction, connectString=3D127.0.0.1:38144/solr sessionTimeout=3D10000 watcher= =3Dorg.apache.solr.common.cloud.ConnectionManager@d8e8e7f [junit4:junit4] 2> 3851 T350 oascc.ConnectionManager.waitForConnected Wai= ting for client to connect to ZooKeeper [junit4:junit4] 2> 3852 T378 oaz.ClientCnxn$SendThread.logStartConnect Op= ening socket connection to server localhost/127.0.0.1:38144. Will not attem= pt to authenticate using SASL (access denied (javax.security.auth.AuthPermi= ssion getLoginConfiguration)) [junit4:junit4] 2> 3852 T378 oaz.ClientCnxn$SendThread.primeConnection So= cket connection established to localhost/127.0.0.1:38144, initiating sessio= n [junit4:junit4] 2> 3852 T352 oazs.NIOServerCnxnFactory.run Accepted socke= t connection from /140.211.11.196:38150 [junit4:junit4] 2> 3853 T352 oazs.ZooKeeperServer.processConnectRequest C= lient attempting to establish new session at /140.211.11.196:38150 [junit4:junit4] 2> 3855 T354 oazs.ZooKeeperServer.finishSessionInit Estab= lished session 0x13d69639f040004 with negotiated timeout 10000 for client /= 140.211.11.196:38150 [junit4:junit4] 2> 3855 T378 oaz.ClientCnxn$SendThread.onConnected Sessio= n establishment complete on server localhost/127.0.0.1:38144, sessionid =3D= 0x13d69639f040004, negotiated timeout =3D 10000 [junit4:junit4] 2> 3856 T379 oascc.ConnectionManager.process Watcher org.= apache.solr.common.cloud.ConnectionManager@d8e8e7f name:ZooKeeperConnection= Watcher:127.0.0.1:38144/solr got event WatchedEvent state:SyncConnected ty= pe:None path:null path:null type:None [junit4:junit4] 2> 3856 T350 oascc.ConnectionManager.waitForConnected Cli= ent is connected to ZooKeeper [junit4:junit4] 2> 3858 T350 oascc.ZkStateReader.createClusterStateWatche= rsAndUpdate Updating cluster state from ZooKeeper...=20 [junit4:junit4] 2> 3864 T350 oasc.ChaosMonkey.monkeyLog monkey: init - ex= pire sessions:true cause connection loss:true [junit4:junit4] 2> 4059 T350 oejs.Server.doStart jetty-8.1.8.v20121106 [junit4:junit4] 2> 4061 T350 oejs.AbstractConnector.doStart Started Socke= tConnector@127.0.0.1:38151 [junit4:junit4] 2> 4062 T350 oass.SolrDispatchFilter.init SolrDispatchFil= ter.init() [junit4:junit4] 2> 4063 T350 oasc.SolrResourceLoader.locateSolrHome JNDI = not configured for solr (NoInitialContextEx) [junit4:junit4] 2> 4063 T350 oasc.SolrResourceLoader.locateSolrHome using= system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cl= oud.BasicDistributedZk2Test-jetty1-1363272773137 [junit4:junit4] 2> 4063 T350 oasc.CoreContainer$Initializer.initialize lo= oking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-= Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.B= asicDistributedZk2Test-jetty1-1363272773137/solr.xml [junit4:junit4] 2> 4064 T350 oasc.CoreContainer. New CoreContainer = 456751011 [junit4:junit4] 2> 4065 T350 oasc.CoreContainer.load Loading CoreContaine= r using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tes= ts-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDist= ributedZk2Test-jetty1-1363272773137/' [junit4:junit4] 2> 4065 T350 oasc.SolrResourceLoader. new SolrResou= rceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-So= lr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Bas= icDistributedZk2Test-jetty1-1363272773137/' [junit4:junit4] 2> 4117 T350 oashc.HttpShardHandlerFactory.getParameter S= etting socketTimeout to: 120000 [junit4:junit4] 2> 4118 T350 oashc.HttpShardHandlerFactory.getParameter S= etting urlScheme to: http:// [junit4:junit4] 2> 4118 T350 oashc.HttpShardHandlerFactory.getParameter S= etting connTimeout to: 15000 [junit4:junit4] 2> 4119 T350 oashc.HttpShardHandlerFactory.getParameter S= etting maxConnectionsPerHost to: 20 [junit4:junit4] 2> 4119 T350 oashc.HttpShardHandlerFactory.getParameter S= etting corePoolSize to: 0 [junit4:junit4] 2> 4120 T350 oashc.HttpShardHandlerFactory.getParameter S= etting maximumPoolSize to: 2147483647 [junit4:junit4] 2> 4120 T350 oashc.HttpShardHandlerFactory.getParameter S= etting maxThreadIdleTime to: 5 [junit4:junit4] 2> 4120 T350 oashc.HttpShardHandlerFactory.getParameter S= etting sizeOfQueue to: -1 [junit4:junit4] 2> 4121 T350 oashc.HttpShardHandlerFactory.getParameter S= etting fairnessPolicy to: false [junit4:junit4] 2> 4121 T350 oascsi.HttpClientUtil.createClient Creating = new http client, config:maxConnectionsPerHost=3D20&maxConnections=3D10000&s= ocketTimeout=3D120000&connTimeout=3D15000&retry=3Dfalse [junit4:junit4] 2> 4143 T350 oasc.CoreContainer.load Registering Log List= ener [junit4:junit4] 2> 4163 T350 oasc.CoreContainer.initZooKeeper Zookeeper c= lient=3D127.0.0.1:38144/solr [junit4:junit4] 2> 4163 T350 oasc.ZkController.checkChrootPath zkHost inc= ludes chroot [junit4:junit4] 2> 4164 T350 oaz.ZooKeeper. Initiating client conne= ction, connectString=3D127.0.0.1:38144 sessionTimeout=3D60000 watcher=3Dorg= .apache.solr.common.cloud.ConnectionManager@5c0b4e04 [junit4:junit4] 2> 4165 T350 oascc.ConnectionManager.waitForConnected Wai= ting for client to connect to ZooKeeper [junit4:junit4] 2> 4165 T389 oaz.ClientCnxn$SendThread.logStartConnect Op= ening socket connection to server localhost/127.0.0.1:38144. Will not attem= pt to authenticate using SASL (access denied (javax.security.auth.AuthPermi= ssion getLoginConfiguration)) [junit4:junit4] 2> 4166 T389 oaz.ClientCnxn$SendThread.primeConnection So= cket connection established to localhost/127.0.0.1:38144, initiating sessio= n [junit4:junit4] 2> 4167 T352 oazs.NIOServerCnxnFactory.run Accepted socke= t connection from /140.211.11.196:38152 [junit4:junit4] 2> 4167 T352 oazs.ZooKeeperServer.processConnectRequest C= lient attempting to establish new session at /140.211.11.196:38152 [junit4:junit4] 2> 4169 T354 oazs.ZooKeeperServer.finishSessionInit Estab= lished session 0x13d69639f040005 with negotiated timeout 20000 for client /= 140.211.11.196:38152 [junit4:junit4] 2> 4169 T389 oaz.ClientCnxn$SendThread.onConnected Sessio= n establishment complete on server localhost/127.0.0.1:38144, sessionid =3D= 0x13d69639f040005, negotiated timeout =3D 20000 [junit4:junit4] 2> 4170 T390 oascc.ConnectionManager.process Watcher org.= apache.solr.common.cloud.ConnectionManager@5c0b4e04 name:ZooKeeperConnectio= n Watcher:127.0.0.1:38144 got event WatchedEvent state:SyncConnected type:N= one path:null path:null type:None [junit4:junit4] 2> 4170 T350 oascc.ConnectionManager.waitForConnected Cli= ent is connected to ZooKeeper [junit4:junit4] 2> 4172 T355 oazs.PrepRequestProcessor.pRequest2Txn Proce= ssed session termination for sessionid: 0x13d69639f040005 [junit4:junit4] 2> 4186 T390 oaz.ClientCnxn$EventThread.run EventThread s= hut down [junit4:junit4] 2> 4186 T352 oazs.NIOServerCnxn.closeSock Closed socket c= onnection for client /140.211.11.196:38152 which had sessionid 0x13d69639f0= 40005 [junit4:junit4] 2> 4186 T350 oaz.ZooKeeper.close Session: 0x13d69639f0400= 05 closed [junit4:junit4] 2> 4187 T350 oascsi.HttpClientUtil.createClient Creating = new http client, config:maxConnections=3D500&maxConnectionsPerHost=3D16&soc= ketTimeout=3D120000&connTimeout=3D15000 [junit4:junit4] 2> 4198 T350 oaz.ZooKeeper. Initiating client conne= ction, connectString=3D127.0.0.1:38144/solr sessionTimeout=3D30000 watcher= =3Dorg.apache.solr.common.cloud.ConnectionManager@6d9b3c58 [junit4:junit4] 2> 4199 T350 oascc.ConnectionManager.waitForConnected Wai= ting for client to connect to ZooKeeper [junit4:junit4] 2> 4200 T391 oaz.ClientCnxn$SendThread.logStartConnect Op= ening socket connection to server localhost/127.0.0.1:38144. Will not attem= pt to authenticate using SASL (access denied (javax.security.auth.AuthPermi= ssion getLoginConfiguration)) [junit4:junit4] 2> 4200 T391 oaz.ClientCnxn$SendThread.primeConnection So= cket connection established to localhost/127.0.0.1:38144, initiating sessio= n [junit4:junit4] 2> 4201 T352 oazs.NIOServerCnxnFactory.run Accepted socke= t connection from /140.211.11.196:38153 [junit4:junit4] 2> 4201 T352 oazs.ZooKeeperServer.processConnectRequest C= lient attempting to establish new session at /140.211.11.196:38153 [junit4:junit4] 2> 4203 T354 oazs.ZooKeeperServer.finishSessionInit Estab= lished session 0x13d69639f040006 with negotiated timeout 20000 for client /= 140.211.11.196:38153 [junit4:junit4] 2> 4203 T391 oaz.ClientCnxn$SendThread.onConnected Sessio= n establishment complete on server localhost/127.0.0.1:38144, sessionid =3D= 0x13d69639f040006, negotiated timeout =3D 20000 [junit4:junit4] 2> 4203 T392 oascc.ConnectionManager.process Watcher org.= apache.solr.common.cloud.ConnectionManager@6d9b3c58 name:ZooKeeperConnectio= n Watcher:127.0.0.1:38144/solr got event WatchedEvent state:SyncConnected t= ype:None path:null path:null type:None [junit4:junit4] 2> 4203 T350 oascc.ConnectionManager.waitForConnected Cli= ent is connected to ZooKeeper [junit4:junit4] 2> 4205 T355 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d69639f040006 type:crea= te cxid:0x1 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Erro= r:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 4207 T355 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d69639f040006 type:crea= te cxid:0x2 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/overseer Erro= r:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 4216 T350 oascc.ZkStateReader.createClusterStateWatche= rsAndUpdate Updating cluster state from ZooKeeper...=20 [junit4:junit4] 2> 5229 T350 oasc.ZkController.createEphemeralLiveNode Re= gister node as live in ZooKeeper:/live_nodes/127.0.0.1:38151_muhkb%2Fmb [junit4:junit4] 2> 5230 T355 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d69639f040006 type:dele= te cxid:0xb zxid:0x4c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/12= 7.0.0.1:38151_muhkb%2Fmb Error:KeeperErrorCode =3D NoNode for /solr/live_no= des/127.0.0.1:38151_muhkb%2Fmb [junit4:junit4] 2> 5232 T350 oascc.SolrZkClient.makePath makePath: /live_= nodes/127.0.0.1:38151_muhkb%2Fmb [junit4:junit4] 2> 5237 T372 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/l= ive_nodes, has occurred - updating... (live nodes size: 1) [junit4:junit4] 2> 5238 T379 oascc.ZkStateReader$3.process Updating live = nodes... (2) [junit4:junit4] 2> 5238 T392 oascc.ZkStateReader$3.process Updating live = nodes... (2) [junit4:junit4] 2> 5239 T372 oascc.ZkStateReader$3.process Updating live = nodes... (2) [junit4:junit4] 2> 5253 T393 oasc.CoreContainer.create Creating SolrCore = 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cl= oud.BasicDistributedZk2Test-jetty1-1363272773137/collection1 [junit4:junit4] 2> 5253 T393 oasc.ZkController.createCollectionZkNode Che= ck for collection zkNode:collection1 [junit4:junit4] 2> 5254 T393 oasc.ZkController.createCollectionZkNode Col= lection zkNode exists [junit4:junit4] 2> 5254 T393 oasc.ZkController.readConfigName Load collec= tion config from:/collections/collection1 [junit4:junit4] 2> 5256 T393 oasc.SolrResourceLoader. new SolrResou= rceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-So= lr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Bas= icDistributedZk2Test-jetty1-1363272773137/collection1/' [junit4:junit4] 2> 5257 T393 oasc.SolrResourceLoader.replaceClassLoader A= dding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-J= ava6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2= Test-jetty1-1363272773137/collection1/lib/README' to classloader [junit4:junit4] 2> 5258 T393 oasc.SolrResourceLoader.replaceClassLoader A= dding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-J= ava6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2= Test-jetty1-1363272773137/collection1/lib/classes/' to classloader [junit4:junit4] 2> 5289 T373 oascc.ZkStateReader.updateClusterState Updat= ing cloud state from ZooKeeper...=20 [junit4:junit4] 2> 5290 T373 oasc.Overseer$ClusterStateUpdater.updateStat= e Update state numShards=3D1 message=3D{ [junit4:junit4] 2> =09 "operation":"state", [junit4:junit4] 2> =09 "core_node_name":"1", [junit4:junit4] 2> =09 "numShards":"1", [junit4:junit4] 2> =09 "shard":"shard1", [junit4:junit4] 2> =09 "roles":null, [junit4:junit4] 2> =09 "state":"active", [junit4:junit4] 2> =09 "core":"collection1", [junit4:junit4] 2> =09 "collection":"control_collection", [junit4:junit4] 2> =09 "node_name":"127.0.0.1:38147_muhkb%2Fmb", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:38147/muhkb/mb"} [junit4:junit4] 2> 5303 T379 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 5303 T372 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 5303 T392 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 5310 T393 oasc.SolrConfig. Using Lucene MatchVer= sion: LUCENE_43 [junit4:junit4] 2> 5369 T393 oasc.SolrConfig. Loaded SolrConfig: so= lrconfig.xml [junit4:junit4] 2> 5371 T393 oass.IndexSchema.readSchema Reading Solr Sch= ema [junit4:junit4] 2> 5378 T393 oass.IndexSchema.readSchema Schema name=3Dte= st [junit4:junit4] 2> 6069 T393 oass.OpenExchangeRatesOrgProvider.init Initi= alized with rates=3Dopen-exchange-rates.json, refreshInterval=3D1440. [junit4:junit4] 2> 6080 T393 oass.IndexSchema.readSchema default search f= ield in schema is text [junit4:junit4] 2> 6084 T393 oass.IndexSchema.readSchema unique key field= : id [junit4:junit4] 2> 6101 T393 oass.FileExchangeRateProvider.reload Reloadi= ng exchange rates from file currency.xml [junit4:junit4] 2> 6106 T393 oass.FileExchangeRateProvider.reload Reloadi= ng exchange rates from file currency.xml [junit4:junit4] 2> 6109 T393 oass.OpenExchangeRatesOrgProvider.reload Rel= oading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 6111 T393 oass.OpenExchangeRatesOrgProvider$OpenExchan= geRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 6111 T393 oass.OpenExchangeRatesOrgProvider$OpenExchan= geRates. WARNING Expected key, got STRING [junit4:junit4] 2> 6112 T393 oass.OpenExchangeRatesOrgProvider.reload Rel= oading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 6113 T393 oass.OpenExchangeRatesOrgProvider$OpenExchan= geRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 6113 T393 oass.OpenExchangeRatesOrgProvider$OpenExchan= geRates. WARNING Expected key, got STRING [junit4:junit4] 2> 6113 T393 oasc.SolrCore.initDirectoryFactory org.apach= e.solr.core.MockDirectoryFactory [junit4:junit4] 2> 6114 T393 oasc.SolrCore. [collection1] Opening n= ew SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.= x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistribut= edZk2Test-jetty1-1363272773137/collection1/, dataDir=3D./org.apache.solr.cl= oud.BasicDistributedZk2Test-1363272769277/jetty1/ [junit4:junit4] 2> 6114 T393 oasc.JmxMonitoredMap. JMX monitoring i= s enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBe= anServer@3dbe8711 [junit4:junit4] 2> 6114 T393 oasc.SolrCore.initDirectoryFactory org.apach= e.solr.core.MockDirectoryFactory [junit4:junit4] 2> 6115 T393 oasc.CachingDirectoryFactory.get return new = directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363272769277= /jetty1 forceNew: false [junit4:junit4] 2> 6115 T393 oasc.SolrCore.getNewIndexDir New index direc= tory detected: old=3Dnull new=3D./org.apache.solr.cloud.BasicDistributedZk2= Test-1363272769277/jetty1/index/ [junit4:junit4] 2> 6115 T393 oasc.SolrCore.initIndex WARNING [collection1= ] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-136= 3272769277/jetty1/index' doesn't exist. Creating new index... [junit4:junit4] 2> 6115 T393 oasc.CachingDirectoryFactory.get return new = directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363272769277= /jetty1/index forceNew: false [junit4:junit4] 2> 6117 T393 oasc.SolrDeletionPolicy.onCommit SolrDeletio= nPolicy.onCommit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@3f54b627 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@cf2e646),segFN=3Dsegments_1,generation=3D1,filenames=3D[segm= ents_1] [junit4:junit4] 2> 6118 T393 oasc.SolrDeletionPolicy.updateCommits newest= commit =3D 1[segments_1] [junit4:junit4] 2> 6119 T393 oasup.UpdateRequestProcessorChain.init inser= ting DistributedUpdateProcessorFactory into updateRequestProcessorChain "de= dupe" [junit4:junit4] 2> 6120 T393 oasup.UpdateRequestProcessorChain.init inser= ting DistributedUpdateProcessorFactory into updateRequestProcessorChain "st= ored_sig" [junit4:junit4] 2> 6120 T393 oasup.UpdateRequestProcessorChain.init inser= ting DistributedUpdateProcessorFactory into updateRequestProcessorChain "di= strib-dup-test-chain-implicit" [junit4:junit4] 2> 6120 T393 oasc.RequestHandlers.initHandlersFromConfig = created standard: solr.StandardRequestHandler [junit4:junit4] 2> 6121 T393 oasc.RequestHandlers.initHandlersFromConfig = created /get: solr.RealTimeGetHandler [junit4:junit4] 2> 6121 T393 oasc.RequestHandlers.initHandlersFromConfig = adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 2> 6121 T393 oasc.RequestHandlers.initHandlersFromConfig = created /replication: solr.ReplicationHandler [junit4:junit4] 2> 6122 T393 oasc.RequestHandlers.initHandlersFromConfig = created /update: solr.UpdateRequestHandler [junit4:junit4] 2> 6122 T393 oasc.RequestHandlers.initHandlersFromConfig = created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4:junit4] 2> 6127 T393 oashl.XMLLoader.init xsltCacheLifetimeSecond= s=3D60 [junit4:junit4] 2> 6132 T393 oass.SolrIndexSearcher. Opening Search= er@1ded8ee6 main [junit4:junit4] 2> 6132 T393 oasu.UpdateHandler.clearLog Clearing tlog fi= les, tlogDir=3D./org.apache.solr.cloud.BasicDistributedZk2Test-136327276927= 7/jetty1/tlog [junit4:junit4] 2> 6133 T393 oasu.CommitTracker. Hard AutoCommit: d= isabled [junit4:junit4] 2> 6133 T393 oasu.CommitTracker. Soft AutoCommit: d= isabled [junit4:junit4] 2> 6136 T394 oasc.SolrCore.registerSearcher [collection1]= Registered new searcher Searcher@1ded8ee6 main{StandardDirectoryReader(seg= ments_1:1)} [junit4:junit4] 2> 6138 T393 oasc.ZkController.publish publishing core=3D= collection1 state=3Ddown [junit4:junit4] 2> 6138 T393 oasc.ZkController.publish numShards not foun= d on descriptor - reading it from system property [junit4:junit4] 2> 6812 T373 oascc.ZkStateReader.updateClusterState Updat= ing cloud state from ZooKeeper...=20 [junit4:junit4] 2> 6813 T373 oasc.Overseer$ClusterStateUpdater.updateStat= e Update state numShards=3D2 message=3D{ [junit4:junit4] 2> =09 "operation":"state", [junit4:junit4] 2> =09 "core_node_name":"2", [junit4:junit4] 2> =09 "numShards":"2", [junit4:junit4] 2> =09 "shard":null, [junit4:junit4] 2> =09 "roles":null, [junit4:junit4] 2> =09 "state":"down", [junit4:junit4] 2> =09 "core":"collection1", [junit4:junit4] 2> =09 "collection":"collection1", [junit4:junit4] 2> =09 "node_name":"127.0.0.1:38151_muhkb%2Fmb", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:38151/muhkb/mb"} [junit4:junit4] 2> 6813 T373 oasc.Overseer$ClusterStateUpdater.createColl= ection Create collection collection1 with numShards 2 [junit4:junit4] 2> 6814 T373 oasc.Overseer$ClusterStateUpdater.updateStat= e Assigning new node to shard shard=3Dshard1 [junit4:junit4] 2> 6830 T392 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 6830 T379 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 6830 T372 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 7141 T393 oasc.CoreContainer.registerCore registering = core: collection1 [junit4:junit4] 2> 7141 T393 oasc.ZkController.register Register replica = - core:collection1 address:http://127.0.0.1:38151/muhkb/mb collection:colle= ction1 shard:shard1 [junit4:junit4] 2> 7142 T393 oascc.SolrZkClient.makePath makePath: /colle= ctions/collection1/leader_elect/shard1/election [junit4:junit4] 2> 7163 T355 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d69639f040006 type:dele= te cxid:0x48 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/collections/= collection1/leaders Error:KeeperErrorCode =3D NoNode for /solr/collections/= collection1/leaders [junit4:junit4] 2> 7164 T393 oasc.ShardLeaderElectionContext.runLeaderPro= cess Running the leader process. [junit4:junit4] 2> 7165 T355 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d69639f040006 type:crea= te cxid:0x49 zxid:0x5d txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 7168 T393 oasc.ShardLeaderElectionContext.waitForRepli= casToComeUp Enough replicas found to continue. [junit4:junit4] 2> 7168 T393 oasc.ShardLeaderElectionContext.runLeaderPro= cess I may be the new leader - try and sync [junit4:junit4] 2> 7169 T393 oasc.SyncStrategy.sync Sync replicas to http= ://127.0.0.1:38151/muhkb/mb/collection1/ [junit4:junit4] 2> 7169 T393 oasc.SyncStrategy.syncReplicas Sync Success = - now sync replicas to me [junit4:junit4] 2> 7170 T393 oasc.SyncStrategy.syncToMe http://127.0.0.1:= 38151/muhkb/mb/collection1/ has no replicas [junit4:junit4] 2> 7170 T393 oasc.ShardLeaderElectionContext.runLeaderPro= cess I am the new leader: http://127.0.0.1:38151/muhkb/mb/collection1/ [junit4:junit4] 2> 7171 T393 oascc.SolrZkClient.makePath makePath: /colle= ctions/collection1/leaders/shard1 [junit4:junit4] 2> 7181 T355 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d69639f040006 type:crea= te cxid:0x53 zxid:0x61 txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 8338 T373 oascc.ZkStateReader.updateClusterState Updat= ing cloud state from ZooKeeper...=20 [junit4:junit4] 2> 8365 T392 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 8365 T372 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 8365 T379 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 8408 T393 oasc.ZkController.register We are http://127= .0.0.1:38151/muhkb/mb/collection1/ and leader is http://127.0.0.1:38151/muh= kb/mb/collection1/ [junit4:junit4] 2> 8408 T393 oasc.ZkController.register No LogReplay need= ed for core=3Dcollection1 baseURL=3Dhttp://127.0.0.1:38151/muhkb/mb [junit4:junit4] 2> 8408 T393 oasc.ZkController.checkRecovery I am the lea= der, no recovery necessary [junit4:junit4] 2> 8409 T393 oasc.ZkController.publish publishing core=3D= collection1 state=3Dactive [junit4:junit4] 2> 8409 T393 oasc.ZkController.publish numShards not foun= d on descriptor - reading it from system property [junit4:junit4] 2> 8412 T393 oascc.ZkStateReader.updateClusterState Updat= ing cloud state from ZooKeeper...=20 [junit4:junit4] 2> 8414 T350 oass.SolrDispatchFilter.init user.dir=3D/usr= /home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/= solr-core/test/J1 [junit4:junit4] 2> 8415 T350 oass.SolrDispatchFilter.init SolrDispatchFil= ter.init() done [junit4:junit4] 2> 8415 T350 oascsi.HttpClientUtil.createClient Creating = new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&fol= lowRedirects=3Dfalse [junit4:junit4] 2> 8656 T350 oejs.Server.doStart jetty-8.1.8.v20121106 [junit4:junit4] 2> 8659 T350 oejs.AbstractConnector.doStart Started Socke= tConnector@127.0.0.1:38154 [junit4:junit4] 2> 8660 T350 oass.SolrDispatchFilter.init SolrDispatchFil= ter.init() [junit4:junit4] 2> 8661 T350 oasc.SolrResourceLoader.locateSolrHome JNDI = not configured for solr (NoInitialContextEx) [junit4:junit4] 2> 8661 T350 oasc.SolrResourceLoader.locateSolrHome using= system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cl= oud.BasicDistributedZk2Test-jetty2-1363272777707 [junit4:junit4] 2> 8662 T350 oasc.CoreContainer$Initializer.initialize lo= oking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-= Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.B= asicDistributedZk2Test-jetty2-1363272777707/solr.xml [junit4:junit4] 2> 8662 T350 oasc.CoreContainer. New CoreContainer = 1523392510 [junit4:junit4] 2> 8663 T350 oasc.CoreContainer.load Loading CoreContaine= r using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tes= ts-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDist= ributedZk2Test-jetty2-1363272777707/' [junit4:junit4] 2> 8664 T350 oasc.SolrResourceLoader. new SolrResou= rceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-So= lr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Bas= icDistributedZk2Test-jetty2-1363272777707/' [junit4:junit4] 2> 8719 T350 oashc.HttpShardHandlerFactory.getParameter S= etting socketTimeout to: 120000 [junit4:junit4] 2> 8720 T350 oashc.HttpShardHandlerFactory.getParameter S= etting urlScheme to: http:// [junit4:junit4] 2> 8720 T350 oashc.HttpShardHandlerFactory.getParameter S= etting connTimeout to: 15000 [junit4:junit4] 2> 8721 T350 oashc.HttpShardHandlerFactory.getParameter S= etting maxConnectionsPerHost to: 20 [junit4:junit4] 2> 8721 T350 oashc.HttpShardHandlerFactory.getParameter S= etting corePoolSize to: 0 [junit4:junit4] 2> 8721 T350 oashc.HttpShardHandlerFactory.getParameter S= etting maximumPoolSize to: 2147483647 [junit4:junit4] 2> 8722 T350 oashc.HttpShardHandlerFactory.getParameter S= etting maxThreadIdleTime to: 5 [junit4:junit4] 2> 8722 T350 oashc.HttpShardHandlerFactory.getParameter S= etting sizeOfQueue to: -1 [junit4:junit4] 2> 8724 T350 oashc.HttpShardHandlerFactory.getParameter S= etting fairnessPolicy to: false [junit4:junit4] 2> 8724 T350 oascsi.HttpClientUtil.createClient Creating = new http client, config:maxConnectionsPerHost=3D20&maxConnections=3D10000&s= ocketTimeout=3D120000&connTimeout=3D15000&retry=3Dfalse [junit4:junit4] 2> 8748 T350 oasc.CoreContainer.load Registering Log List= ener [junit4:junit4] 2> 8783 T350 oasc.CoreContainer.initZooKeeper Zookeeper c= lient=3D127.0.0.1:38144/solr [junit4:junit4] 2> 8783 T350 oasc.ZkController.checkChrootPath zkHost inc= ludes chroot [junit4:junit4] 2> 8784 T350 oaz.ZooKeeper. Initiating client conne= ction, connectString=3D127.0.0.1:38144 sessionTimeout=3D60000 watcher=3Dorg= .apache.solr.common.cloud.ConnectionManager@1dc02a4a [junit4:junit4] 2> 8785 T350 oascc.ConnectionManager.waitForConnected Wai= ting for client to connect to ZooKeeper [junit4:junit4] 2> 8786 T405 oaz.ClientCnxn$SendThread.logStartConnect Op= ening socket connection to server localhost/127.0.0.1:38144. Will not attem= pt to authenticate using SASL (access denied (javax.security.auth.AuthPermi= ssion getLoginConfiguration)) [junit4:junit4] 2> 8786 T405 oaz.ClientCnxn$SendThread.primeConnection So= cket connection established to localhost/127.0.0.1:38144, initiating sessio= n [junit4:junit4] 2> 8787 T352 oazs.NIOServerCnxnFactory.run Accepted socke= t connection from /140.211.11.196:38155 [junit4:junit4] 2> 8787 T352 oazs.ZooKeeperServer.processConnectRequest C= lient attempting to establish new session at /140.211.11.196:38155 [junit4:junit4] 2> 8791 T354 oazs.ZooKeeperServer.finishSessionInit Estab= lished session 0x13d69639f040007 with negotiated timeout 20000 for client /= 140.211.11.196:38155 [junit4:junit4] 2> 8791 T405 oaz.ClientCnxn$SendThread.onConnected Sessio= n establishment complete on server localhost/127.0.0.1:38144, sessionid =3D= 0x13d69639f040007, negotiated timeout =3D 20000 [junit4:junit4] 2> 8792 T406 oascc.ConnectionManager.process Watcher org.= apache.solr.common.cloud.ConnectionManager@1dc02a4a name:ZooKeeperConnectio= n Watcher:127.0.0.1:38144 got event WatchedEvent state:SyncConnected type:N= one path:null path:null type:None [junit4:junit4] 2> 8792 T350 oascc.ConnectionManager.waitForConnected Cli= ent is connected to ZooKeeper [junit4:junit4] 2> 8794 T355 oazs.PrepRequestProcessor.pRequest2Txn Proce= ssed session termination for sessionid: 0x13d69639f040007 [junit4:junit4] 2> 8795 T406 oaz.ClientCnxn$EventThread.run EventThread s= hut down [junit4:junit4] 2> 8795 T352 oazs.NIOServerCnxn.closeSock Closed socket c= onnection for client /140.211.11.196:38155 which had sessionid 0x13d69639f0= 40007 [junit4:junit4] 2> 8795 T350 oaz.ZooKeeper.close Session: 0x13d69639f0400= 07 closed [junit4:junit4] 2> 8796 T350 oascsi.HttpClientUtil.createClient Creating = new http client, config:maxConnections=3D500&maxConnectionsPerHost=3D16&soc= ketTimeout=3D120000&connTimeout=3D15000 [junit4:junit4] 2> 8809 T350 oaz.ZooKeeper. Initiating client conne= ction, connectString=3D127.0.0.1:38144/solr sessionTimeout=3D30000 watcher= =3Dorg.apache.solr.common.cloud.ConnectionManager@61ab196b [junit4:junit4] 2> 8810 T350 oascc.ConnectionManager.waitForConnected Wai= ting for client to connect to ZooKeeper [junit4:junit4] 2> 8810 T407 oaz.ClientCnxn$SendThread.logStartConnect Op= ening socket connection to server localhost/127.0.0.1:38144. Will not attem= pt to authenticate using SASL (access denied (javax.security.auth.AuthPermi= ssion getLoginConfiguration)) [junit4:junit4] 2> 8811 T407 oaz.ClientCnxn$SendThread.primeConnection So= cket connection established to localhost/127.0.0.1:38144, initiating sessio= n [junit4:junit4] 2> 8811 T352 oazs.NIOServerCnxnFactory.run Accepted socke= t connection from /140.211.11.196:38156 [junit4:junit4] 2> 8812 T352 oazs.ZooKeeperServer.processConnectRequest C= lient attempting to establish new session at /140.211.11.196:38156 [junit4:junit4] 2> 8813 T354 oazs.ZooKeeperServer.finishSessionInit Estab= lished session 0x13d69639f040008 with negotiated timeout 20000 for client /= 140.211.11.196:38156 [junit4:junit4] 2> 8813 T407 oaz.ClientCnxn$SendThread.onConnected Sessio= n establishment complete on server localhost/127.0.0.1:38144, sessionid =3D= 0x13d69639f040008, negotiated timeout =3D 20000 [junit4:junit4] 2> 8814 T408 oascc.ConnectionManager.process Watcher org.= apache.solr.common.cloud.ConnectionManager@61ab196b name:ZooKeeperConnectio= n Watcher:127.0.0.1:38144/solr got event WatchedEvent state:SyncConnected t= ype:None path:null path:null type:None [junit4:junit4] 2> 8814 T350 oascc.ConnectionManager.waitForConnected Cli= ent is connected to ZooKeeper [junit4:junit4] 2> 8815 T355 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d69639f040008 type:crea= te cxid:0x1 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Erro= r:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 8818 T355 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d69639f040008 type:crea= te cxid:0x2 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/overseer Erro= r:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 8821 T350 oascc.ZkStateReader.createClusterStateWatche= rsAndUpdate Updating cluster state from ZooKeeper...=20 [junit4:junit4] 2> 9826 T350 oasc.ZkController.createEphemeralLiveNode Re= gister node as live in ZooKeeper:/live_nodes/127.0.0.1:38154_muhkb%2Fmb [junit4:junit4] 2> 9827 T355 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d69639f040008 type:dele= te cxid:0xb zxid:0x70 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/12= 7.0.0.1:38154_muhkb%2Fmb Error:KeeperErrorCode =3D NoNode for /solr/live_no= des/127.0.0.1:38154_muhkb%2Fmb [junit4:junit4] 2> 9880 T350 oascc.SolrZkClient.makePath makePath: /live_= nodes/127.0.0.1:38154_muhkb%2Fmb [junit4:junit4] 2> 9883 T373 oascc.ZkStateReader.updateClusterState Updat= ing cloud state from ZooKeeper...=20 [junit4:junit4] 2> 9885 T392 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/l= ive_nodes, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 9885 T372 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/l= ive_nodes, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 9886 T373 oasc.Overseer$ClusterStateUpdater.updateStat= e Update state numShards=3D2 message=3D{ [junit4:junit4] 2> =09 "operation":"state", [junit4:junit4] 2> =09 "core_node_name":"2", [junit4:junit4] 2> =09 "numShards":"2", [junit4:junit4] 2> =09 "shard":"shard1", [junit4:junit4] 2> =09 "roles":null, [junit4:junit4] 2> =09 "state":"active", [junit4:junit4] 2> =09 "core":"collection1", [junit4:junit4] 2> =09 "collection":"collection1", [junit4:junit4] 2> =09 "node_name":"127.0.0.1:38151_muhkb%2Fmb", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:38151/muhkb/mb"} [junit4:junit4] 2> 9887 T379 oascc.ZkStateReader$3.process Updating live = nodes... (3) [junit4:junit4] 2> 9887 T408 oascc.ZkStateReader$3.process Updating live = nodes... (3) [junit4:junit4] 2> 9888 T379 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/l= ive_nodes, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 9890 T392 oascc.ZkStateReader$3.process Updating live = nodes... (3) [junit4:junit4] 2> 9903 T392 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 9903 T379 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 9903 T408 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 9907 T409 oasc.CoreContainer.create Creating SolrCore = 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cl= oud.BasicDistributedZk2Test-jetty2-1363272777707/collection1 [junit4:junit4] 2> 9908 T409 oasc.ZkController.createCollectionZkNode Che= ck for collection zkNode:collection1 [junit4:junit4] 2> 9909 T409 oasc.ZkController.createCollectionZkNode Col= lection zkNode exists [junit4:junit4] 2> 9909 T409 oasc.ZkController.readConfigName Load collec= tion config from:/collections/collection1 [junit4:junit4] 2> 9910 T372 oascc.ZkStateReader$3.process Updating live = nodes... (3) [junit4:junit4] 2> 9910 T372 oascc.ZkStateReader$2.process A cluster stat= e change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clust= erstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 9911 T409 oasc.SolrResourceLoader. new SolrResou= rceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-So= lr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Bas= icDistributedZk2Test-jetty2-1363272777707/collection1/' [junit4:junit4] 2> 9912 T409 oasc.SolrResourceLoader.replaceClassLoader A= dding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-J= ava6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2= Test-jetty2-1363272777707/collection1/lib/README' to classloader [junit4:junit4] 2> 9913 T409 oasc.SolrResourceLoader.replaceClassLoader A= dding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-J= ava6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2= Test-jetty2-1363272777707/collection1/lib/classes/' to classloader [junit4:junit4] 2> 9972 T409 oasc.SolrConfig. Using Lucene MatchVer= sion: LUCENE_43 [junit4:junit4] 2> 10037 T409 oasc.SolrConfig. Loaded SolrConfig: s= olrconfig.xml [junit4:junit4] 2> 10039 T409 oass.IndexSchema.readSchema Reading Solr Sc= hema [junit4:junit4] 2> 10046 T409 oass.IndexSchema.readSchema Schema name=3Dt= est [junit4:junit4] 2> 10684 T409 oass.OpenExchangeRatesOrgProvider.init Init= ialized with rates=3Dopen-exchange-rates.json, refreshInterval=3D1440. [junit4:junit4] 2> 10696 T409 oass.IndexSchema.readSchema default search = field in schema is text [junit4:junit4] 2> 10731 T409 oass.IndexSchema.readSchema unique key fiel= d: id [junit4:junit4] 2> 10755 T409 oass.FileExchangeRateProvider.reload Reload= ing exchange rates from file currency.xml [junit4:junit4] 2> 10761 T409 oass.FileExchangeRateProvider.reload Reload= ing exchange rates from file currency.xml [junit4:junit4] 2> 10768 T409 oass.OpenExchangeRatesOrgProvider.reload Re= loading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 10770 T409 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 10770 T409 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 10771 T409 oass.OpenExchangeRatesOrgProvider.reload Re= loading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 10773 T409 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 10773 T409 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 10773 T409 oasc.SolrCore.initDirectoryFactory org.apac= he.solr.core.MockDirectoryFactory [junit4:junit4] 2> 10773 T409 oasc.SolrCore. [collection1] Opening = new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4= .x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistribu= tedZk2Test-jetty2-1363272777707/collection1/, dataDir=3D./org.apache.solr.c= loud.BasicDistributedZk2Test-1363272769277/jetty2/ [junit4:junit4] 2> 10774 T409 oasc.JmxMonitoredMap. JMX monitoring = is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMB= eanServer@3dbe8711 [junit4:junit4] 2> 10774 T409 oasc.SolrCore.initDirectoryFactory org.apac= he.solr.core.MockDirectoryFactory [junit4:junit4] 2> 10775 T409 oasc.CachingDirectoryFactory.get return new= directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-136327276927= 7/jetty2 forceNew: false [junit4:junit4] 2> 10775 T409 oasc.SolrCore.getNewIndexDir New index dire= ctory detected: old=3Dnull new=3D./org.apache.solr.cloud.BasicDistributedZk= 2Test-1363272769277/jetty2/index/ [junit4:junit4] 2> 10776 T409 oasc.SolrCore.initIndex WARNING [collection= 1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-13= 63272769277/jetty2/index' doesn't exist. Creating new index... [junit4:junit4] 2> 10776 T409 oasc.CachingDirectoryFactory.get return new= directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-136327276927= 7/jetty2/index forceNew: false [junit4:junit4] 2> 10779 T409 oasc.SolrDeletionPolicy.onCommit SolrDeleti= onPolicy.onCommit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@1d04e75b lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@7eb9926),segFN=3Dsegments_1,generation=3D1,filenames=3D[segm= ents_1] [junit4:junit4] 2> 10779 T409 oasc.SolrDeletionPolicy.updateCommits newes= t commit =3D 1[segments_1] [junit4:junit4] 2> 10782 T409 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "d= edupe" [junit4:junit4] 2> 10782 T409 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "s= tored_sig" [junit4:junit4] 2> 10783 T409 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "d= istrib-dup-test-chain-implicit" [junit4:junit4] 2> 10783 T409 oasc.RequestHandlers.initHandlersFromConfig= created standard: solr.StandardRequestHandler [junit4:junit4] 2> 10784 T409 oasc.RequestHandlers.initHandlersFromConfig= created /get: solr.RealTimeGetHandler [junit4:junit4] 2> 10784 T409 oasc.RequestHandlers.initHandlersFromConfig= adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 2> 10784 T409 oasc.RequestHandlers.initHandlersFromConfig= created /replication: solr.ReplicationHandler [junit4:junit4] 2> 10785 T409 oasc.RequestHandlers.initHandlersFromConfig= created /update: solr.UpdateRequestHandler [junit4:junit4] 2> 10785 T409 oasc.RequestHandlers.initHandlersFromConfig= created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4:junit4] 2> 10793 T409 oashl.XMLLoader.init xsltCacheLifetimeSecon= ds=3D60 [junit4:junit4] 2> 10799 T409 oass.SolrIndexSearcher. Opening Searc= her@91f1520 main [junit4:junit4] 2> 10799 T409 oasu.UpdateHandler.clearLog Clearing tlog f= iles, tlogDir=3D./org.apache.solr.cloud.BasicDistributedZk2Test-13632727692= 77/jetty2/tlog [junit4:junit4] 2> 10800 T409 oasu.CommitTracker. Hard AutoCommit: = disabled [junit4:junit4] 2> 10801 T409 oasu.CommitTracker. Soft AutoCommit: = disabled [junit4:junit4] 2> 10805 T410 oasc.SolrCore.registerSearcher [collection1= ] Registered new searcher Searcher@91f1520 main{StandardDirectoryReader(seg= ments_1:1)} [junit4:junit4] 2> 10807 T409 oasc.ZkController.publish publishing core= =3Dcollection1 state=3Ddown [junit4:junit4] 2> 10807 T409 oasc.ZkController.publish numShards not fou= nd on descriptor - reading it from system property [junit4:junit4] 2> 11411 T373 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 11412 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Update state numShards=3D2 message=3D{ [junit4:junit4] 2> =09 "operation":"state", [junit4:junit4] 2> =09 "core_node_name":"3", [junit4:junit4] 2> =09 "numShards":"2", [junit4:junit4] 2> =09 "shard":null, [junit4:junit4] 2> =09 "roles":null, [junit4:junit4] 2> =09 "state":"down", [junit4:junit4] 2> =09 "core":"collection1", [junit4:junit4] 2> =09 "collection":"collection1", [junit4:junit4] 2> =09 "node_name":"127.0.0.1:38154_muhkb%2Fmb", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:38154/muhkb/mb"} [junit4:junit4] 2> 11412 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Collection already exists with numShards=3D2 [junit4:junit4] 2> 11412 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Assigning new node to shard shard=3Dshard2 [junit4:junit4] 2> 11451 T379 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 11451 T392 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 11451 T408 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 11451 T372 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 11846 T409 oasc.CoreContainer.registerCore registering= core: collection1 [junit4:junit4] 2> 11846 T409 oasc.ZkController.register Register replica= - core:collection1 address:http://127.0.0.1:38154/muhkb/mb collection:coll= ection1 shard:shard2 [junit4:junit4] 2> 11847 T409 oascc.SolrZkClient.makePath makePath: /coll= ections/collection1/leader_elect/shard2/election [junit4:junit4] 2> 11875 T355 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d69639f040008 type:del= ete cxid:0x47 zxid:0x7f txntype:-1 reqpath:n/a Error Path:/solr/collections= /collection1/leaders/shard2 Error:KeeperErrorCode =3D NoNode for /solr/coll= ections/collection1/leaders/shard2 [junit4:junit4] 2> 11876 T409 oasc.ShardLeaderElectionContext.runLeaderPr= ocess Running the leader process. [junit4:junit4] 2> 11877 T355 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d69639f040008 type:cre= ate cxid:0x48 zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/overseer Er= ror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 11888 T409 oasc.ShardLeaderElectionContext.waitForRepl= icasToComeUp Enough replicas found to continue. [junit4:junit4] 2> 11889 T409 oasc.ShardLeaderElectionContext.runLeaderPr= ocess I may be the new leader - try and sync [junit4:junit4] 2> 11889 T409 oasc.SyncStrategy.sync Sync replicas to htt= p://127.0.0.1:38154/muhkb/mb/collection1/ [junit4:junit4] 2> 11889 T409 oasc.SyncStrategy.syncReplicas Sync Success= - now sync replicas to me [junit4:junit4] 2> 11889 T409 oasc.SyncStrategy.syncToMe http://127.0.0.1= :38154/muhkb/mb/collection1/ has no replicas [junit4:junit4] 2> 11889 T409 oasc.ShardLeaderElectionContext.runLeaderPr= ocess I am the new leader: http://127.0.0.1:38154/muhkb/mb/collection1/ [junit4:junit4] 2> 11890 T409 oascc.SolrZkClient.makePath makePath: /coll= ections/collection1/leaders/shard2 [junit4:junit4] 2> 11895 T355 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d69639f040008 type:cre= ate cxid:0x51 zxid:0x83 txntype:-1 reqpath:n/a Error Path:/solr/overseer Er= ror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 12959 T373 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 12980 T379 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 12980 T392 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 12981 T372 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 12980 T408 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 13028 T409 oasc.ZkController.register We are http://12= 7.0.0.1:38154/muhkb/mb/collection1/ and leader is http://127.0.0.1:38154/mu= hkb/mb/collection1/ [junit4:junit4] 2> 13028 T409 oasc.ZkController.register No LogReplay nee= ded for core=3Dcollection1 baseURL=3Dhttp://127.0.0.1:38154/muhkb/mb [junit4:junit4] 2> 13028 T409 oasc.ZkController.checkRecovery I am the le= ader, no recovery necessary [junit4:junit4] 2> 13028 T409 oasc.ZkController.publish publishing core= =3Dcollection1 state=3Dactive [junit4:junit4] 2> 13029 T409 oasc.ZkController.publish numShards not fou= nd on descriptor - reading it from system property [junit4:junit4] 2> 13032 T409 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 13034 T350 oass.SolrDispatchFilter.init user.dir=3D/us= r/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build= /solr-core/test/J1 [junit4:junit4] 2> 13034 T350 oass.SolrDispatchFilter.init SolrDispatchFi= lter.init() done [junit4:junit4] 2> 13035 T350 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&fo= llowRedirects=3Dfalse [junit4:junit4] 2> 13247 T350 oejs.Server.doStart jetty-8.1.8.v20121106 [junit4:junit4] 2> 13250 T350 oejs.AbstractConnector.doStart Started Sock= etConnector@127.0.0.1:38157 [junit4:junit4] 2> 13251 T350 oass.SolrDispatchFilter.init SolrDispatchFi= lter.init() [junit4:junit4] 2> 13252 T350 oasc.SolrResourceLoader.locateSolrHome JNDI= not configured for solr (NoInitialContextEx) [junit4:junit4] 2> 13253 T350 oasc.SolrResourceLoader.locateSolrHome usin= g system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.c= loud.BasicDistributedZk2Test-jetty3-1363272782324 [junit4:junit4] 2> 13254 T350 oasc.CoreContainer$Initializer.initialize l= ooking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene= -Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.= BasicDistributedZk2Test-jetty3-1363272782324/solr.xml [junit4:junit4] 2> 13254 T350 oasc.CoreContainer. New CoreContainer= 432131260 [junit4:junit4] 2> 13255 T350 oasc.CoreContainer.load Loading CoreContain= er using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDis= tributedZk2Test-jetty3-1363272782324/' [junit4:junit4] 2> 13256 T350 oasc.SolrResourceLoader. new SolrReso= urceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-S= olr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Ba= sicDistributedZk2Test-jetty3-1363272782324/' [junit4:junit4] 2> 13310 T350 oashc.HttpShardHandlerFactory.getParameter = Setting socketTimeout to: 120000 [junit4:junit4] 2> 13311 T350 oashc.HttpShardHandlerFactory.getParameter = Setting urlScheme to: http:// [junit4:junit4] 2> 13311 T350 oashc.HttpShardHandlerFactory.getParameter = Setting connTimeout to: 15000 [junit4:junit4] 2> 13311 T350 oashc.HttpShardHandlerFactory.getParameter = Setting maxConnectionsPerHost to: 20 [junit4:junit4] 2> 13312 T350 oashc.HttpShardHandlerFactory.getParameter = Setting corePoolSize to: 0 [junit4:junit4] 2> 13312 T350 oashc.HttpShardHandlerFactory.getParameter = Setting maximumPoolSize to: 2147483647 [junit4:junit4] 2> 13313 T350 oashc.HttpShardHandlerFactory.getParameter = Setting maxThreadIdleTime to: 5 [junit4:junit4] 2> 13313 T350 oashc.HttpShardHandlerFactory.getParameter = Setting sizeOfQueue to: -1 [junit4:junit4] 2> 13314 T350 oashc.HttpShardHandlerFactory.getParameter = Setting fairnessPolicy to: false [junit4:junit4] 2> 13314 T350 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnectionsPerHost=3D20&maxConnections=3D10000&= socketTimeout=3D120000&connTimeout=3D15000&retry=3Dfalse [junit4:junit4] 2> 13336 T350 oasc.CoreContainer.load Registering Log Lis= tener [junit4:junit4] 2> 13355 T350 oasc.CoreContainer.initZooKeeper Zookeeper = client=3D127.0.0.1:38144/solr [junit4:junit4] 2> 13356 T350 oasc.ZkController.checkChrootPath zkHost in= cludes chroot [junit4:junit4] 2> 13356 T350 oaz.ZooKeeper. Initiating client conn= ection, connectString=3D127.0.0.1:38144 sessionTimeout=3D60000 watcher=3Dor= g.apache.solr.common.cloud.ConnectionManager@105faa72 [junit4:junit4] 2> 13357 T350 oascc.ConnectionManager.waitForConnected Wa= iting for client to connect to ZooKeeper [junit4:junit4] 2> 13358 T421 oaz.ClientCnxn$SendThread.logStartConnect O= pening socket connection to server localhost/127.0.0.1:38144. Will not atte= mpt to authenticate using SASL (access denied (javax.security.auth.AuthPerm= ission getLoginConfiguration)) [junit4:junit4] 2> 13358 T421 oaz.ClientCnxn$SendThread.primeConnection S= ocket connection established to localhost/127.0.0.1:38144, initiating sessi= on [junit4:junit4] 2> 13359 T352 oazs.NIOServerCnxnFactory.run Accepted sock= et connection from /140.211.11.196:38158 [junit4:junit4] 2> 13359 T352 oazs.ZooKeeperServer.processConnectRequest = Client attempting to establish new session at /140.211.11.196:38158 [junit4:junit4] 2> 13361 T354 oazs.ZooKeeperServer.finishSessionInit Esta= blished session 0x13d69639f040009 with negotiated timeout 20000 for client = /140.211.11.196:38158 [junit4:junit4] 2> 13361 T421 oaz.ClientCnxn$SendThread.onConnected Sessi= on establishment complete on server localhost/127.0.0.1:38144, sessionid = =3D 0x13d69639f040009, negotiated timeout =3D 20000 [junit4:junit4] 2> 13362 T422 oascc.ConnectionManager.process Watcher org= .apache.solr.common.cloud.ConnectionManager@105faa72 name:ZooKeeperConnecti= on Watcher:127.0.0.1:38144 got event WatchedEvent state:SyncConnected type:= None path:null path:null type:None [junit4:junit4] 2> 13362 T350 oascc.ConnectionManager.waitForConnected Cl= ient is connected to ZooKeeper [junit4:junit4] 2> 13364 T355 oazs.PrepRequestProcessor.pRequest2Txn Proc= essed session termination for sessionid: 0x13d69639f040009 [junit4:junit4] 2> 13377 T422 oaz.ClientCnxn$EventThread.run EventThread = shut down [junit4:junit4] 2> 13377 T352 oazs.NIOServerCnxn.closeSock Closed socket = connection for client /140.211.11.196:38158 which had sessionid 0x13d69639f= 040009 [junit4:junit4] 2> 13377 T350 oaz.ZooKeeper.close Session: 0x13d69639f040= 009 closed [junit4:junit4] 2> 13378 T350 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnections=3D500&maxConnectionsPerHost=3D16&so= cketTimeout=3D120000&connTimeout=3D15000 [junit4:junit4] 2> 13391 T350 oaz.ZooKeeper. Initiating client conn= ection, connectString=3D127.0.0.1:38144/solr sessionTimeout=3D30000 watcher= =3Dorg.apache.solr.common.cloud.ConnectionManager@5b525b5f [junit4:junit4] 2> 13393 T350 oascc.ConnectionManager.waitForConnected Wa= iting for client to connect to ZooKeeper [junit4:junit4] 2> 13393 T423 oaz.ClientCnxn$SendThread.logStartConnect O= pening socket connection to server localhost/127.0.0.1:38144. Will not atte= mpt to authenticate using SASL (access denied (javax.security.auth.AuthPerm= ission getLoginConfiguration)) [junit4:junit4] 2> 13394 T423 oaz.ClientCnxn$SendThread.primeConnection S= ocket connection established to localhost/127.0.0.1:38144, initiating sessi= on [junit4:junit4] 2> 13394 T352 oazs.NIOServerCnxnFactory.run Accepted sock= et connection from /140.211.11.196:38159 [junit4:junit4] 2> 13394 T352 oazs.ZooKeeperServer.processConnectRequest = Client attempting to establish new session at /140.211.11.196:38159 [junit4:junit4] 2> 13396 T354 oazs.ZooKeeperServer.finishSessionInit Esta= blished session 0x13d69639f04000a with negotiated timeout 20000 for client = /140.211.11.196:38159 [junit4:junit4] 2> 13396 T423 oaz.ClientCnxn$SendThread.onConnected Sessi= on establishment complete on server localhost/127.0.0.1:38144, sessionid = =3D 0x13d69639f04000a, negotiated timeout =3D 20000 [junit4:junit4] 2> 13396 T424 oascc.ConnectionManager.process Watcher org= .apache.solr.common.cloud.ConnectionManager@5b525b5f name:ZooKeeperConnecti= on Watcher:127.0.0.1:38144/solr got event WatchedEvent state:SyncConnected = type:None path:null path:null type:None [junit4:junit4] 2> 13397 T350 oascc.ConnectionManager.waitForConnected Cl= ient is connected to ZooKeeper [junit4:junit4] 2> 13398 T355 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d69639f04000a type:cre= ate cxid:0x1 zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 13400 T355 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d69639f04000a type:cre= ate cxid:0x2 zxid:0x91 txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 13403 T350 oascc.ZkStateReader.createClusterStateWatch= ersAndUpdate Updating cluster state from ZooKeeper...=20 [junit4:junit4] 2> 14408 T350 oasc.ZkController.createEphemeralLiveNode R= egister node as live in ZooKeeper:/live_nodes/127.0.0.1:38157_muhkb%2Fmb [junit4:junit4] 2> 14409 T355 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d69639f04000a type:del= ete cxid:0xb zxid:0x92 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/1= 27.0.0.1:38157_muhkb%2Fmb Error:KeeperErrorCode =3D NoNode for /solr/live_n= odes/127.0.0.1:38157_muhkb%2Fmb [junit4:junit4] 2> 14437 T350 oascc.SolrZkClient.makePath makePath: /live= _nodes/127.0.0.1:38157_muhkb%2Fmb [junit4:junit4] 2> 14441 T392 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/= live_nodes, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 14442 T372 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/= live_nodes, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 14442 T408 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/= live_nodes, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 14442 T379 oascc.ZkStateReader$3.process Updating live= nodes... (4) [junit4:junit4] 2> 14442 T424 oascc.ZkStateReader$3.process Updating live= nodes... (4) [junit4:junit4] 2> 14443 T379 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/= live_nodes, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 14445 T392 oascc.ZkStateReader$3.process Updating live= nodes... (4) [junit4:junit4] 2> 14445 T372 oascc.ZkStateReader$3.process Updating live= nodes... (4) [junit4:junit4] 2> 14446 T408 oascc.ZkStateReader$3.process Updating live= nodes... (4) [junit4:junit4] 2> 14456 T425 oasc.CoreContainer.create Creating SolrCore= 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.c= loud.BasicDistributedZk2Test-jetty3-1363272782324/collection1 [junit4:junit4] 2> 14456 T425 oasc.ZkController.createCollectionZkNode Ch= eck for collection zkNode:collection1 [junit4:junit4] 2> 14458 T425 oasc.ZkController.createCollectionZkNode Co= llection zkNode exists [junit4:junit4] 2> 14458 T425 oasc.ZkController.readConfigName Load colle= ction config from:/collections/collection1 [junit4:junit4] 2> 14460 T425 oasc.SolrResourceLoader. new SolrReso= urceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-S= olr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Ba= sicDistributedZk2Test-jetty3-1363272782324/collection1/' [junit4:junit4] 2> 14461 T425 oasc.SolrResourceLoader.replaceClassLoader = Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-= Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk= 2Test-jetty3-1363272782324/collection1/lib/classes/' to classloader [junit4:junit4] 2> 14462 T425 oasc.SolrResourceLoader.replaceClassLoader = Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-= Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk= 2Test-jetty3-1363272782324/collection1/lib/README' to classloader [junit4:junit4] 2> 14496 T373 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 14497 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Update state numShards=3D2 message=3D{ [junit4:junit4] 2> =09 "operation":"state", [junit4:junit4] 2> =09 "core_node_name":"3", [junit4:junit4] 2> =09 "numShards":"2", [junit4:junit4] 2> =09 "shard":"shard2", [junit4:junit4] 2> =09 "roles":null, [junit4:junit4] 2> =09 "state":"active", [junit4:junit4] 2> =09 "core":"collection1", [junit4:junit4] 2> =09 "collection":"collection1", [junit4:junit4] 2> =09 "node_name":"127.0.0.1:38154_muhkb%2Fmb", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:38154/muhkb/mb"} [junit4:junit4] 2> 14511 T392 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 14511 T379 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 14511 T372 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 14511 T408 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 14511 T424 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 14512 T425 oasc.SolrConfig. Using Lucene MatchVe= rsion: LUCENE_43 [junit4:junit4] 2> 14574 T425 oasc.SolrConfig. Loaded SolrConfig: s= olrconfig.xml [junit4:junit4] 2> 14593 T425 oass.IndexSchema.readSchema Reading Solr Sc= hema [junit4:junit4] 2> 14600 T425 oass.IndexSchema.readSchema Schema name=3Dt= est [junit4:junit4] 2> 15240 T425 oass.OpenExchangeRatesOrgProvider.init Init= ialized with rates=3Dopen-exchange-rates.json, refreshInterval=3D1440. [junit4:junit4] 2> 15252 T425 oass.IndexSchema.readSchema default search = field in schema is text [junit4:junit4] 2> 15257 T425 oass.IndexSchema.readSchema unique key fiel= d: id [junit4:junit4] 2> 15278 T425 oass.FileExchangeRateProvider.reload Reload= ing exchange rates from file currency.xml [junit4:junit4] 2> 15284 T425 oass.FileExchangeRateProvider.reload Reload= ing exchange rates from file currency.xml [junit4:junit4] 2> 15289 T425 oass.OpenExchangeRatesOrgProvider.reload Re= loading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 15291 T425 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 15291 T425 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 15291 T425 oass.OpenExchangeRatesOrgProvider.reload Re= loading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 15293 T425 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 15293 T425 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 15294 T425 oasc.SolrCore.initDirectoryFactory org.apac= he.solr.core.MockDirectoryFactory [junit4:junit4] 2> 15294 T425 oasc.SolrCore. [collection1] Opening = new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4= .x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistribu= tedZk2Test-jetty3-1363272782324/collection1/, dataDir=3D./org.apache.solr.c= loud.BasicDistributedZk2Test-1363272769277/jetty3/ [junit4:junit4] 2> 15294 T425 oasc.JmxMonitoredMap. JMX monitoring = is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMB= eanServer@3dbe8711 [junit4:junit4] 2> 15295 T425 oasc.SolrCore.initDirectoryFactory org.apac= he.solr.core.MockDirectoryFactory [junit4:junit4] 2> 15295 T425 oasc.CachingDirectoryFactory.get return new= directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-136327276927= 7/jetty3 forceNew: false [junit4:junit4] 2> 15295 T425 oasc.SolrCore.getNewIndexDir New index dire= ctory detected: old=3Dnull new=3D./org.apache.solr.cloud.BasicDistributedZk= 2Test-1363272769277/jetty3/index/ [junit4:junit4] 2> 15296 T425 oasc.SolrCore.initIndex WARNING [collection= 1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-13= 63272769277/jetty3/index' doesn't exist. Creating new index... [junit4:junit4] 2> 15296 T425 oasc.CachingDirectoryFactory.get return new= directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-136327276927= 7/jetty3/index forceNew: false [junit4:junit4] 2> 15299 T425 oasc.SolrDeletionPolicy.onCommit SolrDeleti= onPolicy.onCommit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@588c6ea1 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@438060f4),segFN=3Dsegments_1,generation=3D1,filenames=3D[seg= ments_1] [junit4:junit4] 2> 15299 T425 oasc.SolrDeletionPolicy.updateCommits newes= t commit =3D 1[segments_1] [junit4:junit4] 2> 15302 T425 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "d= edupe" [junit4:junit4] 2> 15302 T425 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "s= tored_sig" [junit4:junit4] 2> 15303 T425 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "d= istrib-dup-test-chain-implicit" [junit4:junit4] 2> 15303 T425 oasc.RequestHandlers.initHandlersFromConfig= created standard: solr.StandardRequestHandler [junit4:junit4] 2> 15304 T425 oasc.RequestHandlers.initHandlersFromConfig= created /get: solr.RealTimeGetHandler [junit4:junit4] 2> 15304 T425 oasc.RequestHandlers.initHandlersFromConfig= adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 2> 15304 T425 oasc.RequestHandlers.initHandlersFromConfig= created /replication: solr.ReplicationHandler [junit4:junit4] 2> 15305 T425 oasc.RequestHandlers.initHandlersFromConfig= created /update: solr.UpdateRequestHandler [junit4:junit4] 2> 15305 T425 oasc.RequestHandlers.initHandlersFromConfig= created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4:junit4] 2> 15313 T425 oashl.XMLLoader.init xsltCacheLifetimeSecon= ds=3D60 [junit4:junit4] 2> 15319 T425 oass.SolrIndexSearcher. Opening Searc= her@70a58086 main [junit4:junit4] 2> 15319 T425 oasu.UpdateHandler.clearLog Clearing tlog f= iles, tlogDir=3D./org.apache.solr.cloud.BasicDistributedZk2Test-13632727692= 77/jetty3/tlog [junit4:junit4] 2> 15320 T425 oasu.CommitTracker. Hard AutoCommit: = disabled [junit4:junit4] 2> 15320 T425 oasu.CommitTracker. Soft AutoCommit: = disabled [junit4:junit4] 2> 15324 T426 oasc.SolrCore.registerSearcher [collection1= ] Registered new searcher Searcher@70a58086 main{StandardDirectoryReader(se= gments_1:1)} [junit4:junit4] 2> 15326 T425 oasc.ZkController.publish publishing core= =3Dcollection1 state=3Ddown [junit4:junit4] 2> 15327 T425 oasc.ZkController.publish numShards not fou= nd on descriptor - reading it from system property [junit4:junit4] 2> 16023 T373 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 16025 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Update state numShards=3D2 message=3D{ [junit4:junit4] 2> =09 "operation":"state", [junit4:junit4] 2> =09 "core_node_name":"4", [junit4:junit4] 2> =09 "numShards":"2", [junit4:junit4] 2> =09 "shard":null, [junit4:junit4] 2> =09 "roles":null, [junit4:junit4] 2> =09 "state":"down", [junit4:junit4] 2> =09 "core":"collection1", [junit4:junit4] 2> =09 "collection":"collection1", [junit4:junit4] 2> =09 "node_name":"127.0.0.1:38157_muhkb%2Fmb", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:38157/muhkb/mb"} [junit4:junit4] 2> 16025 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Collection already exists with numShards=3D2 [junit4:junit4] 2> 16026 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Assigning new node to shard shard=3Dshard1 [junit4:junit4] 2> 16113 T392 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 16113 T424 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 16114 T408 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 16113 T372 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 16114 T379 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 16356 T425 oasc.CoreContainer.registerCore registering= core: collection1 [junit4:junit4] 2> 16356 T425 oasc.ZkController.register Register replica= - core:collection1 address:http://127.0.0.1:38157/muhkb/mb collection:coll= ection1 shard:shard1 [junit4:junit4] 2> 16361 T425 oasc.ZkController.register We are http://12= 7.0.0.1:38157/muhkb/mb/collection1/ and leader is http://127.0.0.1:38151/mu= hkb/mb/collection1/ [junit4:junit4] 2> 16361 T425 oasc.ZkController.register No LogReplay nee= ded for core=3Dcollection1 baseURL=3Dhttp://127.0.0.1:38157/muhkb/mb [junit4:junit4] 2> 16362 T425 oasc.ZkController.checkRecovery Core needs = to recover:collection1 [junit4:junit4] 2> 16362 T425 oasu.DefaultSolrCoreState.doRecovery Runnin= g recovery - first canceling any ongoing recovery [junit4:junit4] 2> ASYNC NEW_CORE C60 name=3Dcollection1 org.apache.solr= .core.SolrCore@7b898bff url=3Dhttp://127.0.0.1:38157/muhkb/mb/collection1 n= ode=3D127.0.0.1:38157_muhkb%2Fmb C60_STATE=3Dcoll:collection1 core:collecti= on1 props:{state=3Ddown, core=3Dcollection1, collection=3Dcollection1, node= _name=3D127.0.0.1:38157_muhkb%2Fmb, base_url=3Dhttp://127.0.0.1:38157/muhkb= /mb} [junit4:junit4] 2> 16369 T427 C60 P38157 oasc.RecoveryStrategy.run Starti= ng recovery process. core=3Dcollection1 recoveringAfterStartup=3Dtrue [junit4:junit4] 2> 16370 T425 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 16370 T427 C60 P38157 oasc.RecoveryStrategy.doRecovery= ###### startupVersions=3D[] [junit4:junit4] 2> 16371 T427 C60 P38157 oasc.ZkController.publish publis= hing core=3Dcollection1 state=3Drecovering [junit4:junit4] 2> 16371 T427 C60 P38157 oasc.ZkController.publish numSha= rds not found on descriptor - reading it from system property [junit4:junit4] 2> 16372 T350 oass.SolrDispatchFilter.init user.dir=3D/us= r/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build= /solr-core/test/J1 [junit4:junit4] 2> 16372 T350 oass.SolrDispatchFilter.init SolrDispatchFi= lter.init() done [junit4:junit4] 2> 16373 T427 C60 P38157 oascsi.HttpClientUtil.createClie= nt Creating new http client, config:maxConnections=3D128&maxConnectionsPerH= ost=3D32&followRedirects=3Dfalse [junit4:junit4] 2> 16373 T350 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&fo= llowRedirects=3Dfalse [junit4:junit4] 2> 16617 T350 oejs.Server.doStart jetty-8.1.8.v20121106 [junit4:junit4] 2> 16621 T350 oejs.AbstractConnector.doStart Started Sock= etConnector@127.0.0.1:38161 [junit4:junit4] 2> 16621 T350 oass.SolrDispatchFilter.init SolrDispatchFi= lter.init() [junit4:junit4] 2> 16622 T350 oasc.SolrResourceLoader.locateSolrHome JNDI= not configured for solr (NoInitialContextEx) [junit4:junit4] 2> 16622 T350 oasc.SolrResourceLoader.locateSolrHome usin= g system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.c= loud.BasicDistributedZk2Test-jetty4-1363272785670 [junit4:junit4] 2> 16623 T350 oasc.CoreContainer$Initializer.initialize l= ooking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene= -Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.= BasicDistributedZk2Test-jetty4-1363272785670/solr.xml [junit4:junit4] 2> 16623 T350 oasc.CoreContainer. New CoreContainer= 1792970379 [junit4:junit4] 2> 16624 T350 oasc.CoreContainer.load Loading CoreContain= er using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDis= tributedZk2Test-jetty4-1363272785670/' [junit4:junit4] 2> 16624 T350 oasc.SolrResourceLoader. new SolrReso= urceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-S= olr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Ba= sicDistributedZk2Test-jetty4-1363272785670/' [junit4:junit4] 2> 16681 T350 oashc.HttpShardHandlerFactory.getParameter = Setting socketTimeout to: 120000 [junit4:junit4] 2> 16681 T350 oashc.HttpShardHandlerFactory.getParameter = Setting urlScheme to: http:// [junit4:junit4] 2> 16682 T350 oashc.HttpShardHandlerFactory.getParameter = Setting connTimeout to: 15000 [junit4:junit4] 2> 16682 T350 oashc.HttpShardHandlerFactory.getParameter = Setting maxConnectionsPerHost to: 20 [junit4:junit4] 2> 16683 T350 oashc.HttpShardHandlerFactory.getParameter = Setting corePoolSize to: 0 [junit4:junit4] 2> 16683 T350 oashc.HttpShardHandlerFactory.getParameter = Setting maximumPoolSize to: 2147483647 [junit4:junit4] 2> 16684 T350 oashc.HttpShardHandlerFactory.getParameter = Setting maxThreadIdleTime to: 5 [junit4:junit4] 2> 16684 T350 oashc.HttpShardHandlerFactory.getParameter = Setting sizeOfQueue to: -1 [junit4:junit4] 2> 16685 T350 oashc.HttpShardHandlerFactory.getParameter = Setting fairnessPolicy to: false [junit4:junit4] 2> 16685 T350 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnectionsPerHost=3D20&maxConnections=3D10000&= socketTimeout=3D120000&connTimeout=3D15000&retry=3Dfalse [junit4:junit4] 2> 16713 T350 oasc.CoreContainer.load Registering Log Lis= tener [junit4:junit4] 2> 16738 T350 oasc.CoreContainer.initZooKeeper Zookeeper = client=3D127.0.0.1:38144/solr [junit4:junit4] 2> 16739 T350 oasc.ZkController.checkChrootPath zkHost in= cludes chroot [junit4:junit4] 2> 16740 T350 oaz.ZooKeeper. Initiating client conn= ection, connectString=3D127.0.0.1:38144 sessionTimeout=3D60000 watcher=3Dor= g.apache.solr.common.cloud.ConnectionManager@6e105df8 [junit4:junit4] 2> 16742 T350 oascc.ConnectionManager.waitForConnected Wa= iting for client to connect to ZooKeeper [junit4:junit4] 2> 16742 T438 oaz.ClientCnxn$SendThread.logStartConnect O= pening socket connection to server localhost/127.0.0.1:38144. Will not atte= mpt to authenticate using SASL (access denied (javax.security.auth.AuthPerm= ission getLoginConfiguration)) [junit4:junit4] 2> 16743 T438 oaz.ClientCnxn$SendThread.primeConnection S= ocket connection established to localhost/127.0.0.1:38144, initiating sessi= on [junit4:junit4] 2> 16743 T352 oazs.NIOServerCnxnFactory.run Accepted sock= et connection from /140.211.11.196:38162 [junit4:junit4] 2> 16744 T352 oazs.ZooKeeperServer.processConnectRequest = Client attempting to establish new session at /140.211.11.196:38162 [junit4:junit4] 2> 16746 T354 oazs.ZooKeeperServer.finishSessionInit Esta= blished session 0x13d69639f04000b with negotiated timeout 20000 for client = /140.211.11.196:38162 [junit4:junit4] 2> 16746 T438 oaz.ClientCnxn$SendThread.onConnected Sessi= on establishment complete on server localhost/127.0.0.1:38144, sessionid = =3D 0x13d69639f04000b, negotiated timeout =3D 20000 [junit4:junit4] 2> 16746 T439 oascc.ConnectionManager.process Watcher org= .apache.solr.common.cloud.ConnectionManager@6e105df8 name:ZooKeeperConnecti= on Watcher:127.0.0.1:38144 got event WatchedEvent state:SyncConnected type:= None path:null path:null type:None [junit4:junit4] 2> 16746 T350 oascc.ConnectionManager.waitForConnected Cl= ient is connected to ZooKeeper [junit4:junit4] 2> 16749 T355 oazs.PrepRequestProcessor.pRequest2Txn Proc= essed session termination for sessionid: 0x13d69639f04000b [junit4:junit4] 2> 16759 T352 oazs.NIOServerCnxn.closeSock Closed socket = connection for client /140.211.11.196:38162 which had sessionid 0x13d69639f= 04000b [junit4:junit4] 2> 16759 T439 oaz.ClientCnxn$EventThread.run EventThread = shut down [junit4:junit4] 2> 16759 T350 oaz.ZooKeeper.close Session: 0x13d69639f040= 00b closed [junit4:junit4] 2> 16761 T350 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnections=3D500&maxConnectionsPerHost=3D16&so= cketTimeout=3D120000&connTimeout=3D15000 [junit4:junit4] 2> 16772 T350 oaz.ZooKeeper. Initiating client conn= ection, connectString=3D127.0.0.1:38144/solr sessionTimeout=3D30000 watcher= =3Dorg.apache.solr.common.cloud.ConnectionManager@446d6f32 [junit4:junit4] 2> 16774 T350 oascc.ConnectionManager.waitForConnected Wa= iting for client to connect to ZooKeeper [junit4:junit4] 2> 16774 T440 oaz.ClientCnxn$SendThread.logStartConnect O= pening socket connection to server localhost/127.0.0.1:38144. Will not atte= mpt to authenticate using SASL (access denied (javax.security.auth.AuthPerm= ission getLoginConfiguration)) [junit4:junit4] 2> 16775 T440 oaz.ClientCnxn$SendThread.primeConnection S= ocket connection established to localhost/127.0.0.1:38144, initiating sessi= on [junit4:junit4] 2> 16775 T352 oazs.NIOServerCnxnFactory.run Accepted sock= et connection from /140.211.11.196:38163 [junit4:junit4] 2> 16776 T352 oazs.ZooKeeperServer.processConnectRequest = Client attempting to establish new session at /140.211.11.196:38163 [junit4:junit4] 2> 16777 T354 oazs.ZooKeeperServer.finishSessionInit Esta= blished session 0x13d69639f04000c with negotiated timeout 20000 for client = /140.211.11.196:38163 [junit4:junit4] 2> 16777 T440 oaz.ClientCnxn$SendThread.onConnected Sessi= on establishment complete on server localhost/127.0.0.1:38144, sessionid = =3D 0x13d69639f04000c, negotiated timeout =3D 20000 [junit4:junit4] 2> 16778 T441 oascc.ConnectionManager.process Watcher org= .apache.solr.common.cloud.ConnectionManager@446d6f32 name:ZooKeeperConnecti= on Watcher:127.0.0.1:38144/solr got event WatchedEvent state:SyncConnected = type:None path:null path:null type:None [junit4:junit4] 2> 16778 T350 oascc.ConnectionManager.waitForConnected Cl= ient is connected to ZooKeeper [junit4:junit4] 2> 16780 T355 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d69639f04000c type:cre= ate cxid:0x1 zxid:0xa3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 16783 T355 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d69639f04000c type:cre= ate cxid:0x2 zxid:0xa4 txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 16787 T350 oascc.ZkStateReader.createClusterStateWatch= ersAndUpdate Updating cluster state from ZooKeeper...=20 [junit4:junit4] 2> 17629 T373 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 17630 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Update state numShards=3D2 message=3D{ [junit4:junit4] 2> =09 "operation":"state", [junit4:junit4] 2> =09 "core_node_name":"4", [junit4:junit4] 2> =09 "numShards":"2", [junit4:junit4] 2> =09 "shard":"shard1", [junit4:junit4] 2> =09 "roles":null, [junit4:junit4] 2> =09 "state":"recovering", [junit4:junit4] 2> =09 "core":"collection1", [junit4:junit4] 2> =09 "collection":"collection1", [junit4:junit4] 2> =09 "node_name":"127.0.0.1:38157_muhkb%2Fmb", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:38157/muhkb/mb"} [junit4:junit4] 2> 17674 T372 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17674 T424 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17674 T392 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17674 T408 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17674 T379 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17674 T441 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17793 T350 oasc.ZkController.createEphemeralLiveNode R= egister node as live in ZooKeeper:/live_nodes/127.0.0.1:38161_muhkb%2Fmb [junit4:junit4] 2> 17794 T355 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d69639f04000c type:del= ete cxid:0xd zxid:0xa9 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/1= 27.0.0.1:38161_muhkb%2Fmb Error:KeeperErrorCode =3D NoNode for /solr/live_n= odes/127.0.0.1:38161_muhkb%2Fmb [junit4:junit4] 2> 17799 T350 oascc.SolrZkClient.makePath makePath: /live= _nodes/127.0.0.1:38161_muhkb%2Fmb [junit4:junit4] 2> 17802 T392 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/= live_nodes, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17802 T408 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/= live_nodes, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17802 T372 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/= live_nodes, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17803 T379 oascc.ZkStateReader$3.process Updating live= nodes... (5) [junit4:junit4] 2> 17803 T441 oascc.ZkStateReader$3.process Updating live= nodes... (5) [junit4:junit4] 2> 17803 T424 oascc.ZkStateReader$3.process Updating live= nodes... (5) [junit4:junit4] 2> 17803 T379 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/= live_nodes, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 17804 T441 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/= live_nodes, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 17804 T424 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/= live_nodes, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 17805 T392 oascc.ZkStateReader$3.process Updating live= nodes... (5) [junit4:junit4] 2> 17806 T408 oascc.ZkStateReader$3.process Updating live= nodes... (5) [junit4:junit4] 2> 17806 T372 oascc.ZkStateReader$3.process Updating live= nodes... (5) [junit4:junit4] 2> 17813 T442 oasc.CoreContainer.create Creating SolrCore= 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.c= loud.BasicDistributedZk2Test-jetty4-1363272785670/collection1 [junit4:junit4] 2> 17813 T442 oasc.ZkController.createCollectionZkNode Ch= eck for collection zkNode:collection1 [junit4:junit4] 2> 17815 T442 oasc.ZkController.createCollectionZkNode Co= llection zkNode exists [junit4:junit4] 2> 17815 T442 oasc.ZkController.readConfigName Load colle= ction config from:/collections/collection1 [junit4:junit4] 2> 17817 T442 oasc.SolrResourceLoader. new SolrReso= urceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-S= olr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Ba= sicDistributedZk2Test-jetty4-1363272785670/collection1/' [junit4:junit4] 2> 17818 T442 oasc.SolrResourceLoader.replaceClassLoader = Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-= Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk= 2Test-jetty4-1363272785670/collection1/lib/classes/' to classloader [junit4:junit4] 2> 17819 T442 oasc.SolrResourceLoader.replaceClassLoader = Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-= Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk= 2Test-jetty4-1363272785670/collection1/lib/README' to classloader [junit4:junit4] 2> 17869 T442 oasc.SolrConfig. Using Lucene MatchVe= rsion: LUCENE_43 [junit4:junit4] 2> 17931 T442 oasc.SolrConfig. Loaded SolrConfig: s= olrconfig.xml [junit4:junit4] 2> 17933 T442 oass.IndexSchema.readSchema Reading Solr Sc= hema [junit4:junit4] 2> 17939 T442 oass.IndexSchema.readSchema Schema name=3Dt= est [junit4:junit4] 2> 18426 T382 oass.SolrDispatchFilter.handleAdminRequest = /admin/cores {coreNodeName=3D4&state=3Drecovering&nodeName=3D127.0.0.1:3815= 7_muhkb%252Fmb&action=3DPREPRECOVERY&checkLive=3Dtrue&core=3Dcollection1&wt= =3Djavabin&onlyIfLeader=3Dtrue&version=3D2} status=3D0 QTime=3D2008=20 [junit4:junit4] 2> 18538 T442 oass.OpenExchangeRatesOrgProvider.init Init= ialized with rates=3Dopen-exchange-rates.json, refreshInterval=3D1440. [junit4:junit4] 2> 18547 T442 oass.IndexSchema.readSchema default search = field in schema is text [junit4:junit4] 2> 18550 T442 oass.IndexSchema.readSchema unique key fiel= d: id [junit4:junit4] 2> 18571 T442 oass.FileExchangeRateProvider.reload Reload= ing exchange rates from file currency.xml [junit4:junit4] 2> 18576 T442 oass.FileExchangeRateProvider.reload Reload= ing exchange rates from file currency.xml [junit4:junit4] 2> 18580 T442 oass.OpenExchangeRatesOrgProvider.reload Re= loading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 18581 T442 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 18582 T442 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 18582 T442 oass.OpenExchangeRatesOrgProvider.reload Re= loading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 18583 T442 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 18583 T442 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 18583 T442 oasc.SolrCore.initDirectoryFactory org.apac= he.solr.core.MockDirectoryFactory [junit4:junit4] 2> 18584 T442 oasc.SolrCore. [collection1] Opening = new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4= .x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistribu= tedZk2Test-jetty4-1363272785670/collection1/, dataDir=3D./org.apache.solr.c= loud.BasicDistributedZk2Test-1363272769277/jetty4/ [junit4:junit4] 2> 18584 T442 oasc.JmxMonitoredMap. JMX monitoring = is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMB= eanServer@3dbe8711 [junit4:junit4] 2> 18584 T442 oasc.SolrCore.initDirectoryFactory org.apac= he.solr.core.MockDirectoryFactory [junit4:junit4] 2> 18585 T442 oasc.CachingDirectoryFactory.get return new= directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-136327276927= 7/jetty4 forceNew: false [junit4:junit4] 2> 18585 T442 oasc.SolrCore.getNewIndexDir New index dire= ctory detected: old=3Dnull new=3D./org.apache.solr.cloud.BasicDistributedZk= 2Test-1363272769277/jetty4/index/ [junit4:junit4] 2> 18585 T442 oasc.SolrCore.initIndex WARNING [collection= 1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-13= 63272769277/jetty4/index' doesn't exist. Creating new index... [junit4:junit4] 2> 18586 T442 oasc.CachingDirectoryFactory.get return new= directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-136327276927= 7/jetty4/index forceNew: false [junit4:junit4] 2> 18588 T442 oasc.SolrDeletionPolicy.onCommit SolrDeleti= onPolicy.onCommit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@64d091d8 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@213709b3),segFN=3Dsegments_1,generation=3D1,filenames=3D[seg= ments_1] [junit4:junit4] 2> 18588 T442 oasc.SolrDeletionPolicy.updateCommits newes= t commit =3D 1[segments_1] [junit4:junit4] 2> 18590 T442 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "d= edupe" [junit4:junit4] 2> 18590 T442 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "s= tored_sig" [junit4:junit4] 2> 18590 T442 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "d= istrib-dup-test-chain-implicit" [junit4:junit4] 2> 18591 T442 oasc.RequestHandlers.initHandlersFromConfig= created standard: solr.StandardRequestHandler [junit4:junit4] 2> 18591 T442 oasc.RequestHandlers.initHandlersFromConfig= created /get: solr.RealTimeGetHandler [junit4:junit4] 2> 18591 T442 oasc.RequestHandlers.initHandlersFromConfig= adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 2> 18591 T442 oasc.RequestHandlers.initHandlersFromConfig= created /replication: solr.ReplicationHandler [junit4:junit4] 2> 18592 T442 oasc.RequestHandlers.initHandlersFromConfig= created /update: solr.UpdateRequestHandler [junit4:junit4] 2> 18592 T442 oasc.RequestHandlers.initHandlersFromConfig= created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4:junit4] 2> 18597 T442 oashl.XMLLoader.init xsltCacheLifetimeSecon= ds=3D60 [junit4:junit4] 2> 18602 T442 oass.SolrIndexSearcher. Opening Searc= her@b8ef90d main [junit4:junit4] 2> 18602 T442 oasu.UpdateHandler.clearLog Clearing tlog f= iles, tlogDir=3D./org.apache.solr.cloud.BasicDistributedZk2Test-13632727692= 77/jetty4/tlog [junit4:junit4] 2> 18603 T442 oasu.CommitTracker. Hard AutoCommit: = disabled [junit4:junit4] 2> 18603 T442 oasu.CommitTracker. Soft AutoCommit: = disabled [junit4:junit4] 2> 18606 T443 oasc.SolrCore.registerSearcher [collection1= ] Registered new searcher Searcher@b8ef90d main{StandardDirectoryReader(seg= ments_1:1)} [junit4:junit4] 2> 18607 T442 oasc.ZkController.publish publishing core= =3Dcollection1 state=3Ddown [junit4:junit4] 2> 18607 T442 oasc.ZkController.publish numShards not fou= nd on descriptor - reading it from system property [junit4:junit4] 2> 19198 T373 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 19200 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Update state numShards=3D2 message=3D{ [junit4:junit4] 2> =09 "operation":"state", [junit4:junit4] 2> =09 "core_node_name":"5", [junit4:junit4] 2> =09 "numShards":"2", [junit4:junit4] 2> =09 "shard":null, [junit4:junit4] 2> =09 "roles":null, [junit4:junit4] 2> =09 "state":"down", [junit4:junit4] 2> =09 "core":"collection1", [junit4:junit4] 2> =09 "collection":"collection1", [junit4:junit4] 2> =09 "node_name":"127.0.0.1:38161_muhkb%2Fmb", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:38161/muhkb/mb"} [junit4:junit4] 2> 19200 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Collection already exists with numShards=3D2 [junit4:junit4] 2> 19200 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Assigning new node to shard shard=3Dshard2 [junit4:junit4] 2> 19246 T441 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 19246 T424 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 19246 T408 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 19246 T372 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 19246 T379 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 19246 T392 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 19643 T442 oasc.CoreContainer.registerCore registering= core: collection1 [junit4:junit4] 2> 19643 T442 oasc.ZkController.register Register replica= - core:collection1 address:http://127.0.0.1:38161/muhkb/mb collection:coll= ection1 shard:shard2 [junit4:junit4] 2> 19649 T442 oasc.ZkController.register We are http://12= 7.0.0.1:38161/muhkb/mb/collection1/ and leader is http://127.0.0.1:38154/mu= hkb/mb/collection1/ [junit4:junit4] 2> 19649 T442 oasc.ZkController.register No LogReplay nee= ded for core=3Dcollection1 baseURL=3Dhttp://127.0.0.1:38161/muhkb/mb [junit4:junit4] 2> 19649 T442 oasc.ZkController.checkRecovery Core needs = to recover:collection1 [junit4:junit4] 2> 19649 T442 oasu.DefaultSolrCoreState.doRecovery Runnin= g recovery - first canceling any ongoing recovery [junit4:junit4] 2> ASYNC NEW_CORE C61 name=3Dcollection1 org.apache.solr= .core.SolrCore@2ad0107a url=3Dhttp://127.0.0.1:38161/muhkb/mb/collection1 n= ode=3D127.0.0.1:38161_muhkb%2Fmb C61_STATE=3Dcoll:collection1 core:collecti= on1 props:{state=3Ddown, core=3Dcollection1, collection=3Dcollection1, node= _name=3D127.0.0.1:38161_muhkb%2Fmb, base_url=3Dhttp://127.0.0.1:38161/muhkb= /mb} [junit4:junit4] 2> 19650 T444 C61 P38161 oasc.RecoveryStrategy.run Starti= ng recovery process. core=3Dcollection1 recoveringAfterStartup=3Dtrue [junit4:junit4] 2> 19651 T444 C61 P38161 oasc.RecoveryStrategy.doRecovery= ###### startupVersions=3D[] [junit4:junit4] 2> 19651 T442 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 19651 T444 C61 P38161 oasc.ZkController.publish publis= hing core=3Dcollection1 state=3Drecovering [junit4:junit4] 2> 19651 T444 C61 P38161 oasc.ZkController.publish numSha= rds not found on descriptor - reading it from system property [junit4:junit4] 2> 19653 T350 oass.SolrDispatchFilter.init user.dir=3D/us= r/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build= /solr-core/test/J1 [junit4:junit4] 2> 19653 T350 oass.SolrDispatchFilter.init SolrDispatchFi= lter.init() done [junit4:junit4] 2> 19653 T444 C61 P38161 oascsi.HttpClientUtil.createClie= nt Creating new http client, config:maxConnections=3D128&maxConnectionsPerH= ost=3D32&followRedirects=3Dfalse [junit4:junit4] 2> 19654 T350 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&fo= llowRedirects=3Dfalse [junit4:junit4] 2> 19671 T350 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 19674 T350 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&fo= llowRedirects=3Dfalse [junit4:junit4] 2> 19688 T383 oasc.CoreContainer.create Creating SolrCore= 'onenodecollectioncore' using instanceDir: /usr/home/hudson/hudson-slave/w= orkspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apa= che.solr.cloud.BasicDistributedZk2Test-jetty1-1363272773137/onenodecollecti= oncore [junit4:junit4] 2> 19689 T383 oasc.ZkController.createCollectionZkNode Ch= eck for collection zkNode:onenodecollection [junit4:junit4] 2> 19690 T383 oasc.ZkController.createCollectionZkNode Cr= eating collection in ZooKeeper:onenodecollection [junit4:junit4] 2> 19691 T383 oasc.ZkController.getConfName Looking for c= ollection configName [junit4:junit4] 2> 19698 T383 oasc.ZkController.getConfName Only one conf= ig set found in zk - using it:conf1 [junit4:junit4] 2> 19698 T383 oascc.SolrZkClient.makePath makePath: /coll= ections/onenodecollection [junit4:junit4] 2> 19702 T383 oasc.ZkController.readConfigName Load colle= ction config from:/collections/onenodecollection [junit4:junit4] 2> 19705 T383 oasc.SolrResourceLoader. new SolrReso= urceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-S= olr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Ba= sicDistributedZk2Test-jetty1-1363272773137/onenodecollectioncore/' [junit4:junit4] 2> 19804 T383 oasc.SolrConfig. Using Lucene MatchVe= rsion: LUCENE_43 [junit4:junit4] 2> 19905 T383 oasc.SolrConfig. Loaded SolrConfig: s= olrconfig.xml [junit4:junit4] 2> 19907 T383 oass.IndexSchema.readSchema Reading Solr Sc= hema [junit4:junit4] 2> 19917 T383 oass.IndexSchema.readSchema Schema name=3Dt= est [junit4:junit4] 2> C60_STATE=3Dcoll:collection1 core:collection1 props:{= shard=3Dshard1, state=3Drecovering, core=3Dcollection1, collection=3Dcollec= tion1, node_name=3D127.0.0.1:38157_muhkb%2Fmb, base_url=3Dhttp://127.0.0.1:= 38157/muhkb/mb} [junit4:junit4] 2> 20428 T427 C60 P38157 oasc.RecoveryStrategy.doRecovery= Attempting to PeerSync from http://127.0.0.1:38151/muhkb/mb/collection1/ c= ore=3Dcollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 2> 20436 T427 C60 P38157 oascsi.HttpClientUtil.createClie= nt Creating new http client, config:maxConnectionsPerHost=3D20&maxConnectio= ns=3D10000&connTimeout=3D30000&socketTimeout=3D30000&retry=3Dfalse [junit4:junit4] 2> 20454 T427 C60 P38157 oasu.PeerSync.sync PeerSync: cor= e=3Dcollection1 url=3Dhttp://127.0.0.1:38157/muhkb/mb START replicas=3D[htt= p://127.0.0.1:38151/muhkb/mb/collection1/] nUpdates=3D100 [junit4:junit4] 2> 20461 T427 C60 P38157 oasu.PeerSync.sync WARNING no fr= ame of reference to tell of we've missed updates [junit4:junit4] 2> 20462 T427 C60 P38157 oasc.RecoveryStrategy.doRecovery= PeerSync Recovery was not successful - trying replication. core=3Dcollecti= on1 [junit4:junit4] 2> 20462 T427 C60 P38157 oasc.RecoveryStrategy.doRecovery= Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 2> 20462 T427 C60 P38157 oasc.RecoveryStrategy.doRecovery= Begin buffering updates. core=3Dcollection1 [junit4:junit4] 2> 20462 T427 C60 P38157 oasu.UpdateLog.bufferUpdates Sta= rting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog=3Dnull} [junit4:junit4] 2> 20462 T427 C60 P38157 oasc.RecoveryStrategy.replicate = Attempting to replicate from http://127.0.0.1:38151/muhkb/mb/collection1/. = core=3Dcollection1 [junit4:junit4] 2> 20462 T427 C60 P38157 oascsi.HttpClientUtil.createClie= nt Creating new http client, config:maxConnections=3D128&maxConnectionsPerH= ost=3D32&followRedirects=3Dfalse [junit4:junit4] 2> ASYNC NEW_CORE C62 name=3Dcollection1 org.apache.solr= .core.SolrCore@2dedc443 url=3Dhttp://127.0.0.1:38151/muhkb/mb/collection1 n= ode=3D127.0.0.1:38151_muhkb%2Fmb C62_STATE=3Dcoll:collection1 core:collecti= on1 props:{shard=3Dshard1, state=3Dactive, core=3Dcollection1, collection= =3Dcollection1, node_name=3D127.0.0.1:38151_muhkb%2Fmb, base_url=3Dhttp://1= 27.0.0.1:38151/muhkb/mb, leader=3Dtrue} [junit4:junit4] 2> 20473 T384 C62 P38151 REQ /get {getVersions=3D100&dist= rib=3Dfalse&wt=3Djavabin&qt=3D/get&version=3D2} status=3D0 QTime=3D2=20 [junit4:junit4] 2> 20473 T385 C62 P38151 oasu.DirectUpdateHandler2.commit= start commit{,optimize=3Dfalse,openSearcher=3Dfalse,waitSearcher=3Dtrue,ex= pungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 20475 T385 C62 P38151 oasc.SolrDeletionPolicy.onInit S= olrDeletionPolicy.onInit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@3f54b627 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@cf2e646),segFN=3Dsegments_1,generation=3D1,filenames=3D[segm= ents_1] [junit4:junit4] 2> 20476 T385 C62 P38151 oasc.SolrDeletionPolicy.updateCo= mmits newest commit =3D 1[segments_1] [junit4:junit4] 2> 20476 T385 C62 P38151 oasc.SolrDeletionPolicy.onCommit= SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@3f54b627 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@cf2e646),segFN=3Dsegments_1,generation=3D1,filenames=3D[segm= ents_1] [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@3f54b627 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@cf2e646),segFN=3Dsegments_2,generation=3D2,filenames=3D[segm= ents_2] [junit4:junit4] 2> 20477 T385 C62 P38151 oasc.SolrDeletionPolicy.updateCo= mmits newest commit =3D 2[segments_2] [junit4:junit4] 2> 20477 T385 C62 P38151 oass.SolrIndexSearcher. Op= ening Searcher@1b4f43c9 realtime [junit4:junit4] 2> 20477 T385 C62 P38151 oasu.DirectUpdateHandler2.commit= end_commit_flush [junit4:junit4] 2> 20477 T385 C62 P38151 /update {waitSearcher=3Dtrue&ope= nSearcher=3Dfalse&commit=3Dtrue&wt=3Djavabin&commit_end_point=3Dtrue&versio= n=3D2&softCommit=3Dfalse} {commit=3D} 0 4 [junit4:junit4] 2> 20478 T427 C60 P38157 oash.ReplicationHandler.inform C= ommits will be reserved for 10000 [junit4:junit4] 2> 20478 T427 C60 P38157 oascsi.HttpClientUtil.createClie= nt Creating new http client, config:connTimeout=3D5000&socketTimeout=3D2000= 0&allowCompression=3Dfalse&maxConnections=3D10000&maxConnectionsPerHost=3D1= 0000 [junit4:junit4] 2> 20493 T427 C60 P38157 oash.SnapPuller. No value= set for 'pollInterval'. Timer Task not started. [junit4:junit4] 2> 20495 T386 C62 P38151 oash.ReplicationHandler.inform C= ommits will be reserved for 10000 [junit4:junit4] 2> 20496 T386 C62 P38151 REQ /replication {command=3Dinde= xversion&qt=3D/replication&wt=3Djavabin&version=3D2} status=3D0 QTime=3D2= =20 [junit4:junit4] 2> 20497 T427 C60 P38157 oash.SnapPuller.fetchLatestIndex= Master's generation: 2 [junit4:junit4] 2> 20497 T427 C60 P38157 oash.SnapPuller.fetchLatestIndex= Slave's generation: 1 [junit4:junit4] 2> 20497 T427 C60 P38157 oash.SnapPuller.fetchLatestIndex= Starting replication process [junit4:junit4] 2> 20500 T386 C62 P38151 REQ /replication {command=3Dfile= list&qt=3D/replication&wt=3Djavabin&generation=3D2&version=3D2} status=3D0 = QTime=3D1=20 [junit4:junit4] 2> 20500 T427 C60 P38157 oash.SnapPuller.fetchLatestIndex= Number of files in latest index in master: 1 [junit4:junit4] 2> 20501 T427 C60 P38157 oasc.CachingDirectoryFactory.get= return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1= 363272769277/jetty3/index.20130314155309774 forceNew: false [junit4:junit4] 2> 20501 T427 C60 P38157 oash.SnapPuller.fetchLatestIndex= Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@7= 2d3b39a lockFactory=3Dorg.apache.lucene.store.NativeFSLockFactory@61d39d3d)= fullCopy=3Dfalse [junit4:junit4] 2> 20513 T386 C62 P38151 REQ /replication {file=3Dsegment= s_2&command=3Dfilecontent&checksum=3Dtrue&wt=3Dfilestream&qt=3D/replication= &generation=3D2} status=3D0 QTime=3D5=20 [junit4:junit4] 2> 20524 T427 C60 P38157 oash.SnapPuller.fetchLatestIndex= Total time taken for download : 0 secs [junit4:junit4] 2> 20525 T427 C60 P38157 oasu.DefaultSolrCoreState.newInd= exWriter Creating new IndexWriter... [junit4:junit4] 2> 20526 T427 C60 P38157 oasu.DefaultSolrCoreState.newInd= exWriter Waiting until IndexWriter is unused... core=3Dcollection1 [junit4:junit4] 2> 20527 T427 C60 P38157 oasc.SolrDeletionPolicy.onInit S= olrDeletionPolicy.onInit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@588c6ea1 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@438060f4),segFN=3Dsegments_1,generation=3D1,filenames=3D[seg= ments_1] [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@588c6ea1 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@438060f4),segFN=3Dsegments_2,generation=3D2,filenames=3D[seg= ments_2] [junit4:junit4] 2> 20528 T427 C60 P38157 oasc.SolrDeletionPolicy.updateCo= mmits newest commit =3D 2[segments_2] [junit4:junit4] 2> 20528 T427 C60 P38157 oasu.DefaultSolrCoreState.newInd= exWriter New IndexWriter is ready to be used. [junit4:junit4] 2> 20528 T427 C60 P38157 oass.SolrIndexSearcher. Op= ening Searcher@2d235262 main [junit4:junit4] 2> 20529 T426 oasc.SolrCore.registerSearcher [collection1= ] Registered new searcher Searcher@2d235262 main{StandardDirectoryReader(se= gments_2:1:nrt)} [junit4:junit4] 2> 20529 T427 C60 P38157 oash.SnapPuller.fetchLatestIndex= removing temporary index download directory files MockDirWrapper(org.apach= e.lucene.store.RAMDirectory@72d3b39a lockFactory=3Dorg.apache.lucene.store.= NativeFSLockFactory@61d39d3d) [junit4:junit4] 2> 20530 T427 C60 P38157 oasc.RecoveryStrategy.replay No = replay needed. core=3Dcollection1 [junit4:junit4] 2> 20530 T427 C60 P38157 oasc.RecoveryStrategy.doRecovery= Replication Recovery was successful - registering as Active. core=3Dcollec= tion1 [junit4:junit4] 2> 20530 T427 C60 P38157 oasc.ZkController.publish publis= hing core=3Dcollection1 state=3Dactive [junit4:junit4] 2> 20530 T427 C60 P38157 oasc.ZkController.publish numSha= rds not found on descriptor - reading it from system property [junit4:junit4] 2> 20559 T427 C60 P38157 oasc.RecoveryStrategy.doRecovery= Finished recovery process. core=3Dcollection1 [junit4:junit4] 2> 20621 T383 oass.OpenExchangeRatesOrgProvider.init Init= ialized with rates=3Dopen-exchange-rates.json, refreshInterval=3D1440. [junit4:junit4] 2> 20629 T383 oass.IndexSchema.readSchema default search = field in schema is text [junit4:junit4] 2> 20632 T383 oass.IndexSchema.readSchema unique key fiel= d: id [junit4:junit4] 2> 20647 T383 oass.FileExchangeRateProvider.reload Reload= ing exchange rates from file currency.xml [junit4:junit4] 2> 20653 T383 oass.FileExchangeRateProvider.reload Reload= ing exchange rates from file currency.xml [junit4:junit4] 2> 20658 T383 oass.OpenExchangeRatesOrgProvider.reload Re= loading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 20659 T383 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 20660 T383 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 20660 T383 oass.OpenExchangeRatesOrgProvider.reload Re= loading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 20665 T383 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 20665 T383 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 20666 T383 oasc.SolrCore.initDirectoryFactory org.apac= he.solr.core.MockDirectoryFactory [junit4:junit4] 2> 20666 T383 oasc.SolrCore. [onenodecollectioncore= ] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-So= lr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Bas= icDistributedZk2Test-jetty1-1363272773137/onenodecollectioncore/, dataDir= =3D/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr= /build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363272769278/o= nenodecollection/ [junit4:junit4] 2> 20667 T383 oasc.JmxMonitoredMap. JMX monitoring = is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMB= eanServer@3dbe8711 [junit4:junit4] 2> 20668 T383 oasc.SolrCore.initDirectoryFactory org.apac= he.solr.core.MockDirectoryFactory [junit4:junit4] 2> 20668 T383 oasc.CachingDirectoryFactory.get return new= directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.= x-Java6/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-136= 3272769278/onenodecollection forceNew: false [junit4:junit4] 2> 20669 T383 oasc.SolrCore.getNewIndexDir New index dire= ctory detected: old=3Dnull new=3D/usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./solrtest-BasicDist= ributedZk2Test-1363272769278/onenodecollection/index/ [junit4:junit4] 2> 20669 T383 oasc.SolrCore.initIndex WARNING [onenodecol= lectioncore] Solr index directory '/usr/home/hudson/hudson-slave/workspace/= Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./solrtest-BasicDi= stributedZk2Test-1363272769278/onenodecollection/index' doesn't exist. Crea= ting new index... [junit4:junit4] 2> 20669 T383 oasc.CachingDirectoryFactory.get return new= directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.= x-Java6/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-136= 3272769278/onenodecollection/index forceNew: false [junit4:junit4] 2> 20671 T383 oasc.SolrDeletionPolicy.onCommit SolrDeleti= onPolicy.onCommit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@52380405 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@4ea386b8),segFN=3Dsegments_1,generation=3D1,filenames=3D[seg= ments_1] [junit4:junit4] 2> 20672 T383 oasc.SolrDeletionPolicy.updateCommits newes= t commit =3D 1[segments_1] [junit4:junit4] 2> 20674 T383 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "d= edupe" [junit4:junit4] 2> 20674 T383 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "s= tored_sig" [junit4:junit4] 2> 20675 T383 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "d= istrib-dup-test-chain-implicit" [junit4:junit4] 2> 20675 T383 oasc.RequestHandlers.initHandlersFromConfig= created standard: solr.StandardRequestHandler [junit4:junit4] 2> 20676 T383 oasc.RequestHandlers.initHandlersFromConfig= created /get: solr.RealTimeGetHandler [junit4:junit4] 2> 20676 T383 oasc.RequestHandlers.initHandlersFromConfig= adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 2> 20676 T383 oasc.RequestHandlers.initHandlersFromConfig= created /replication: solr.ReplicationHandler [junit4:junit4] 2> 20677 T383 oasc.RequestHandlers.initHandlersFromConfig= created /update: solr.UpdateRequestHandler [junit4:junit4] 2> 20677 T383 oasc.RequestHandlers.initHandlersFromConfig= created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4:junit4] 2> 20683 T383 oashl.XMLLoader.init xsltCacheLifetimeSecon= ds=3D60 [junit4:junit4] 2> 20687 T383 oass.SolrIndexSearcher. Opening Searc= her@330db8ad main [junit4:junit4] 2> 20688 T383 oasu.UpdateHandler.clearLog Clearing tlog f= iles, tlogDir=3D/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4= .x-Java6/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-13= 63272769278/onenodecollection/tlog [junit4:junit4] 2> 20689 T383 oasu.CommitTracker. Hard AutoCommit: = disabled [junit4:junit4] 2> 20689 T383 oasu.CommitTracker. Soft AutoCommit: = disabled [junit4:junit4] 2> 20692 T448 oasc.SolrCore.registerSearcher [onenodecoll= ectioncore] Registered new searcher Searcher@330db8ad main{StandardDirector= yReader(segments_1:1)} [junit4:junit4] 2> 20693 T383 oasc.ZkController.publish publishing core= =3Donenodecollectioncore state=3Ddown [junit4:junit4] 2> 20758 T373 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 20759 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Update state numShards=3D2 message=3D{ [junit4:junit4] 2> =09 "operation":"state", [junit4:junit4] 2> =09 "core_node_name":"5", [junit4:junit4] 2> =09 "numShards":"2", [junit4:junit4] 2> =09 "shard":"shard2", [junit4:junit4] 2> =09 "roles":null, [junit4:junit4] 2> =09 "state":"recovering", [junit4:junit4] 2> =09 "core":"collection1", [junit4:junit4] 2> =09 "collection":"collection1", [junit4:junit4] 2> =09 "node_name":"127.0.0.1:38161_muhkb%2Fmb", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:38161/muhkb/mb"} [junit4:junit4] 2> 20779 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Update state numShards=3D2 message=3D{ [junit4:junit4] 2> =09 "operation":"state", [junit4:junit4] 2> =09 "core_node_name":"4", [junit4:junit4] 2> =09 "numShards":"2", [junit4:junit4] 2> =09 "shard":"shard1", [junit4:junit4] 2> =09 "roles":null, [junit4:junit4] 2> =09 "state":"active", [junit4:junit4] 2> =09 "core":"collection1", [junit4:junit4] 2> =09 "collection":"collection1", [junit4:junit4] 2> =09 "node_name":"127.0.0.1:38157_muhkb%2Fmb", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:38157/muhkb/mb"} [junit4:junit4] 2> 20790 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Update state numShards=3D1 message=3D{ [junit4:junit4] 2> =09 "operation":"state", [junit4:junit4] 2> =09 "core_node_name":null, [junit4:junit4] 2> =09 "numShards":"1", [junit4:junit4] 2> =09 "shard":null, [junit4:junit4] 2> =09 "roles":"none", [junit4:junit4] 2> =09 "state":"down", [junit4:junit4] 2> =09 "core":"onenodecollectioncore", [junit4:junit4] 2> =09 "collection":"onenodecollection", [junit4:junit4] 2> =09 "node_name":"127.0.0.1:38151_muhkb%2Fmb", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:38151/muhkb/mb"} [junit4:junit4] 2> 20791 T373 oasc.Overseer$ClusterStateUpdater.createCol= lection Create collection onenodecollection with numShards 1 [junit4:junit4] 2> 20791 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Assigning new node to shard shard=3Dshard1 [junit4:junit4] 2> 20803 T392 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 20803 T441 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 20803 T372 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 20803 T424 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 20803 T379 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 20803 T408 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 21675 T398 oass.SolrDispatchFilter.handleAdminRequest = /admin/cores {coreNodeName=3D5&state=3Drecovering&nodeName=3D127.0.0.1:3816= 1_muhkb%252Fmb&action=3DPREPRECOVERY&checkLive=3Dtrue&core=3Dcollection1&wt= =3Djavabin&onlyIfLeader=3Dtrue&version=3D2} status=3D0 QTime=3D2002=20 [junit4:junit4] 2> 21696 T383 oasc.CoreContainer.registerCore registering= core: onenodecollectioncore [junit4:junit4] 2> 21697 T383 oasc.ZkController.register Register replica= - core:onenodecollectioncore address:http://127.0.0.1:38151/muhkb/mb colle= ction:onenodecollection shard:shard1 [junit4:junit4] 2> 21698 T383 oascc.SolrZkClient.makePath makePath: /coll= ections/onenodecollection/leader_elect/shard1/election [junit4:junit4] 2> 21725 T355 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d69639f040006 type:del= ete cxid:0xa8 zxid:0xc4 txntype:-1 reqpath:n/a Error Path:/solr/collections= /onenodecollection/leaders Error:KeeperErrorCode =3D NoNode for /solr/colle= ctions/onenodecollection/leaders [junit4:junit4] 2> 21731 T383 oasc.ShardLeaderElectionContext.runLeaderPr= ocess Running the leader process. [junit4:junit4] 2> 21732 T355 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d69639f040006 type:cre= ate cxid:0xa9 zxid:0xc5 txntype:-1 reqpath:n/a Error Path:/solr/overseer Er= ror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 21737 T383 oasc.ShardLeaderElectionContext.waitForRepl= icasToComeUp Enough replicas found to continue. [junit4:junit4] 2> 21737 T383 oasc.ShardLeaderElectionContext.runLeaderPr= ocess I may be the new leader - try and sync [junit4:junit4] 2> 21738 T383 oasc.SyncStrategy.sync Sync replicas to htt= p://127.0.0.1:38151/muhkb/mb/onenodecollectioncore/ [junit4:junit4] 2> 21738 T383 oasc.SyncStrategy.syncReplicas Sync Success= - now sync replicas to me [junit4:junit4] 2> 21738 T383 oasc.SyncStrategy.syncToMe http://127.0.0.1= :38151/muhkb/mb/onenodecollectioncore/ has no replicas [junit4:junit4] 2> 21739 T383 oasc.ShardLeaderElectionContext.runLeaderPr= ocess I am the new leader: http://127.0.0.1:38151/muhkb/mb/onenodecollectio= ncore/ [junit4:junit4] 2> 21739 T383 oascc.SolrZkClient.makePath makePath: /coll= ections/onenodecollection/leaders/shard1 [junit4:junit4] 2> 21746 T355 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d69639f040006 type:cre= ate cxid:0xb3 zxid:0xc9 txntype:-1 reqpath:n/a Error Path:/solr/overseer Er= ror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 22322 T373 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 22372 T424 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 22372 T392 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 22372 T441 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 22372 T372 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 22372 T408 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 22372 T379 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 22413 T383 oasc.ZkController.register We are http://12= 7.0.0.1:38151/muhkb/mb/onenodecollectioncore/ and leader is http://127.0.0.= 1:38151/muhkb/mb/onenodecollectioncore/ [junit4:junit4] 2> 22413 T383 oasc.ZkController.register No LogReplay nee= ded for core=3Donenodecollectioncore baseURL=3Dhttp://127.0.0.1:38151/muhkb= /mb [junit4:junit4] 2> 22414 T383 oasc.ZkController.checkRecovery I am the le= ader, no recovery necessary [junit4:junit4] 2> 22414 T383 oasc.ZkController.publish publishing core= =3Donenodecollectioncore state=3Dactive [junit4:junit4] 2> 22418 T383 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 22419 T383 oass.SolrDispatchFilter.handleAdminRequest = /admin/cores {numShards=3D1&roles=3Dnone&name=3Donenodecollectioncore&actio= n=3DCREATE&collection=3Donenodecollection&dataDir=3D/usr/home/hudson/hudson= -slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/.= /solrtest-BasicDistributedZk2Test-1363272769278/onenodecollection&wt=3Djava= bin&version=3D2} status=3D0 QTime=3D2731=20 [junit4:junit4] 2> 22420 T350 oasc.AbstractDistribZkTestBase.waitForRecov= eriesToFinish Wait for recoveries to finish - collection: onenodecollection= failOnTimeout:true timeout (sec):230 [junit4:junit4] 2> 22422 T350 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 23425 T350 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> C61_STATE=3Dcoll:collection1 core:collection1 props:{= shard=3Dshard2, state=3Drecovering, core=3Dcollection1, collection=3Dcollec= tion1, node_name=3D127.0.0.1:38161_muhkb%2Fmb, base_url=3Dhttp://127.0.0.1:= 38161/muhkb/mb} [junit4:junit4] 2> 23677 T444 C61 P38161 oasc.RecoveryStrategy.doRecovery= Attempting to PeerSync from http://127.0.0.1:38154/muhkb/mb/collection1/ c= ore=3Dcollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 2> 23677 T444 C61 P38161 oasu.PeerSync.sync PeerSync: cor= e=3Dcollection1 url=3Dhttp://127.0.0.1:38161/muhkb/mb START replicas=3D[htt= p://127.0.0.1:38154/muhkb/mb/collection1/] nUpdates=3D100 [junit4:junit4] 2> 23678 T444 C61 P38161 oasu.PeerSync.sync WARNING no fr= ame of reference to tell of we've missed updates [junit4:junit4] 2> 23678 T444 C61 P38161 oasc.RecoveryStrategy.doRecovery= PeerSync Recovery was not successful - trying replication. core=3Dcollecti= on1 [junit4:junit4] 2> 23679 T444 C61 P38161 oasc.RecoveryStrategy.doRecovery= Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 2> 23679 T444 C61 P38161 oasc.RecoveryStrategy.doRecovery= Begin buffering updates. core=3Dcollection1 [junit4:junit4] 2> 23679 T444 C61 P38161 oasu.UpdateLog.bufferUpdates Sta= rting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog=3Dnull} [junit4:junit4] 2> 23679 T444 C61 P38161 oasc.RecoveryStrategy.replicate = Attempting to replicate from http://127.0.0.1:38154/muhkb/mb/collection1/. = core=3Dcollection1 [junit4:junit4] 2> 23679 T444 C61 P38161 oascsi.HttpClientUtil.createClie= nt Creating new http client, config:maxConnections=3D128&maxConnectionsPerH= ost=3D32&followRedirects=3Dfalse [junit4:junit4] 2> ASYNC NEW_CORE C63 name=3Dcollection1 org.apache.solr= .core.SolrCore@1244c1b9 url=3Dhttp://127.0.0.1:38154/muhkb/mb/collection1 n= ode=3D127.0.0.1:38154_muhkb%2Fmb C63_STATE=3Dcoll:collection1 core:collecti= on1 props:{shard=3Dshard2, state=3Dactive, core=3Dcollection1, collection= =3Dcollection1, node_name=3D127.0.0.1:38154_muhkb%2Fmb, base_url=3Dhttp://1= 27.0.0.1:38154/muhkb/mb, leader=3Dtrue} [junit4:junit4] 2> 23693 T399 C63 P38154 REQ /get {getVersions=3D100&dist= rib=3Dfalse&wt=3Djavabin&qt=3D/get&version=3D2} status=3D0 QTime=3D5=20 [junit4:junit4] 2> 23702 T400 C63 P38154 oasu.DirectUpdateHandler2.commit= start commit{,optimize=3Dfalse,openSearcher=3Dfalse,waitSearcher=3Dtrue,ex= pungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 23704 T400 C63 P38154 oasc.SolrDeletionPolicy.onInit S= olrDeletionPolicy.onInit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@1d04e75b lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@7eb9926),segFN=3Dsegments_1,generation=3D1,filenames=3D[segm= ents_1] [junit4:junit4] 2> 23705 T400 C63 P38154 oasc.SolrDeletionPolicy.updateCo= mmits newest commit =3D 1[segments_1] [junit4:junit4] 2> 23705 T400 C63 P38154 oasc.SolrDeletionPolicy.onCommit= SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@1d04e75b lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@7eb9926),segFN=3Dsegments_1,generation=3D1,filenames=3D[segm= ents_1] [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@1d04e75b lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@7eb9926),segFN=3Dsegments_2,generation=3D2,filenames=3D[segm= ents_2] [junit4:junit4] 2> 23706 T400 C63 P38154 oasc.SolrDeletionPolicy.updateCo= mmits newest commit =3D 2[segments_2] [junit4:junit4] 2> 23706 T400 C63 P38154 oass.SolrIndexSearcher. Op= ening Searcher@25b0ead3 realtime [junit4:junit4] 2> 23707 T400 C63 P38154 oasu.DirectUpdateHandler2.commit= end_commit_flush [junit4:junit4] 2> 23707 T400 C63 P38154 /update {waitSearcher=3Dtrue&ope= nSearcher=3Dfalse&commit=3Dtrue&wt=3Djavabin&commit_end_point=3Dtrue&versio= n=3D2&softCommit=3Dfalse} {commit=3D} 0 5 [junit4:junit4] 2> 23708 T444 C61 P38161 oash.ReplicationHandler.inform C= ommits will be reserved for 10000 [junit4:junit4] 2> 23708 T444 C61 P38161 oash.SnapPuller. No value= set for 'pollInterval'. Timer Task not started. [junit4:junit4] 2> 23711 T401 C63 P38154 oash.ReplicationHandler.inform C= ommits will be reserved for 10000 [junit4:junit4] 2> 23711 T401 C63 P38154 REQ /replication {command=3Dinde= xversion&qt=3D/replication&wt=3Djavabin&version=3D2} status=3D0 QTime=3D0= =20 [junit4:junit4] 2> 23712 T444 C61 P38161 oash.SnapPuller.fetchLatestIndex= Master's generation: 2 [junit4:junit4] 2> 23712 T444 C61 P38161 oash.SnapPuller.fetchLatestIndex= Slave's generation: 1 [junit4:junit4] 2> 23713 T444 C61 P38161 oash.SnapPuller.fetchLatestIndex= Starting replication process [junit4:junit4] 2> 23716 T401 C63 P38154 REQ /replication {command=3Dfile= list&qt=3D/replication&wt=3Djavabin&generation=3D2&version=3D2} status=3D0 = QTime=3D1=20 [junit4:junit4] 2> 23717 T444 C61 P38161 oash.SnapPuller.fetchLatestIndex= Number of files in latest index in master: 1 [junit4:junit4] 2> 23718 T444 C61 P38161 oasc.CachingDirectoryFactory.get= return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1= 363272769277/jetty4/index.20130314155312990 forceNew: false [junit4:junit4] 2> 23718 T444 C61 P38161 oash.SnapPuller.fetchLatestIndex= Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@5= 93c2bdb lockFactory=3Dorg.apache.lucene.store.NativeFSLockFactory@863c657) = fullCopy=3Dfalse [junit4:junit4] 2> 23722 T401 C63 P38154 REQ /replication {file=3Dsegment= s_2&command=3Dfilecontent&checksum=3Dtrue&wt=3Dfilestream&qt=3D/replication= &generation=3D2} status=3D0 QTime=3D1=20 [junit4:junit4] 2> 23723 T444 C61 P38161 oash.SnapPuller.fetchLatestIndex= Total time taken for download : 0 secs [junit4:junit4] 2> 23724 T444 C61 P38161 oasu.DefaultSolrCoreState.newInd= exWriter Creating new IndexWriter... [junit4:junit4] 2> 23724 T444 C61 P38161 oasu.DefaultSolrCoreState.newInd= exWriter Waiting until IndexWriter is unused... core=3Dcollection1 [junit4:junit4] 2> 23726 T444 C61 P38161 oasc.SolrDeletionPolicy.onInit S= olrDeletionPolicy.onInit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@64d091d8 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@213709b3),segFN=3Dsegments_1,generation=3D1,filenames=3D[seg= ments_1] [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@64d091d8 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@213709b3),segFN=3Dsegments_2,generation=3D2,filenames=3D[seg= ments_2] [junit4:junit4] 2> 23727 T444 C61 P38161 oasc.SolrDeletionPolicy.updateCo= mmits newest commit =3D 2[segments_2] [junit4:junit4] 2> 23727 T444 C61 P38161 oasu.DefaultSolrCoreState.newInd= exWriter New IndexWriter is ready to be used. [junit4:junit4] 2> 23727 T444 C61 P38161 oass.SolrIndexSearcher. Op= ening Searcher@7ce5bd main [junit4:junit4] 2> 23728 T443 oasc.SolrCore.registerSearcher [collection1= ] Registered new searcher Searcher@7ce5bd main{StandardDirectoryReader(segm= ents_2:1:nrt)} [junit4:junit4] 2> 23729 T444 C61 P38161 oash.SnapPuller.fetchLatestIndex= removing temporary index download directory files MockDirWrapper(org.apach= e.lucene.store.RAMDirectory@593c2bdb lockFactory=3Dorg.apache.lucene.store.= NativeFSLockFactory@863c657) [junit4:junit4] 2> 23730 T444 C61 P38161 oasc.RecoveryStrategy.replay No = replay needed. core=3Dcollection1 [junit4:junit4] 2> 23730 T444 C61 P38161 oasc.RecoveryStrategy.doRecovery= Replication Recovery was successful - registering as Active. core=3Dcollec= tion1 [junit4:junit4] 2> 23730 T444 C61 P38161 oasc.ZkController.publish publis= hing core=3Dcollection1 state=3Dactive [junit4:junit4] 2> 23730 T444 C61 P38161 oasc.ZkController.publish numSha= rds not found on descriptor - reading it from system property [junit4:junit4] 2> 23732 T444 C61 P38161 oasc.RecoveryStrategy.doRecovery= Finished recovery process. core=3Dcollection1 [junit4:junit4] 2> 23884 T373 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 23886 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Update state numShards=3D1 message=3D{ [junit4:junit4] 2> =09 "operation":"state", [junit4:junit4] 2> =09 "core_node_name":null, [junit4:junit4] 2> =09 "numShards":"1", [junit4:junit4] 2> =09 "shard":"shard1", [junit4:junit4] 2> =09 "roles":"none", [junit4:junit4] 2> =09 "state":"active", [junit4:junit4] 2> =09 "core":"onenodecollectioncore", [junit4:junit4] 2> =09 "collection":"onenodecollection", [junit4:junit4] 2> =09 "node_name":"127.0.0.1:38151_muhkb%2Fmb", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:38151/muhkb/mb"} [junit4:junit4] 2> 23893 T373 oasc.Overseer$ClusterStateUpdater.updateSta= te Update state numShards=3D2 message=3D{ [junit4:junit4] 2> =09 "operation":"state", [junit4:junit4] 2> =09 "core_node_name":"5", [junit4:junit4] 2> =09 "numShards":"2", [junit4:junit4] 2> =09 "shard":"shard2", [junit4:junit4] 2> =09 "roles":null, [junit4:junit4] 2> =09 "state":"active", [junit4:junit4] 2> =09 "core":"collection1", [junit4:junit4] 2> =09 "collection":"collection1", [junit4:junit4] 2> =09 "node_name":"127.0.0.1:38161_muhkb%2Fmb", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:38161/muhkb/mb"} [junit4:junit4] 2> 23911 T424 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 23911 T441 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 23911 T392 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 23911 T408 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 23911 T379 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 23911 T372 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 24428 T350 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 24430 T350 oasc.AbstractDistribZkTestBase.waitForRecov= eriesToFinish Recoveries finished - collection: onenodecollection [junit4:junit4] 2> 24430 T350 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&fo= llowRedirects=3Dfalse [junit4:junit4] 2> ASYNC NEW_CORE C64 name=3Donenodecollectioncore org.a= pache.solr.core.SolrCore@17a5f5a5 url=3Dhttp://127.0.0.1:38151/muhkb/mb/one= nodecollectioncore node=3D127.0.0.1:38151_muhkb%2Fmb C64_STATE=3Dcoll:oneno= decollection core:onenodecollectioncore props:{shard=3Dshard1, roles=3Dnone= , state=3Dactive, core=3Donenodecollectioncore, collection=3Donenodecollect= ion, node_name=3D127.0.0.1:38151_muhkb%2Fmb, base_url=3Dhttp://127.0.0.1:38= 151/muhkb/mb, leader=3Dtrue} [junit4:junit4] 2> 24501 T387 C64 P38151 oasc.SolrDeletionPolicy.onInit S= olrDeletionPolicy.onInit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@52380405 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@4ea386b8),segFN=3Dsegments_1,generation=3D1,filenames=3D[seg= ments_1] [junit4:junit4] 2> 24502 T387 C64 P38151 oasc.SolrDeletionPolicy.updateCo= mmits newest commit =3D 1[segments_1] [junit4:junit4] 2> 24506 T387 C64 P38151 /update {wt=3Djavabin&version=3D= 2} {add=3D[1 (1429495133003317248)]} 0 7 [junit4:junit4] 2> 24517 T387 C64 P38151 oasu.DirectUpdateHandler2.commit= start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,exp= ungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 24520 T387 C64 P38151 oasc.SolrDeletionPolicy.onCommit= SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@52380405 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@4ea386b8),segFN=3Dsegments_1,generation=3D1,filenames=3D[seg= ments_1] [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@52380405 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@4ea386b8),segFN=3Dsegments_2,generation=3D2,filenames=3D[_0_= NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0_Lucene41_0.pos, _0_NestedP= ulsing_0.tip, _0.nvm, _0_NestedPulsing_0.tim, _0_NestedPulsing_0.pos, _0_Lu= cene41_0.doc, _0.nvd, segments_2, _0.fdx, _0.si, _0_Lucene41_0.tim, _0_Luce= ne41_0.tip, _0.fdt] [junit4:junit4] 2> 24520 T387 C64 P38151 oasc.SolrDeletionPolicy.updateCo= mmits newest commit =3D 2[_0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, = _0_Lucene41_0.pos, _0_NestedPulsing_0.tip, _0.nvm, _0_NestedPulsing_0.tim, = _0_NestedPulsing_0.pos, _0_Lucene41_0.doc, _0.nvd, segments_2, _0.fdx, _0.s= i, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt] [junit4:junit4] 2> 24522 T387 C64 P38151 oass.SolrIndexSearcher. Op= ening Searcher@52baae9d main [junit4:junit4] 2> 24523 T387 C64 P38151 oasu.DirectUpdateHandler2.commit= end_commit_flush [junit4:junit4] 2> 24524 T448 oasc.SolrCore.registerSearcher [onenodecoll= ectioncore] Registered new searcher Searcher@52baae9d main{StandardDirector= yReader(segments_2:3 _0(4.3):C1)} [junit4:junit4] 2> 24525 T387 C64 P38151 /update {waitSearcher=3Dtrue&com= mit=3Dtrue&wt=3Djavabin&version=3D2&softCommit=3Dfalse} {commit=3D} 0 8 [junit4:junit4] 2> 24531 T387 C64 P38151 REQ /select {q=3D*:*&wt=3Djavabi= n&version=3D2} hits=3D1 status=3D0 QTime=3D1=20 [junit4:junit4] 2> 24533 T350 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&fo= llowRedirects=3Dfalse [junit4:junit4] 2> 24548 T387 C64 P38151 REQ /select {q=3D*:*&wt=3Djavabi= n&version=3D2} hits=3D1 status=3D0 QTime=3D0=20 [junit4:junit4] 2> ASYNC NEW_CORE C65 name=3Dcollection1 org.apache.solr= .core.SolrCore@50dafd61 url=3Dhttp://127.0.0.1:38147/muhkb/mb/collection1 n= ode=3D127.0.0.1:38147_muhkb%2Fmb C65_STATE=3Dcoll:control_collection core:c= ollection1 props:{shard=3Dshard1, state=3Dactive, core=3Dcollection1, colle= ction=3Dcontrol_collection, node_name=3D127.0.0.1:38147_muhkb%2Fmb, base_ur= l=3Dhttp://127.0.0.1:38147/muhkb/mb, leader=3Dtrue} [junit4:junit4] 2> 24565 T362 C65 P38147 oasc.SolrDeletionPolicy.onInit S= olrDeletionPolicy.onInit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@8f9c09e lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@6e045e81),segFN=3Dsegments_1,generation=3D1,filenames=3D[segm= ents_1] [junit4:junit4] 2> 24566 T362 C65 P38147 oasc.SolrDeletionPolicy.updateCo= mmits newest commit =3D 1[segments_1] [junit4:junit4] 2> 24570 T362 C65 P38147 /update {wt=3Djavabin&version=3D= 2} {add=3D[1 (1429495133069377536)]} 0 8 [junit4:junit4] 2> C60_STATE=3Dcoll:collection1 core:collection1 props:{= shard=3Dshard1, state=3Dactive, core=3Dcollection1, collection=3Dcollection= 1, node_name=3D127.0.0.1:38157_muhkb%2Fmb, base_url=3Dhttp://127.0.0.1:3815= 7/muhkb/mb} [junit4:junit4] 2> 24623 T414 C60 P38157 /update {distrib.from=3Dhttp://1= 27.0.0.1:38151/muhkb/mb/collection1/&update.distrib=3DFROMLEADER&wt=3Djavab= in&version=3D2} {add=3D[1 (1429495133115514880)]} 0 3 [junit4:junit4] 2> 24624 T388 C62 P38151 /update {distrib.from=3Dhttp://1= 27.0.0.1:38154/muhkb/mb/collection1/&update.distrib=3DTOLEADER&wt=3Djavabin= &version=3D2} {add=3D[1 (1429495133115514880)]} 0 17 [junit4:junit4] 2> 24625 T404 C63 P38154 /update {wt=3Djavabin&version=3D= 2} {add=3D[1]} 0 30 [junit4:junit4] 2> 24629 T362 C65 P38147 oasu.DirectUpdateHandler2.commit= start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,exp= ungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 24635 T362 C65 P38147 oasc.SolrDeletionPolicy.onCommit= SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@8f9c09e lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@6e045e81),segFN=3Dsegments_1,generation=3D1,filenames=3D[segm= ents_1] [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@8f9c09e lockFactory=3Dorg.apache.lucene.store.Native= FSLockFactory@6e045e81),segFN=3Dsegments_2,generation=3D2,filenames=3D[_0_N= estedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0_Lucene41_0.pos, _0.nvm, _0_= NestedPulsing_0.tip, _0_Memory_1.ram, _0_NestedPulsing_0.tim, _0_NestedPuls= ing_0.pos, _0_Lucene41_0.doc, _0.nvd, segments_2, _0.fdx, _0.si, _0_Lucene4= 1_0.tim, _0_Lucene41_0.tip, _0.fdt] [junit4:junit4] 2> 24636 T362 C65 P38147 oasc.SolrDeletionPolicy.updateCo= mmits newest commit =3D 2[_0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, = _0_Lucene41_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_Memory_1.ram, _0_Nest= edPulsing_0.tim, _0_NestedPulsing_0.pos, _0_Lucene41_0.doc, _0.nvd, segment= s_2, _0.fdx, _0.si, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt] [junit4:junit4] 2> 24638 T362 C65 P38147 oass.SolrIndexSearcher. Op= ening Searcher@63bbd1f9 main [junit4:junit4] 2> 24639 T362 C65 P38147 oasu.DirectUpdateHandler2.commit= end_commit_flush [junit4:junit4] 2> 24640 T376 oasc.SolrCore.registerSearcher [collection1= ] Registered new searcher Searcher@63bbd1f9 main{StandardDirectoryReader(se= gments_2:3 _0(4.3):C1)} [junit4:junit4] 2> 24642 T362 C65 P38147 /update {waitSearcher=3Dtrue&com= mit=3Dtrue&wt=3Djavabin&version=3D2&softCommit=3Dfalse} {commit=3D} 0 13 [junit4:junit4] 2> 24645 T382 C62 P38151 oasu.DirectUpdateHandler2.commit= start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,exp= ungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 24659 T382 C62 P38151 oasc.SolrDeletionPolicy.onCommit= SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@3f54b627 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@cf2e646),segFN=3Dsegments_2,generation=3D2,filenames=3D[segm= ents_2] [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@3f54b627 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@cf2e646),segFN=3Dsegments_3,generation=3D3,filenames=3D[_0_N= estedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0_Lucene41_0.pos, _0.nvm, _0_= NestedPulsing_0.tip, _0_Memory_1.ram, _0_NestedPulsing_0.tim, _0_NestedPuls= ing_0.pos, _0_Lucene41_0.doc, _0.nvd, _0.fdx, _0.si, _0_Lucene41_0.tim, _0_= Lucene41_0.tip, _0.fdt, segments_3] [junit4:junit4] 2> 24660 T382 C62 P38151 oasc.SolrDeletionPolicy.updateCo= mmits newest commit =3D 3[_0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, = _0_Lucene41_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_Memory_1.ram, _0_Nest= edPulsing_0.tim, _0_NestedPulsing_0.pos, _0_Lucene41_0.doc, _0.nvd, _0.fdx,= _0.si, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt, segments_3] [junit4:junit4] 2> 24662 T382 C62 P38151 oass.SolrIndexSearcher. Op= ening Searcher@58bbaf09 main [junit4:junit4] 2> 24663 T382 C62 P38151 oasu.DirectUpdateHandler2.commit= end_commit_flush [junit4:junit4] 2> 24663 T394 oasc.SolrCore.registerSearcher [collection1= ] Registered new searcher Searcher@58bbaf09 main{StandardDirectoryReader(se= gments_3:3:nrt _0(4.3):C1)} [junit4:junit4] 2> 24664 T382 C62 P38151 oasu.SolrCmdDistributor.distribC= ommit Distrib commit to:[StdNode: http://127.0.0.1:38157/muhkb/mb/collectio= n1/, StdNode: http://127.0.0.1:38154/muhkb/mb/collection1/, StdNode: http:/= /127.0.0.1:38161/muhkb/mb/collection1/] params:commit_end_point=3Dtrue&comm= it=3Dtrue&softCommit=3Dfalse&waitSearcher=3Dtrue&expungeDeletes=3Dfalse [junit4:junit4] 2> 24667 T398 C63 P38154 oasu.DirectUpdateHandler2.commit= start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,exp= ungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 24668 T414 C60 P38157 oasu.DirectUpdateHandler2.commit= start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,exp= ungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 24671 T398 C63 P38154 oasc.SolrDeletionPolicy.onCommit= SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@1d04e75b lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@7eb9926),segFN=3Dsegments_2,generation=3D2,filenames=3D[segm= ents_2] [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@1d04e75b lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@7eb9926),segFN=3Dsegments_3,generation=3D3,filenames=3D[segm= ents_3] [junit4:junit4] 2> 24672 T398 C63 P38154 oasc.SolrDeletionPolicy.updateCo= mmits newest commit =3D 3[segments_3] [junit4:junit4] 2> 24672 T398 C63 P38154 oass.SolrIndexSearcher. Op= ening Searcher@3f7188a9 main [junit4:junit4] 2> 24673 T398 C63 P38154 oasu.DirectUpdateHandler2.commit= end_commit_flush [junit4:junit4] 2> 24674 T410 oasc.SolrCore.registerSearcher [collection1= ] Registered new searcher Searcher@3f7188a9 main{StandardDirectoryReader(se= gments_2:1:nrt)} [junit4:junit4] 2> 24674 T398 C63 P38154 /update {waitSearcher=3Dtrue&com= mit=3Dtrue&wt=3Djavabin&expungeDeletes=3Dfalse&commit_end_point=3Dtrue&vers= ion=3D2&softCommit=3Dfalse} {commit=3D} 0 7 [junit4:junit4] 2> 24676 T414 C60 P38157 oasc.SolrDeletionPolicy.onCommit= SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@588c6ea1 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@438060f4),segFN=3Dsegments_2,generation=3D2,filenames=3D[seg= ments_2] [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@588c6ea1 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@438060f4),segFN=3Dsegments_3,generation=3D3,filenames=3D[_0_= NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0_Lucene41_0.pos, _0.nvm, _0= _NestedPulsing_0.tip, _0_Memory_1.ram, _0_NestedPulsing_0.tim, _0_NestedPul= sing_0.pos, _0_Lucene41_0.doc, _0.nvd, _0.fdx, _0.si, _0_Lucene41_0.tim, _0= _Lucene41_0.tip, _0.fdt, segments_3] [junit4:junit4] 2> 24677 T414 C60 P38157 oasc.SolrDeletionPolicy.updateCo= mmits newest commit =3D 3[_0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, = _0_Lucene41_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_Memory_1.ram, _0_Nest= edPulsing_0.tim, _0_NestedPulsing_0.pos, _0_Lucene41_0.doc, _0.nvd, _0.fdx,= _0.si, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt, segments_3] [junit4:junit4] 2> C61_STATE=3Dcoll:collection1 core:collection1 props:{= shard=3Dshard2, state=3Dactive, core=3Dcollection1, collection=3Dcollection= 1, node_name=3D127.0.0.1:38161_muhkb%2Fmb, base_url=3Dhttp://127.0.0.1:3816= 1/muhkb/mb} [junit4:junit4] 2> 24679 T431 C61 P38161 oasu.DirectUpdateHandler2.commit= start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,exp= ungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 24679 T414 C60 P38157 oass.SolrIndexSearcher. Op= ening Searcher@25e2203c main [junit4:junit4] 2> 24680 T414 C60 P38157 oasu.DirectUpdateHandler2.commit= end_commit_flush [junit4:junit4] 2> 24680 T431 C61 P38161 oasc.SolrDeletionPolicy.onCommit= SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@64d091d8 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@213709b3),segFN=3Dsegments_2,generation=3D2,filenames=3D[seg= ments_2] [junit4:junit4] 2> =09=09commit{dir=3DBaseDirectoryWrapper(org.apache.luc= ene.store.RAMDirectory@64d091d8 lockFactory=3Dorg.apache.lucene.store.Nativ= eFSLockFactory@213709b3),segFN=3Dsegments_3,generation=3D3,filenames=3D[seg= ments_3] [junit4:junit4] 2> 24681 T431 C61 P38161 oasc.SolrDeletionPolicy.updateCo= mmits newest commit =3D 3[segments_3] [junit4:junit4] 2> 24681 T426 oasc.SolrCore.registerSearcher [collection1= ] Registered new searcher Searcher@25e2203c main{StandardDirectoryReader(se= gments_3:3:nrt _0(4.3):C1)} [junit4:junit4] 2> 24681 T431 C61 P38161 oass.SolrIndexSearcher. Op= ening Searcher@6fa0b93e main [junit4:junit4] 2> 24682 T414 C60 P38157 /update {waitSearcher=3Dtrue&com= mit=3Dtrue&wt=3Djavabin&expungeDeletes=3Dfalse&commit_end_point=3Dtrue&vers= ion=3D2&softCommit=3Dfalse} {commit=3D} 0 14 [junit4:junit4] 2> 24682 T431 C61 P38161 oasu.DirectUpdateHandler2.commit= end_commit_flush [junit4:junit4] 2> 24683 T443 oasc.SolrCore.registerSearcher [collection1= ] Registered new searcher Searcher@6fa0b93e main{StandardDirectoryReader(se= gments_2:1:nrt)} [junit4:junit4] 2> 24683 T431 C61 P38161 /update {waitSearcher=3Dtrue&com= mit=3Dtrue&wt=3Djavabin&expungeDeletes=3Dfalse&commit_end_point=3Dtrue&vers= ion=3D2&softCommit=3Dfalse} {commit=3D} 0 5 [junit4:junit4] 2> 24684 T382 C62 P38151 /update {waitSearcher=3Dtrue&com= mit=3Dtrue&wt=3Djavabin&version=3D2&softCommit=3Dfalse} {commit=3D} 0 39 [junit4:junit4] 2> 24685 T350 oasc.AbstractDistribZkTestBase.waitForRecov= eriesToFinish Wait for recoveries to finish - collection: collection1 failO= nTimeout:true timeout (sec):230 [junit4:junit4] 2> 24686 T350 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 24688 T350 oasc.AbstractDistribZkTestBase.waitForRecov= eriesToFinish Recoveries finished - collection: collection1 [junit4:junit4] 2> 24692 T362 C65 P38147 REQ /select {q=3D*:*&wt=3Djavabi= n&version=3D2} hits=3D1 status=3D0 QTime=3D1=20 [junit4:junit4] 2> 24694 T350 oaz.ZooKeeper. Initiating client conn= ection, connectString=3D127.0.0.1:38144/solr sessionTimeout=3D10000 watcher= =3Dorg.apache.solr.common.cloud.ConnectionManager@48c95aa2 [junit4:junit4] 2> 24696 T350 oascc.ConnectionManager.waitForConnected Wa= iting for client to connect to ZooKeeper [junit4:junit4] 2> 24696 T456 oaz.ClientCnxn$SendThread.logStartConnect O= pening socket connection to server localhost/127.0.0.1:38144. Will not atte= mpt to authenticate using SASL (access denied (javax.security.auth.AuthPerm= ission getLoginConfiguration)) [junit4:junit4] 2> 24697 T456 oaz.ClientCnxn$SendThread.primeConnection S= ocket connection established to localhost/127.0.0.1:38144, initiating sessi= on [junit4:junit4] 2> 24697 T352 oazs.NIOServerCnxnFactory.run Accepted sock= et connection from /140.211.11.196:38182 [junit4:junit4] 2> 24698 T352 oazs.ZooKeeperServer.processConnectRequest = Client attempting to establish new session at /140.211.11.196:38182 [junit4:junit4] 2> 24700 T354 oazs.ZooKeeperServer.finishSessionInit Esta= blished session 0x13d69639f04000d with negotiated timeout 10000 for client = /140.211.11.196:38182 [junit4:junit4] 2> 24700 T456 oaz.ClientCnxn$SendThread.onConnected Sessi= on establishment complete on server localhost/127.0.0.1:38144, sessionid = =3D 0x13d69639f04000d, negotiated timeout =3D 10000 [junit4:junit4] 2> 24701 T457 oascc.ConnectionManager.process Watcher org= .apache.solr.common.cloud.ConnectionManager@48c95aa2 name:ZooKeeperConnecti= on Watcher:127.0.0.1:38144/solr got event WatchedEvent state:SyncConnected = type:None path:null path:null type:None [junit4:junit4] 2> 24701 T350 oascc.ConnectionManager.waitForConnected Cl= ient is connected to ZooKeeper [junit4:junit4] 2> 24703 T350 oascc.ZkStateReader.createClusterStateWatch= ersAndUpdate Updating cluster state from ZooKeeper...=20 [junit4:junit4] 2> 24713 T355 oazs.PrepRequestProcessor.pRequest2Txn Proc= essed session termination for sessionid: 0x13d69639f04000d [junit4:junit4] 2> 24714 T457 oaz.ClientCnxn$EventThread.r [...truncated too long message...] 79 oazs.SyncRequestProcessor.run SyncRequestProcessor exited! [junit4:junit4] 2> 79422 T2275 oazs.FinalRequestProcessor.shutdown shutdo= wn of request processor complete [junit4:junit4] 2> 79423 T2275 oasc.ZkTestServer.send4LetterWord connecti= ng to 127.0.0.1:12323 12323 [junit4:junit4] 2> 79550 T2277 oazs.NIOServerCnxnFactory.run NIOServerCnx= n factory exited run method [junit4:junit4] 2> 79551 T2275 oazs.ZooKeeperServer.shutdown shutting dow= n [junit4:junit4] 2> 79551 T2275 oazs.SessionTrackerImpl.shutdown Shutting = down [junit4:junit4] 2> 79552 T2275 oazs.PrepRequestProcessor.shutdown Shuttin= g down [junit4:junit4] 2> 79552 T2275 oazs.SyncRequestProcessor.shutdown Shuttin= g down [junit4:junit4] 2> 79552 T2275 oazs.FinalRequestProcessor.shutdown shutdo= wn of request processor complete [junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0 [junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=3DSyncSlice= Test -Dtests.method=3DtestDistribSearch -Dtests.seed=3D60EC721D15B9797D -Dt= ests.multiplier=3D3 -Dtests.slow=3Dtrue -Dtests.locale=3Dde -Dtests.timezon= e=3DAustralia/Broken_Hill -Dtests.file.encoding=3DUS-ASCII [junit4:junit4] FAILURE 79.6s J1 | SyncSliceTest.testDistribSearch <<< [junit4:junit4] > Throwable #1: java.lang.AssertionError [junit4:junit4] > =09at __randomizedtesting.SeedInfo.seed([60EC721D15B97= 97D:E10AFC0562E61941]:0) [junit4:junit4] > =09at org.junit.Assert.fail(Assert.java:92) [junit4:junit4] > =09at org.junit.Assert.assertTrue(Assert.java:43) [junit4:junit4] > =09at org.junit.Assert.assertTrue(Assert.java:54) [junit4:junit4] > =09at org.apache.solr.cloud.SyncSliceTest.doTest(SyncS= liceTest.java:196) [junit4:junit4] > =09at org.apache.solr.BaseDistributedSearchTestCase.te= stDistribSearch(BaseDistributedSearchTestCase.java:806) [junit4:junit4] > =09at sun.reflect.NativeMethodAccessorImpl.invoke0(Nat= ive Method) [junit4:junit4] > =09at sun.reflect.NativeMethodAccessorImpl.invoke(Nati= veMethodAccessorImpl.java:57) [junit4:junit4] > =09at sun.reflect.DelegatingMethodAccessorImpl.invoke(= DelegatingMethodAccessorImpl.java:43) [junit4:junit4] > =09at java.lang.reflect.Method.invoke(Method.java:616) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.RandomizedRun= ner.invoke(RandomizedRunner.java:1559) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.RandomizedRun= ner.access$600(RandomizedRunner.java:79) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.RandomizedRun= ner$6.evaluate(RandomizedRunner.java:737) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.RandomizedRun= ner$7.evaluate(RandomizedRunner.java:773) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.RandomizedRun= ner$8.evaluate(RandomizedRunner.java:787) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.rules.SystemP= ropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53) [junit4:junit4] > =09at org.apache.lucene.util.TestRuleSetupTeardownChai= ned$1.evaluate(TestRuleSetupTeardownChained.java:50) [junit4:junit4] > =09at org.apache.lucene.util.TestRuleFieldCacheSanity$= 1.evaluate(TestRuleFieldCacheSanity.java:51) [junit4:junit4] > =09at org.apache.lucene.util.AbstractBeforeAfterRule$1= .evaluate(AbstractBeforeAfterRule.java:46) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.rules.SystemP= ropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55) [junit4:junit4] > =09at org.apache.lucene.util.TestRuleThreadAndTestName= $1.evaluate(TestRuleThreadAndTestName.java:49) [junit4:junit4] > =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFai= lures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70) [junit4:junit4] > =09at org.apache.lucene.util.TestRuleMarkFailure$1.eva= luate(TestRuleMarkFailure.java:48) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.rules.Stateme= ntAdapter.evaluate(StatementAdapter.java:36) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.ThreadLeakCon= trol$StatementRunner.run(ThreadLeakControl.java:358) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.ThreadLeakCon= trol.forkTimeoutingTask(ThreadLeakControl.java:782) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.ThreadLeakCon= trol$3.evaluate(ThreadLeakControl.java:442) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.RandomizedRun= ner.runSingleTest(RandomizedRunner.java:746) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.RandomizedRun= ner$3.evaluate(RandomizedRunner.java:648) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.RandomizedRun= ner$4.evaluate(RandomizedRunner.java:682) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.RandomizedRun= ner$5.evaluate(RandomizedRunner.java:693) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.rules.Stateme= ntAdapter.evaluate(StatementAdapter.java:36) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.rules.SystemP= ropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53) [junit4:junit4] > =09at org.apache.lucene.util.AbstractBeforeAfterRule$1= .evaluate(AbstractBeforeAfterRule.java:46) [junit4:junit4] > =09at org.apache.lucene.util.TestRuleStoreClassName$1.= evaluate(TestRuleStoreClassName.java:42) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.rules.SystemP= ropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.rules.NoShado= wingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule= .java:39) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.rules.NoShado= wingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule= .java:39) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.rules.Stateme= ntAdapter.evaluate(StatementAdapter.java:36) [junit4:junit4] > =09at org.apache.lucene.util.TestRuleAssertionsRequire= d$1.evaluate(TestRuleAssertionsRequired.java:43) [junit4:junit4] > =09at org.apache.lucene.util.TestRuleMarkFailure$1.eva= luate(TestRuleMarkFailure.java:48) [junit4:junit4] > =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFai= lures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70) [junit4:junit4] > =09at org.apache.lucene.util.TestRuleIgnoreTestSuites$= 1.evaluate(TestRuleIgnoreTestSuites.java:55) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.rules.Stateme= ntAdapter.evaluate(StatementAdapter.java:36) [junit4:junit4] > =09at com.carrotsearch.randomizedtesting.ThreadLeakCon= trol$StatementRunner.run(ThreadLeakControl.java:358) [junit4:junit4] > =09at java.lang.Thread.run(Thread.java:679) [junit4:junit4] 2> 79558 T2275 oas.SolrTestCaseJ4.deleteCore ###deleteCor= e [junit4:junit4] 2> 79561 T2274 ccr.ThreadLeakControl.checkThreadLeaks WAR= NING Will linger awaiting termination of 1 leaked thread(s). [junit4:junit4] 2> 80079 T2278 oazs.SessionTrackerImpl.run SessionTracker= Impl exited loop! [junit4:junit4] 2> NOTE: test params are: codec=3DLucene41, sim=3DRandomS= imilarityProvider(queryNorm=3Dfalse,coord=3Dcrazy): {}, locale=3Dde, timezo= ne=3DAustralia/Broken_Hill [junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. = 1.6.0_32 (64-bit)/cpus=3D16,threads=3D4,free=3D216916560,total=3D453246976 [junit4:junit4] 2> NOTE: All tests run in this JVM: [SignatureUpdateProce= ssorFactoryTest, CurrencyFieldXmlFileTest, IndexReaderFactoryTest, Suggeste= rTSTTest, TestQueryTypes, NumericFieldsTest, TestOmitPositions, TestCSVLoad= er, BadIndexSchemaTest, RequestHandlersTest, TestStressReorder, TestLMJelin= ekMercerSimilarityFactory, ConvertedLegacyTest, PathHierarchyTokenizerFacto= ryTest, BasicZkTest, DateMathParserTest, CurrencyFieldOpenExchangeTest, Tes= tReload, TestFastOutputStream, SolrCmdDistributorTest, TestElisionMultiterm= Query, URLClassifyProcessorTest, BasicDistributedZk2Test, MultiTermTest, Al= iasIntegrationTest, SolrIndexConfigTest, FullSolrCloudDistribCmdsTest, Open= CloseCoreStressTest, TestSystemIdResolver, TestSolr4Spatial, IndexSchemaRun= timeFieldTest, PingRequestHandlerTest, TestUtils, OpenExchangeRatesOrgProvi= derTest, TestFieldCollectionResource, TestFiltering, TestJmxMonitoredMap, T= estDistributedGrouping, XmlUpdateRequestHandlerTest, LeaderElectionIntegrat= ionTest, SpellCheckComponentTest, TestArbitraryIndexDir, StandardRequestHan= dlerTest, FileUtilsTest, StatsComponentTest, ShardRoutingCustomTest, SolrRe= questParserTest, TestCollationField, TestLazyCores, TestStressLucene, Sampl= eTest, TestJmxIntegration, TestSuggestSpellingConverter, CollectionsAPIDist= ributedZkTest, DistanceFunctionTest, SortByFunctionTest, TestRangeQuery, Xs= ltUpdateRequestHandlerTest, RequiredFieldsTest, TestBinaryField, TestUpdate= , TestQuerySenderNoQuery, SolrPluginUtilsTest, SyncSliceTest] [junit4:junit4] Completed on J1 in 80.33s, 1 test, 1 failure <<< FAILURES! [...truncated 412 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:449: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/= common-build.xml:1213: 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:877: There were test failures: 272 suites, 1145 tests, 1 e= rror, 1 failure, 27 ignored (8 assumptions) Total time: 48 minutes 20 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_4313_1869662082.1363273788812 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_4313_1869662082.1363273788812--