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 B882BDCCA for ; Thu, 14 Mar 2013 02:30:58 +0000 (UTC) Received: (qmail 48323 invoked by uid 500); 14 Mar 2013 02:30:57 -0000 Delivered-To: apmail-lucene-dev-archive@lucene.apache.org Received: (qmail 48157 invoked by uid 500); 14 Mar 2013 02:30:55 -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 48126 invoked by uid 99); 14 Mar 2013 02:30:54 -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 02:30:54 +0000 X-ASF-Spam-Status: No, hits=-1999.0 required=5.0 tests=ALL_TRUSTED,FRT_ADOBE2,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 02:30:32 +0000 Received: from aegis.apache.org (localhost [127.0.0.1]) by aegis.apache.org (Postfix) with ESMTP id BFDBBC00CA for ; Thu, 14 Mar 2013 02:30:09 +0000 (UTC) Date: Thu, 14 Mar 2013 02:29:53 +0000 (UTC) From: Apache Jenkins Server To: dev@lucene.apache.org Message-ID: <1448132931.4199.1363228207132.JavaMail.hudson@aegis> In-Reply-To: <1918241159.4110.1363193877215.JavaMail.hudson@aegis> References: <1918241159.4110.1363193877215.JavaMail.hudson@aegis> Subject: [JENKINS] Lucene-Solr-Tests-trunk-Java6 - Build # 16001 - Still Failing MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----=_Part_4198_1899652021.1363228193534" X-Jenkins-Job: Lucene-Solr-Tests-trunk-Java6 X-Jenkins-Result: FAILURE X-Virus-Checked: Checked by ClamAV on apache.org ------=_Part_4198_1899652021.1363228193534 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-Java6/16001/ 1 tests failed. REGRESSION: org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearc= h 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([B04836D63D1D8C3D:31AEB8CE4A42EC01]= :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 8610 lines...] [junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test [junit4:junit4] 2> 0 T2117 oas.BaseDistributedSearchTestCase.initHostCont= ext Setting hostContext system property: / [junit4:junit4] 2> 5 T2117 oas.SolrTestCaseJ4.setUp ###Starting testDistr= ibSearch [junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/worksp= ace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./solrtest-B= asicDistributedZk2Test-1363227524745 [junit4:junit4] 2> 6 T2117 oasc.ZkTestServer.run STARTING ZK TEST SERVER [junit4:junit4] 2> 7 T2118 oasc.ZkTestServer$ZKServerMain.runFromConfig S= tarting server [junit4:junit4] 2> 11 T2118 oazs.ZooKeeperServer.setTickTime tickTime set= to 1000 [junit4:junit4] 2> 11 T2118 oazs.ZooKeeperServer.setMinSessionTimeout min= SessionTimeout set to -1 [junit4:junit4] 2> 11 T2118 oazs.ZooKeeperServer.setMaxSessionTimeout max= SessionTimeout set to -1 [junit4:junit4] 2> 12 T2118 oazs.NIOServerCnxnFactory.configure binding t= o port 0.0.0.0/0.0.0.0:0 [junit4:junit4] 2> 14 T2118 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 t= o /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/sol= r/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1= 363227524744/zookeeper/server1/data/version-2/snapshot.0 [junit4:junit4] 2> 108 T2117 oasc.ZkTestServer.run start zk server on por= t:16556 [junit4:junit4] 2> 108 T2117 oaz.ZooKeeper. Initiating client conne= ction, connectString=3D127.0.0.1:16556 sessionTimeout=3D10000 watcher=3Dorg= .apache.solr.common.cloud.ConnectionManager@6f536152 [junit4:junit4] 2> 109 T2117 oascc.ConnectionManager.waitForConnected Wai= ting for client to connect to ZooKeeper [junit4:junit4] 2> 110 T2123 oaz.ClientCnxn$SendThread.logStartConnect Op= ening socket connection to server localhost/127.0.0.1:16556. Will not attem= pt to authenticate using SASL (access denied (javax.security.auth.AuthPermi= ssion getLoginConfiguration)) [junit4:junit4] 2> 110 T2123 oaz.ClientCnxn$SendThread.primeConnection So= cket connection established to localhost/127.0.0.1:16556, initiating sessio= n [junit4:junit4] 2> 111 T2119 oazs.NIOServerCnxnFactory.run Accepted socke= t connection from /140.211.11.196:51111 [junit4:junit4] 2> 111 T2119 oazs.ZooKeeperServer.processConnectRequest C= lient attempting to establish new session at /140.211.11.196:51111 [junit4:junit4] 2> 111 T2121 oazsp.FileTxnLog.append Creating new log fil= e: log.1 [junit4:junit4] 2> 114 T2121 oazs.ZooKeeperServer.finishSessionInit Estab= lished session 0x13d66b13e920000 with negotiated timeout 10000 for client /= 140.211.11.196:51111 [junit4:junit4] 2> 114 T2123 oaz.ClientCnxn$SendThread.onConnected Sessio= n establishment complete on server localhost/127.0.0.1:16556, sessionid =3D= 0x13d66b13e920000, negotiated timeout =3D 10000 [junit4:junit4] 2> 115 T2124 oascc.ConnectionManager.process Watcher org.= apache.solr.common.cloud.ConnectionManager@6f536152 name:ZooKeeperConnectio= n Watcher:127.0.0.1:16556 got event WatchedEvent state:SyncConnected type:N= one path:null path:null type:None [junit4:junit4] 2> 115 T2117 oascc.ConnectionManager.waitForConnected Cli= ent is connected to ZooKeeper [junit4:junit4] 2> 116 T2117 oascc.SolrZkClient.makePath makePath: /solr [junit4:junit4] 2> 120 T2122 oazs.PrepRequestProcessor.pRequest2Txn Proce= ssed session termination for sessionid: 0x13d66b13e920000 [junit4:junit4] 2> 129 T2124 oaz.ClientCnxn$EventThread.run EventThread s= hut down [junit4:junit4] 2> 129 T2117 oaz.ZooKeeper.close Session: 0x13d66b13e9200= 00 closed [junit4:junit4] 2> 131 T2119 oazs.NIOServerCnxn.closeSock Closed socket c= onnection for client /140.211.11.196:51111 which had sessionid 0x13d66b13e9= 20000 [junit4:junit4] 2> 131 T2117 oaz.ZooKeeper. Initiating client conne= ction, connectString=3D127.0.0.1:16556/solr sessionTimeout=3D10000 watcher= =3Dorg.apache.solr.common.cloud.ConnectionManager@4abff439 [junit4:junit4] 2> 132 T2117 oascc.ConnectionManager.waitForConnected Wai= ting for client to connect to ZooKeeper [junit4:junit4] 2> 132 T2125 oaz.ClientCnxn$SendThread.logStartConnect Op= ening socket connection to server localhost/127.0.0.1:16556. Will not attem= pt to authenticate using SASL (access denied (javax.security.auth.AuthPermi= ssion getLoginConfiguration)) [junit4:junit4] 2> 133 T2125 oaz.ClientCnxn$SendThread.primeConnection So= cket connection established to localhost/127.0.0.1:16556, initiating sessio= n [junit4:junit4] 2> 133 T2119 oazs.NIOServerCnxnFactory.run Accepted socke= t connection from /140.211.11.196:34047 [junit4:junit4] 2> 133 T2119 oazs.ZooKeeperServer.processConnectRequest C= lient attempting to establish new session at /140.211.11.196:34047 [junit4:junit4] 2> 135 T2121 oazs.ZooKeeperServer.finishSessionInit Estab= lished session 0x13d66b13e920001 with negotiated timeout 10000 for client /= 140.211.11.196:34047 [junit4:junit4] 2> 135 T2125 oaz.ClientCnxn$SendThread.onConnected Sessio= n establishment complete on server localhost/127.0.0.1:16556, sessionid =3D= 0x13d66b13e920001, negotiated timeout =3D 10000 [junit4:junit4] 2> 135 T2126 oascc.ConnectionManager.process Watcher org.= apache.solr.common.cloud.ConnectionManager@4abff439 name:ZooKeeperConnectio= n Watcher:127.0.0.1:16556/solr got event WatchedEvent state:SyncConnected t= ype:None path:null path:null type:None [junit4:junit4] 2> 135 T2117 oascc.ConnectionManager.waitForConnected Cli= ent is connected to ZooKeeper [junit4:junit4] 2> 136 T2117 oascc.SolrZkClient.makePath makePath: /colle= ctions/collection1 [junit4:junit4] 2> 146 T2117 oascc.SolrZkClient.makePath makePath: /colle= ctions/collection1/shards [junit4:junit4] 2> 150 T2117 oascc.SolrZkClient.makePath makePath: /colle= ctions/control_collection [junit4:junit4] 2> 153 T2117 oascc.SolrZkClient.makePath makePath: /colle= ctions/control_collection/shards [junit4:junit4] 2> 162 T2117 oasc.AbstractZkTestCase.putConfig put /usr/h= ome/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/= solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/= conf1/solrconfig.xml [junit4:junit4] 2> 163 T2117 oascc.SolrZkClient.makePath makePath: /confi= gs/conf1/solrconfig.xml [junit4:junit4] 2> 177 T2117 oasc.AbstractZkTestCase.putConfig put /usr/h= ome/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/= solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/sch= ema.xml [junit4:junit4] 2> 178 T2117 oascc.SolrZkClient.makePath makePath: /confi= gs/conf1/schema.xml [junit4:junit4] 2> 283 T2117 oasc.AbstractZkTestCase.putConfig put /usr/h= ome/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/= solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/= stopwords.txt [junit4:junit4] 2> 284 T2117 oascc.SolrZkClient.makePath makePath: /confi= gs/conf1/stopwords.txt [junit4:junit4] 2> 287 T2117 oasc.AbstractZkTestCase.putConfig put /usr/h= ome/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/= solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/= protwords.txt [junit4:junit4] 2> 288 T2117 oascc.SolrZkClient.makePath makePath: /confi= gs/conf1/protwords.txt [junit4:junit4] 2> 292 T2117 oasc.AbstractZkTestCase.putConfig put /usr/h= ome/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/= solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/c= urrency.xml [junit4:junit4] 2> 292 T2117 oascc.SolrZkClient.makePath makePath: /confi= gs/conf1/currency.xml [junit4:junit4] 2> 302 T2117 oasc.AbstractZkTestCase.putConfig put /usr/h= ome/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/= solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /con= figs/conf1/open-exchange-rates.json [junit4:junit4] 2> 302 T2117 oascc.SolrZkClient.makePath makePath: /confi= gs/conf1/open-exchange-rates.json [junit4:junit4] 2> 305 T2117 oasc.AbstractZkTestCase.putConfig put /usr/h= ome/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/= solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /= configs/conf1/mapping-ISOLatin1Accent.txt [junit4:junit4] 2> 306 T2117 oascc.SolrZkClient.makePath makePath: /confi= gs/conf1/mapping-ISOLatin1Accent.txt [junit4:junit4] 2> 309 T2117 oasc.AbstractZkTestCase.putConfig put /usr/h= ome/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/= solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/con= f1/old_synonyms.txt [junit4:junit4] 2> 310 T2117 oascc.SolrZkClient.makePath makePath: /confi= gs/conf1/old_synonyms.txt [junit4:junit4] 2> 313 T2117 oasc.AbstractZkTestCase.putConfig put /usr/h= ome/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/= solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/s= ynonyms.txt [junit4:junit4] 2> 314 T2117 oascc.SolrZkClient.makePath makePath: /confi= gs/conf1/synonyms.txt [junit4:junit4] 2> 317 T2122 oazs.PrepRequestProcessor.pRequest2Txn Proce= ssed session termination for sessionid: 0x13d66b13e920001 [junit4:junit4] 2> 318 T2126 oaz.ClientCnxn$EventThread.run EventThread s= hut down [junit4:junit4] 2> 318 T2119 oazs.NIOServerCnxn.closeSock Closed socket c= onnection for client /140.211.11.196:34047 which had sessionid 0x13d66b13e9= 20001 [junit4:junit4] 2> 318 T2117 oaz.ZooKeeper.close Session: 0x13d66b13e9200= 01 closed [junit4:junit4] 2> 534 T2117 oejs.Server.doStart jetty-8.1.8.v20121106 [junit4:junit4] 2> 538 T2117 oejs.AbstractConnector.doStart Started Socke= tConnector@127.0.0.1:14029 [junit4:junit4] 2> 539 T2117 oass.SolrDispatchFilter.init SolrDispatchFil= ter.init() [junit4:junit4] 2> 539 T2117 oasc.SolrResourceLoader.locateSolrHome JNDI = not configured for solr (NoInitialContextEx) [junit4:junit4] 2> 540 T2117 oasc.SolrResourceLoader.locateSolrHome using= system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.= cloud.BasicDistributedZk2Test-controljetty-1363227525058 [junit4:junit4] 2> 540 T2117 oasc.CoreContainer$Initializer.initialize lo= oking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-= Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud= .BasicDistributedZk2Test-controljetty-1363227525058/solr.xml [junit4:junit4] 2> 540 T2117 oasc.CoreContainer. New CoreContainer = 1644733137 [junit4:junit4] 2> 541 T2117 oasc.CoreContainer.load Loading CoreContaine= r using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tes= ts-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDi= stributedZk2Test-controljetty-1363227525058/' [junit4:junit4] 2> 542 T2117 oasc.SolrResourceLoader. new SolrResou= rceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-So= lr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.B= asicDistributedZk2Test-controljetty-1363227525058/' [junit4:junit4] 2> 600 T2117 oashc.HttpShardHandlerFactory.getParameter S= etting socketTimeout to: 120000 [junit4:junit4] 2> 601 T2117 oashc.HttpShardHandlerFactory.getParameter S= etting urlScheme to: http:// [junit4:junit4] 2> 601 T2117 oashc.HttpShardHandlerFactory.getParameter S= etting connTimeout to: 15000 [junit4:junit4] 2> 602 T2117 oashc.HttpShardHandlerFactory.getParameter S= etting maxConnectionsPerHost to: 20 [junit4:junit4] 2> 602 T2117 oashc.HttpShardHandlerFactory.getParameter S= etting corePoolSize to: 0 [junit4:junit4] 2> 603 T2117 oashc.HttpShardHandlerFactory.getParameter S= etting maximumPoolSize to: 2147483647 [junit4:junit4] 2> 603 T2117 oashc.HttpShardHandlerFactory.getParameter S= etting maxThreadIdleTime to: 5 [junit4:junit4] 2> 604 T2117 oashc.HttpShardHandlerFactory.getParameter S= etting sizeOfQueue to: -1 [junit4:junit4] 2> 604 T2117 oashc.HttpShardHandlerFactory.getParameter S= etting fairnessPolicy to: false [junit4:junit4] 2> 604 T2117 oascsi.HttpClientUtil.createClient Creating = new http client, config:maxConnectionsPerHost=3D20&maxConnections=3D10000&s= ocketTimeout=3D120000&connTimeout=3D15000&retry=3Dfalse [junit4:junit4] 2> 627 T2117 oasc.CoreContainer.load Registering Log List= ener [junit4:junit4] 2> 647 T2117 oasc.CoreContainer.initZooKeeper Zookeeper c= lient=3D127.0.0.1:16556/solr [junit4:junit4] 2> 647 T2117 oasc.ZkController.checkChrootPath zkHost inc= ludes chroot [junit4:junit4] 2> 648 T2117 oaz.ZooKeeper. Initiating client conne= ction, connectString=3D127.0.0.1:16556 sessionTimeout=3D60000 watcher=3Dorg= .apache.solr.common.cloud.ConnectionManager@769fc8af [junit4:junit4] 2> 649 T2117 oascc.ConnectionManager.waitForConnected Wai= ting for client to connect to ZooKeeper [junit4:junit4] 2> 649 T2136 oaz.ClientCnxn$SendThread.logStartConnect Op= ening socket connection to server localhost/127.0.0.1:16556. Will not attem= pt to authenticate using SASL (access denied (javax.security.auth.AuthPermi= ssion getLoginConfiguration)) [junit4:junit4] 2> 650 T2136 oaz.ClientCnxn$SendThread.primeConnection So= cket connection established to localhost/127.0.0.1:16556, initiating sessio= n [junit4:junit4] 2> 651 T2119 oazs.NIOServerCnxnFactory.run Accepted socke= t connection from /140.211.11.196:49136 [junit4:junit4] 2> 651 T2119 oazs.ZooKeeperServer.processConnectRequest C= lient attempting to establish new session at /140.211.11.196:49136 [junit4:junit4] 2> 653 T2121 oazs.ZooKeeperServer.finishSessionInit Estab= lished session 0x13d66b13e920002 with negotiated timeout 20000 for client /= 140.211.11.196:49136 [junit4:junit4] 2> 653 T2136 oaz.ClientCnxn$SendThread.onConnected Sessio= n establishment complete on server localhost/127.0.0.1:16556, sessionid =3D= 0x13d66b13e920002, negotiated timeout =3D 20000 [junit4:junit4] 2> 653 T2137 oascc.ConnectionManager.process Watcher org.= apache.solr.common.cloud.ConnectionManager@769fc8af name:ZooKeeperConnectio= n Watcher:127.0.0.1:16556 got event WatchedEvent state:SyncConnected type:N= one path:null path:null type:None [junit4:junit4] 2> 653 T2117 oascc.ConnectionManager.waitForConnected Cli= ent is connected to ZooKeeper [junit4:junit4] 2> 655 T2122 oazs.PrepRequestProcessor.pRequest2Txn Proce= ssed session termination for sessionid: 0x13d66b13e920002 [junit4:junit4] 2> 663 T2137 oaz.ClientCnxn$EventThread.run EventThread s= hut down [junit4:junit4] 2> 663 T2119 oazs.NIOServerCnxn.closeSock Closed socket c= onnection for client /140.211.11.196:49136 which had sessionid 0x13d66b13e9= 20002 [junit4:junit4] 2> 663 T2117 oaz.ZooKeeper.close Session: 0x13d66b13e9200= 02 closed [junit4:junit4] 2> 664 T2117 oascsi.HttpClientUtil.createClient Creating = new http client, config:maxConnections=3D500&maxConnectionsPerHost=3D16&soc= ketTimeout=3D120000&connTimeout=3D15000 [junit4:junit4] 2> 676 T2117 oaz.ZooKeeper. Initiating client conne= ction, connectString=3D127.0.0.1:16556/solr sessionTimeout=3D30000 watcher= =3Dorg.apache.solr.common.cloud.ConnectionManager@66782c49 [junit4:junit4] 2> 677 T2117 oascc.ConnectionManager.waitForConnected Wai= ting for client to connect to ZooKeeper [junit4:junit4] 2> 677 T2138 oaz.ClientCnxn$SendThread.logStartConnect Op= ening socket connection to server localhost/127.0.0.1:16556. Will not attem= pt to authenticate using SASL (access denied (javax.security.auth.AuthPermi= ssion getLoginConfiguration)) [junit4:junit4] 2> 678 T2138 oaz.ClientCnxn$SendThread.primeConnection So= cket connection established to localhost/127.0.0.1:16556, initiating sessio= n [junit4:junit4] 2> 678 T2119 oazs.NIOServerCnxnFactory.run Accepted socke= t connection from /140.211.11.196:40252 [junit4:junit4] 2> 678 T2119 oazs.ZooKeeperServer.processConnectRequest C= lient attempting to establish new session at /140.211.11.196:40252 [junit4:junit4] 2> 681 T2121 oazs.ZooKeeperServer.finishSessionInit Estab= lished session 0x13d66b13e920003 with negotiated timeout 20000 for client /= 140.211.11.196:40252 [junit4:junit4] 2> 681 T2138 oaz.ClientCnxn$SendThread.onConnected Sessio= n establishment complete on server localhost/127.0.0.1:16556, sessionid =3D= 0x13d66b13e920003, negotiated timeout =3D 20000 [junit4:junit4] 2> 681 T2139 oascc.ConnectionManager.process Watcher org.= apache.solr.common.cloud.ConnectionManager@66782c49 name:ZooKeeperConnectio= n Watcher:127.0.0.1:16556/solr got event WatchedEvent state:SyncConnected t= ype:None path:null path:null type:None [junit4:junit4] 2> 681 T2117 oascc.ConnectionManager.waitForConnected Cli= ent is connected to ZooKeeper [junit4:junit4] 2> 684 T2122 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d66b13e920003 type:crea= te cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Erro= r:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 686 T2117 oascc.SolrZkClient.makePath makePath: /live_= nodes [junit4:junit4] 2> 695 T2117 oasc.ZkController.createEphemeralLiveNode Re= gister node as live in ZooKeeper:/live_nodes/127.0.0.1:14029_ [junit4:junit4] 2> 696 T2122 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d66b13e920003 type:dele= te cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/12= 7.0.0.1:14029_ Error:KeeperErrorCode =3D NoNode for /solr/live_nodes/127.0.= 0.1:14029_ [junit4:junit4] 2> 697 T2117 oascc.SolrZkClient.makePath makePath: /live_= nodes/127.0.0.1:14029_ [junit4:junit4] 2> 700 T2117 oascc.SolrZkClient.makePath makePath: /overs= eer_elect/election [junit4:junit4] 2> 713 T2122 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d66b13e920003 type:dele= te cxid:0x16 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_ele= ct/leader Error:KeeperErrorCode =3D NoNode for /solr/overseer_elect/leader [junit4:junit4] 2> 719 T2117 oascc.SolrZkClient.makePath makePath: /overs= eer_elect/leader [junit4:junit4] 2> 722 T2117 oasc.Overseer.start Overseer (id=3D893404790= 62278147-127.0.0.1:14029_-n_0000000000) starting [junit4:junit4] 2> 723 T2122 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d66b13e920003 type:crea= te cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 725 T2122 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d66b13e920003 type:crea= te cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 733 T2122 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d66b13e920003 type:crea= te cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 734 T2122 oazs.PrepRequestProcessor.pRequest Got user-= level KeeperException when processing sessionid:0x13d66b13e920003 type:crea= te cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 741 T2141 oasc.OverseerCollectionProcessor.run Process= current queue of collection creations [junit4:junit4] 2> 742 T2117 oascc.SolrZkClient.makePath makePath: /clust= erstate.json [junit4:junit4] 2> 752 T2117 oascc.SolrZkClient.makePath makePath: /alias= es.json [junit4:junit4] 2> 755 T2117 oascc.ZkStateReader.createClusterStateWatche= rsAndUpdate Updating cluster state from ZooKeeper...=20 [junit4:junit4] 2> 758 T2140 oasc.Overseer$ClusterStateUpdater.run Starti= ng to work on the main queue [junit4:junit4] 2> 765 T2142 oasc.CoreContainer.create Creating SolrCore = 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lu= cene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.= cloud.BasicDistributedZk2Test-controljetty-1363227525058/collection1 [junit4:junit4] 2> 765 T2142 oasc.ZkController.createCollectionZkNode Che= ck for collection zkNode:control_collection [junit4:junit4] 2> 766 T2142 oasc.ZkController.createCollectionZkNode Col= lection zkNode exists [junit4:junit4] 2> 766 T2142 oasc.ZkController.readConfigName Load collec= tion config from:/collections/control_collection [junit4:junit4] 2> 768 T2142 oasc.SolrResourceLoader. new SolrResou= rceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-So= lr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.B= asicDistributedZk2Test-controljetty-1363227525058/collection1/' [junit4:junit4] 2> 770 T2142 oasc.SolrResourceLoader.replaceClassLoader A= dding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk= -Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZ= k2Test-controljetty-1363227525058/collection1/lib/classes/' to classloader [junit4:junit4] 2> 770 T2142 oasc.SolrResourceLoader.replaceClassLoader A= dding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk= -Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZ= k2Test-controljetty-1363227525058/collection1/lib/README' to classloader [junit4:junit4] 2> 823 T2142 oasc.SolrConfig. Using Lucene MatchVer= sion: LUCENE_50 [junit4:junit4] 2> 893 T2142 oasc.SolrConfig. Loaded SolrConfig: so= lrconfig.xml [junit4:junit4] 2> 995 T2142 oass.IndexSchema.readSchema Reading Solr Sch= ema [junit4:junit4] 2> 1001 T2142 oass.IndexSchema.readSchema Schema name=3Dt= est [junit4:junit4] 2> 1667 T2142 oass.OpenExchangeRatesOrgProvider.init Init= ialized with rates=3Dopen-exchange-rates.json, refreshInterval=3D1440. [junit4:junit4] 2> 1679 T2142 oass.IndexSchema.readSchema default search = field in schema is text [junit4:junit4] 2> 1684 T2142 oass.IndexSchema.readSchema unique key fiel= d: id [junit4:junit4] 2> 1710 T2142 oass.FileExchangeRateProvider.reload Reload= ing exchange rates from file currency.xml [junit4:junit4] 2> 1716 T2142 oass.FileExchangeRateProvider.reload Reload= ing exchange rates from file currency.xml [junit4:junit4] 2> 1722 T2142 oass.OpenExchangeRatesOrgProvider.reload Re= loading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 1724 T2142 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 1724 T2142 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 1724 T2142 oass.OpenExchangeRatesOrgProvider.reload Re= loading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 1726 T2142 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 1726 T2142 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 1726 T2142 oasc.SolrCore.initDirectoryFactory org.apac= he.solr.core.MockDirectoryFactory [junit4:junit4] 2> 1727 T2142 oasc.SolrCore. [collection1] Opening = new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-t= runk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistri= butedZk2Test-controljetty-1363227525058/collection1/, dataDir=3D./org.apach= e.solr.cloud.BasicDistributedZk2Test-1363227524744/control/data/ [junit4:junit4] 2> 1727 T2142 oasc.JmxMonitoredMap. JMX monitoring = is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMB= eanServer@5c09624 [junit4:junit4] 2> 1728 T2142 oasc.SolrCore.initDirectoryFactory org.apac= he.solr.core.MockDirectoryFactory [junit4:junit4] 2> 1728 T2142 oasc.CachingDirectoryFactory.get return new= directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-136322752474= 4/control/data forceNew: false [junit4:junit4] 2> 1729 T2142 oasc.SolrCore.getNewIndexDir New index dire= ctory detected: old=3Dnull new=3D./org.apache.solr.cloud.BasicDistributedZk= 2Test-1363227524744/control/data/index/ [junit4:junit4] 2> 1729 T2142 oasc.SolrCore.initIndex WARNING [collection= 1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-13= 63227524744/control/data/index' doesn't exist. Creating new index... [junit4:junit4] 2> 1729 T2142 oasc.CachingDirectoryFactory.get return new= directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-136322752474= 4/control/data/index forceNew: false [junit4:junit4] 2> 1733 T2142 oasc.SolrDeletionPolicy.onCommit SolrDeleti= onPolicy.onCommit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@fdd241a lockFactory=3Dorg.apache.lucen= e.store.NativeFSLockFactory@69a1c8d6; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> 1733 T2142 oasc.SolrDeletionPolicy.updateCommits newes= t commit =3D 1[segments_1] [junit4:junit4] 2> 1736 T2142 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "d= edupe" [junit4:junit4] 2> 1736 T2142 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "s= tored_sig" [junit4:junit4] 2> 1737 T2142 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "d= istrib-dup-test-chain-implicit" [junit4:junit4] 2> 1737 T2142 oasc.RequestHandlers.initHandlersFromConfig= created standard: solr.StandardRequestHandler [junit4:junit4] 2> 1738 T2142 oasc.RequestHandlers.initHandlersFromConfig= created /get: solr.RealTimeGetHandler [junit4:junit4] 2> 1738 T2142 oasc.RequestHandlers.initHandlersFromConfig= adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 2> 1738 T2142 oasc.RequestHandlers.initHandlersFromConfig= created /replication: solr.ReplicationHandler [junit4:junit4] 2> 1739 T2142 oasc.RequestHandlers.initHandlersFromConfig= created /update: solr.UpdateRequestHandler [junit4:junit4] 2> 1739 T2142 oasc.RequestHandlers.initHandlersFromConfig= created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4:junit4] 2> 1747 T2142 oashl.XMLLoader.init xsltCacheLifetimeSecon= ds=3D60 [junit4:junit4] 2> 1755 T2142 oass.SolrIndexSearcher. Opening Searc= her@bd05853 main [junit4:junit4] 2> 1755 T2142 oasu.UpdateHandler.clearLog Clearing tlog f= iles, tlogDir=3D./org.apache.solr.cloud.BasicDistributedZk2Test-13632275247= 44/control/data/tlog [junit4:junit4] 2> 1757 T2142 oasu.CommitTracker. Hard AutoCommit: = disabled [junit4:junit4] 2> 1757 T2142 oasu.CommitTracker. Soft AutoCommit: = disabled [junit4:junit4] 2> 1760 T2143 oasc.SolrCore.registerSearcher [collection1= ] Registered new searcher Searcher@bd05853 main{StandardDirectoryReader(seg= ments_1:1)} [junit4:junit4] 2> 1761 T2142 oasc.ZkController.publish publishing core= =3Dcollection1 state=3Ddown [junit4:junit4] 2> 1761 T2142 oasc.ZkController.publish numShards not fou= nd on descriptor - reading it from system property [junit4:junit4] 2> 1762 T2122 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d66b13e920003 type:cre= ate cxid:0x55 zxid:0x2a txntype:-1 reqpath:n/a Error Path:/solr/overseer/qu= eue Error:KeeperErrorCode =3D NoNode for /solr/overseer/queue [junit4:junit4] 2> 2263 T2140 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 2264 T2140 oasc.Overseer$ClusterStateUpdater.updateSta= te 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:14029_", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:14029"} [junit4:junit4] 2> 2264 T2140 oasc.Overseer$ClusterStateUpdater.createCol= lection Create collection control_collection with numShards 1 [junit4:junit4] 2> 2264 T2140 oasc.Overseer$ClusterStateUpdater.updateSta= te Assigning new node to shard shard=3Dshard1 [junit4:junit4] 2> 2265 T2122 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d66b13e920003 type:cre= ate cxid:0x5d zxid:0x2d txntype:-1 reqpath:n/a Error Path:/solr/overseer/qu= eue-work Error:KeeperErrorCode =3D NoNode for /solr/overseer/queue-work [junit4:junit4] 2> 2281 T2139 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 1) [junit4:junit4] 2> 2798 T2142 oasc.CoreContainer.registerCore registering= core: collection1 [junit4:junit4] 2> 2798 T2142 oasc.ZkController.register Register replica= - core:collection1 address:http://127.0.0.1:14029 collection:control_colle= ction shard:shard1 [junit4:junit4] 2> 2799 T2142 oascc.SolrZkClient.makePath makePath: /coll= ections/control_collection/leader_elect/shard1/election [junit4:junit4] 2> 2817 T2122 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d66b13e920003 type:del= ete cxid:0x77 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/collections= /control_collection/leaders Error:KeeperErrorCode =3D NoNode for /solr/coll= ections/control_collection/leaders [junit4:junit4] 2> 2818 T2142 oasc.ShardLeaderElectionContext.runLeaderPr= ocess Running the leader process. [junit4:junit4] 2> 2819 T2122 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d66b13e920003 type:cre= ate cxid:0x78 zxid:0x38 txntype:-1 reqpath:n/a Error Path:/solr/overseer Er= ror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 2827 T2142 oasc.ShardLeaderElectionContext.waitForRepl= icasToComeUp Enough replicas found to continue. [junit4:junit4] 2> 2828 T2142 oasc.ShardLeaderElectionContext.runLeaderPr= ocess I may be the new leader - try and sync [junit4:junit4] 2> 2828 T2142 oasc.SyncStrategy.sync Sync replicas to htt= p://127.0.0.1:14029/collection1/ [junit4:junit4] 2> 2828 T2142 oasc.SyncStrategy.syncReplicas Sync Success= - now sync replicas to me [junit4:junit4] 2> 2828 T2142 oasc.SyncStrategy.syncToMe http://127.0.0.1= :14029/collection1/ has no replicas [junit4:junit4] 2> 2829 T2142 oasc.ShardLeaderElectionContext.runLeaderPr= ocess I am the new leader: http://127.0.0.1:14029/collection1/ [junit4:junit4] 2> 2829 T2142 oascc.SolrZkClient.makePath makePath: /coll= ections/control_collection/leaders/shard1 [junit4:junit4] 2> 2833 T2122 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d66b13e920003 type:cre= ate cxid:0x82 zxid:0x3c txntype:-1 reqpath:n/a Error Path:/solr/overseer Er= ror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 3795 T2140 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 3844 T2139 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 1) [junit4:junit4] 2> 3906 T2142 oasc.ZkController.register We are http://12= 7.0.0.1:14029/collection1/ and leader is http://127.0.0.1:14029/collection1= / [junit4:junit4] 2> 3906 T2142 oasc.ZkController.register No LogReplay nee= ded for core=3Dcollection1 baseURL=3Dhttp://127.0.0.1:14029 [junit4:junit4] 2> 3906 T2142 oasc.ZkController.checkRecovery I am the le= ader, no recovery necessary [junit4:junit4] 2> 3906 T2142 oasc.ZkController.publish publishing core= =3Dcollection1 state=3Dactive [junit4:junit4] 2> 3907 T2142 oasc.ZkController.publish numShards not fou= nd on descriptor - reading it from system property [junit4:junit4] 2> 3909 T2142 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 3910 T2117 oass.SolrDispatchFilter.init user.dir=3D/us= r/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/bui= ld/solr-core/test/J1 [junit4:junit4] 2> 3910 T2117 oass.SolrDispatchFilter.init SolrDispatchFi= lter.init() done [junit4:junit4] 2> 3911 T2117 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&fo= llowRedirects=3Dfalse [junit4:junit4] 2> 3925 T2117 oascsi.HttpClientUtil.createClient Creating= new http client, config: [junit4:junit4] 2> 3926 T2117 oaz.ZooKeeper. Initiating client conn= ection, connectString=3D127.0.0.1:16556/solr sessionTimeout=3D10000 watcher= =3Dorg.apache.solr.common.cloud.ConnectionManager@442b26b [junit4:junit4] 2> 3927 T2117 oascc.ConnectionManager.waitForConnected Wa= iting for client to connect to ZooKeeper [junit4:junit4] 2> 3927 T2145 oaz.ClientCnxn$SendThread.logStartConnect O= pening socket connection to server localhost/127.0.0.1:16556. Will not atte= mpt to authenticate using SASL (access denied (javax.security.auth.AuthPerm= ission getLoginConfiguration)) [junit4:junit4] 2> 3928 T2145 oaz.ClientCnxn$SendThread.primeConnection S= ocket connection established to localhost/127.0.0.1:16556, initiating sessi= on [junit4:junit4] 2> 3928 T2119 oazs.NIOServerCnxnFactory.run Accepted sock= et connection from /140.211.11.196:32861 [junit4:junit4] 2> 3929 T2119 oazs.ZooKeeperServer.processConnectRequest = Client attempting to establish new session at /140.211.11.196:32861 [junit4:junit4] 2> 3930 T2121 oazs.ZooKeeperServer.finishSessionInit Esta= blished session 0x13d66b13e920004 with negotiated timeout 10000 for client = /140.211.11.196:32861 [junit4:junit4] 2> 3930 T2145 oaz.ClientCnxn$SendThread.onConnected Sessi= on establishment complete on server localhost/127.0.0.1:16556, sessionid = =3D 0x13d66b13e920004, negotiated timeout =3D 10000 [junit4:junit4] 2> 3930 T2146 oascc.ConnectionManager.process Watcher org= .apache.solr.common.cloud.ConnectionManager@442b26b name:ZooKeeperConnectio= n Watcher:127.0.0.1:16556/solr got event WatchedEvent state:SyncConnected t= ype:None path:null path:null type:None [junit4:junit4] 2> 3930 T2117 oascc.ConnectionManager.waitForConnected Cl= ient is connected to ZooKeeper [junit4:junit4] 2> 3932 T2117 oascc.ZkStateReader.createClusterStateWatch= ersAndUpdate Updating cluster state from ZooKeeper...=20 [junit4:junit4] 2> 3934 T2117 oasc.ChaosMonkey.monkeyLog monkey: init - e= xpire sessions:true cause connection loss:true [junit4:junit4] 2> 4133 T2117 oejs.Server.doStart jetty-8.1.8.v20121106 [junit4:junit4] 2> 4136 T2117 oejs.AbstractConnector.doStart Started Sock= etConnector@127.0.0.1:64400 [junit4:junit4] 2> 4136 T2117 oass.SolrDispatchFilter.init SolrDispatchFi= lter.init() [junit4:junit4] 2> 4137 T2117 oasc.SolrResourceLoader.locateSolrHome JNDI= not configured for solr (NoInitialContextEx) [junit4:junit4] 2> 4137 T2117 oasc.SolrResourceLoader.locateSolrHome usin= g system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr= .cloud.BasicDistributedZk2Test-jetty1-1363227528673 [junit4:junit4] 2> 4138 T2117 oasc.CoreContainer$Initializer.initialize l= ooking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene= -Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.clou= d.BasicDistributedZk2Test-jetty1-1363227528673/solr.xml [junit4:junit4] 2> 4138 T2117 oasc.CoreContainer. New CoreContainer= 1233374211 [junit4:junit4] 2> 4139 T2117 oasc.CoreContainer.load Loading CoreContain= er using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicD= istributedZk2Test-jetty1-1363227528673/' [junit4:junit4] 2> 4139 T2117 oasc.SolrResourceLoader. new SolrReso= urceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-S= olr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.= BasicDistributedZk2Test-jetty1-1363227528673/' [junit4:junit4] 2> 4195 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting socketTimeout to: 120000 [junit4:junit4] 2> 4195 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting urlScheme to: http:// [junit4:junit4] 2> 4196 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting connTimeout to: 15000 [junit4:junit4] 2> 4196 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting maxConnectionsPerHost to: 20 [junit4:junit4] 2> 4197 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting corePoolSize to: 0 [junit4:junit4] 2> 4197 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting maximumPoolSize to: 2147483647 [junit4:junit4] 2> 4198 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting maxThreadIdleTime to: 5 [junit4:junit4] 2> 4198 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting sizeOfQueue to: -1 [junit4:junit4] 2> 4199 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting fairnessPolicy to: false [junit4:junit4] 2> 4199 T2117 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnectionsPerHost=3D20&maxConnections=3D10000&= socketTimeout=3D120000&connTimeout=3D15000&retry=3Dfalse [junit4:junit4] 2> 4219 T2117 oasc.CoreContainer.load Registering Log Lis= tener [junit4:junit4] 2> 4243 T2117 oasc.CoreContainer.initZooKeeper Zookeeper = client=3D127.0.0.1:16556/solr [junit4:junit4] 2> 4244 T2117 oasc.ZkController.checkChrootPath zkHost in= cludes chroot [junit4:junit4] 2> 4245 T2117 oaz.ZooKeeper. Initiating client conn= ection, connectString=3D127.0.0.1:16556 sessionTimeout=3D60000 watcher=3Dor= g.apache.solr.common.cloud.ConnectionManager@55794086 [junit4:junit4] 2> 4246 T2117 oascc.ConnectionManager.waitForConnected Wa= iting for client to connect to ZooKeeper [junit4:junit4] 2> 4247 T2156 oaz.ClientCnxn$SendThread.logStartConnect O= pening socket connection to server localhost/127.0.0.1:16556. Will not atte= mpt to authenticate using SASL (access denied (javax.security.auth.AuthPerm= ission getLoginConfiguration)) [junit4:junit4] 2> 4248 T2156 oaz.ClientCnxn$SendThread.primeConnection S= ocket connection established to localhost/127.0.0.1:16556, initiating sessi= on [junit4:junit4] 2> 4248 T2119 oazs.NIOServerCnxnFactory.run Accepted sock= et connection from /140.211.11.196:43415 [junit4:junit4] 2> 4249 T2119 oazs.ZooKeeperServer.processConnectRequest = Client attempting to establish new session at /140.211.11.196:43415 [junit4:junit4] 2> 4251 T2121 oazs.ZooKeeperServer.finishSessionInit Esta= blished session 0x13d66b13e920005 with negotiated timeout 20000 for client = /140.211.11.196:43415 [junit4:junit4] 2> 4251 T2156 oaz.ClientCnxn$SendThread.onConnected Sessi= on establishment complete on server localhost/127.0.0.1:16556, sessionid = =3D 0x13d66b13e920005, negotiated timeout =3D 20000 [junit4:junit4] 2> 4252 T2157 oascc.ConnectionManager.process Watcher org= .apache.solr.common.cloud.ConnectionManager@55794086 name:ZooKeeperConnecti= on Watcher:127.0.0.1:16556 got event WatchedEvent state:SyncConnected type:= None path:null path:null type:None [junit4:junit4] 2> 4252 T2117 oascc.ConnectionManager.waitForConnected Cl= ient is connected to ZooKeeper [junit4:junit4] 2> 4253 T2122 oazs.PrepRequestProcessor.pRequest2Txn Proc= essed session termination for sessionid: 0x13d66b13e920005 [junit4:junit4] 2> 4267 T2119 oazs.NIOServerCnxn.closeSock Closed socket = connection for client /140.211.11.196:43415 which had sessionid 0x13d66b13e= 920005 [junit4:junit4] 2> 4267 T2157 oaz.ClientCnxn$EventThread.run EventThread = shut down [junit4:junit4] 2> 4267 T2117 oaz.ZooKeeper.close Session: 0x13d66b13e920= 005 closed [junit4:junit4] 2> 4268 T2117 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnections=3D500&maxConnectionsPerHost=3D16&so= cketTimeout=3D120000&connTimeout=3D15000 [junit4:junit4] 2> 4278 T2117 oaz.ZooKeeper. Initiating client conn= ection, connectString=3D127.0.0.1:16556/solr sessionTimeout=3D30000 watcher= =3Dorg.apache.solr.common.cloud.ConnectionManager@45af4f83 [junit4:junit4] 2> 4279 T2117 oascc.ConnectionManager.waitForConnected Wa= iting for client to connect to ZooKeeper [junit4:junit4] 2> 4279 T2158 oaz.ClientCnxn$SendThread.logStartConnect O= pening socket connection to server localhost/127.0.0.1:16556. Will not atte= mpt to authenticate using SASL (access denied (javax.security.auth.AuthPerm= ission getLoginConfiguration)) [junit4:junit4] 2> 4280 T2158 oaz.ClientCnxn$SendThread.primeConnection S= ocket connection established to localhost/127.0.0.1:16556, initiating sessi= on [junit4:junit4] 2> 4280 T2119 oazs.NIOServerCnxnFactory.run Accepted sock= et connection from /140.211.11.196:51793 [junit4:junit4] 2> 4281 T2119 oazs.ZooKeeperServer.processConnectRequest = Client attempting to establish new session at /140.211.11.196:51793 [junit4:junit4] 2> 4282 T2121 oazs.ZooKeeperServer.finishSessionInit Esta= blished session 0x13d66b13e920006 with negotiated timeout 20000 for client = /140.211.11.196:51793 [junit4:junit4] 2> 4282 T2158 oaz.ClientCnxn$SendThread.onConnected Sessi= on establishment complete on server localhost/127.0.0.1:16556, sessionid = =3D 0x13d66b13e920006, negotiated timeout =3D 20000 [junit4:junit4] 2> 4282 T2159 oascc.ConnectionManager.process Watcher org= .apache.solr.common.cloud.ConnectionManager@45af4f83 name:ZooKeeperConnecti= on Watcher:127.0.0.1:16556/solr got event WatchedEvent state:SyncConnected = type:None path:null path:null type:None [junit4:junit4] 2> 4282 T2117 oascc.ConnectionManager.waitForConnected Cl= ient is connected to ZooKeeper [junit4:junit4] 2> 4284 T2122 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d66b13e920006 type:cre= ate cxid:0x1 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 4285 T2122 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d66b13e920006 type:cre= ate cxid:0x2 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 4294 T2117 oascc.ZkStateReader.createClusterStateWatch= ersAndUpdate Updating cluster state from ZooKeeper...=20 [junit4:junit4] 2> 5299 T2117 oasc.ZkController.createEphemeralLiveNode R= egister node as live in ZooKeeper:/live_nodes/127.0.0.1:64400_ [junit4:junit4] 2> 5300 T2122 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d66b13e920006 type:del= ete cxid:0xb zxid:0x4c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/1= 27.0.0.1:64400_ Error:KeeperErrorCode =3D NoNode for /solr/live_nodes/127.0= .0.1:64400_ [junit4:junit4] 2> 5306 T2117 oascc.SolrZkClient.makePath makePath: /live= _nodes/127.0.0.1:64400_ [junit4:junit4] 2> 5310 T2139 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/= live_nodes, has occurred - updating... (live nodes size: 1) [junit4:junit4] 2> 5310 T2146 oascc.ZkStateReader$3.process Updating live= nodes... (2) [junit4:junit4] 2> 5311 T2159 oascc.ZkStateReader$3.process Updating live= nodes... (2) [junit4:junit4] 2> 5312 T2139 oascc.ZkStateReader$3.process Updating live= nodes... (2) [junit4:junit4] 2> 5318 T2160 oasc.CoreContainer.create Creating SolrCore= 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr= .cloud.BasicDistributedZk2Test-jetty1-1363227528673/collection1 [junit4:junit4] 2> 5318 T2160 oasc.ZkController.createCollectionZkNode Ch= eck for collection zkNode:collection1 [junit4:junit4] 2> 5319 T2160 oasc.ZkController.createCollectionZkNode Co= llection zkNode exists [junit4:junit4] 2> 5319 T2160 oasc.ZkController.readConfigName Load colle= ction config from:/collections/collection1 [junit4:junit4] 2> 5320 T2160 oasc.SolrResourceLoader. new SolrReso= urceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-S= olr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.= BasicDistributedZk2Test-jetty1-1363227528673/collection1/' [junit4:junit4] 2> 5321 T2160 oasc.SolrResourceLoader.replaceClassLoader = Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trun= k-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributed= Zk2Test-jetty1-1363227528673/collection1/lib/classes/' to classloader [junit4:junit4] 2> 5322 T2160 oasc.SolrResourceLoader.replaceClassLoader = Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trun= k-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributed= Zk2Test-jetty1-1363227528673/collection1/lib/README' to classloader [junit4:junit4] 2> 5358 T2140 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 5359 T2140 oasc.Overseer$ClusterStateUpdater.updateSta= te 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:14029_", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:14029"} [junit4:junit4] 2> 5374 T2139 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 5374 T2146 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 5374 T2159 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 5381 T2160 oasc.SolrConfig. Using Lucene MatchVe= rsion: LUCENE_50 [junit4:junit4] 2> 5441 T2160 oasc.SolrConfig. Loaded SolrConfig: s= olrconfig.xml [junit4:junit4] 2> 5542 T2160 oass.IndexSchema.readSchema Reading Solr Sc= hema [junit4:junit4] 2> 5548 T2160 oass.IndexSchema.readSchema Schema name=3Dt= est [junit4:junit4] 2> 6251 T2160 oass.OpenExchangeRatesOrgProvider.init Init= ialized with rates=3Dopen-exchange-rates.json, refreshInterval=3D1440. [junit4:junit4] 2> 6262 T2160 oass.IndexSchema.readSchema default search = field in schema is text [junit4:junit4] 2> 6265 T2160 oass.IndexSchema.readSchema unique key fiel= d: id [junit4:junit4] 2> 6275 T2160 oass.FileExchangeRateProvider.reload Reload= ing exchange rates from file currency.xml [junit4:junit4] 2> 6278 T2160 oass.FileExchangeRateProvider.reload Reload= ing exchange rates from file currency.xml [junit4:junit4] 2> 6281 T2160 oass.OpenExchangeRatesOrgProvider.reload Re= loading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 6282 T2160 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 6282 T2160 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 6282 T2160 oass.OpenExchangeRatesOrgProvider.reload Re= loading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 6283 T2160 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 6283 T2160 oass.OpenExchangeRatesOrgProvider$OpenExcha= ngeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 6284 T2160 oasc.SolrCore.initDirectoryFactory org.apac= he.solr.core.MockDirectoryFactory [junit4:junit4] 2> 6284 T2160 oasc.SolrCore. [collection1] Opening = new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-t= runk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistri= butedZk2Test-jetty1-1363227528673/collection1/, dataDir=3D./org.apache.solr= .cloud.BasicDistributedZk2Test-1363227524744/jetty1/ [junit4:junit4] 2> 6284 T2160 oasc.JmxMonitoredMap. JMX monitoring = is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMB= eanServer@5c09624 [junit4:junit4] 2> 6284 T2160 oasc.SolrCore.initDirectoryFactory org.apac= he.solr.core.MockDirectoryFactory [junit4:junit4] 2> 6285 T2160 oasc.CachingDirectoryFactory.get return new= directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-136322752474= 4/jetty1 forceNew: false [junit4:junit4] 2> 6285 T2160 oasc.SolrCore.getNewIndexDir New index dire= ctory detected: old=3Dnull new=3D./org.apache.solr.cloud.BasicDistributedZk= 2Test-1363227524744/jetty1/index/ [junit4:junit4] 2> 6285 T2160 oasc.SolrCore.initIndex WARNING [collection= 1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-13= 63227524744/jetty1/index' doesn't exist. Creating new index... [junit4:junit4] 2> 6285 T2160 oasc.CachingDirectoryFactory.get return new= directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-136322752474= 4/jetty1/index forceNew: false [junit4:junit4] 2> 6287 T2160 oasc.SolrDeletionPolicy.onCommit SolrDeleti= onPolicy.onCommit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@6809635b lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@f40f91d; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> 6288 T2160 oasc.SolrDeletionPolicy.updateCommits newes= t commit =3D 1[segments_1] [junit4:junit4] 2> 6289 T2160 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "d= edupe" [junit4:junit4] 2> 6289 T2160 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "s= tored_sig" [junit4:junit4] 2> 6290 T2160 oasup.UpdateRequestProcessorChain.init inse= rting DistributedUpdateProcessorFactory into updateRequestProcessorChain "d= istrib-dup-test-chain-implicit" [junit4:junit4] 2> 6290 T2160 oasc.RequestHandlers.initHandlersFromConfig= created standard: solr.StandardRequestHandler [junit4:junit4] 2> 6291 T2160 oasc.RequestHandlers.initHandlersFromConfig= created /get: solr.RealTimeGetHandler [junit4:junit4] 2> 6291 T2160 oasc.RequestHandlers.initHandlersFromConfig= adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 2> 6291 T2160 oasc.RequestHandlers.initHandlersFromConfig= created /replication: solr.ReplicationHandler [junit4:junit4] 2> 6291 T2160 oasc.RequestHandlers.initHandlersFromConfig= created /update: solr.UpdateRequestHandler [junit4:junit4] 2> 6292 T2160 oasc.RequestHandlers.initHandlersFromConfig= created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4:junit4] 2> 6296 T2160 oashl.XMLLoader.init xsltCacheLifetimeSecon= ds=3D60 [junit4:junit4] 2> 6300 T2160 oass.SolrIndexSearcher. Opening Searc= her@5ee5f76f main [junit4:junit4] 2> 6300 T2160 oasu.UpdateHandler.clearLog Clearing tlog f= iles, tlogDir=3D./org.apache.solr.cloud.BasicDistributedZk2Test-13632275247= 44/jetty1/tlog [junit4:junit4] 2> 6301 T2160 oasu.CommitTracker. Hard AutoCommit: = disabled [junit4:junit4] 2> 6301 T2160 oasu.CommitTracker. Soft AutoCommit: = disabled [junit4:junit4] 2> 6310 T2161 oasc.SolrCore.registerSearcher [collection1= ] Registered new searcher Searcher@5ee5f76f main{StandardDirectoryReader(se= gments_1:1)} [junit4:junit4] 2> 6311 T2160 oasc.ZkController.publish publishing core= =3Dcollection1 state=3Ddown [junit4:junit4] 2> 6311 T2160 oasc.ZkController.publish numShards not fou= nd on descriptor - reading it from system property [junit4:junit4] 2> 6879 T2140 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 6880 T2140 oasc.Overseer$ClusterStateUpdater.updateSta= te 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:64400_", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:64400"} [junit4:junit4] 2> 6880 T2140 oasc.Overseer$ClusterStateUpdater.createCol= lection Create collection collection1 with numShards 2 [junit4:junit4] 2> 6881 T2140 oasc.Overseer$ClusterStateUpdater.updateSta= te Assigning new node to shard shard=3Dshard1 [junit4:junit4] 2> 6933 T2146 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 6933 T2139 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 6933 T2159 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 7314 T2160 oasc.CoreContainer.registerCore registering= core: collection1 [junit4:junit4] 2> 7314 T2160 oasc.ZkController.register Register replica= - core:collection1 address:http://127.0.0.1:64400 collection:collection1 s= hard:shard1 [junit4:junit4] 2> 7315 T2160 oascc.SolrZkClient.makePath makePath: /coll= ections/collection1/leader_elect/shard1/election [junit4:junit4] 2> 7344 T2122 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d66b13e920006 type:del= ete 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> 7345 T2160 oasc.ShardLeaderElectionContext.runLeaderPr= ocess Running the leader process. [junit4:junit4] 2> 7346 T2122 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d66b13e920006 type:cre= ate cxid:0x49 zxid:0x5d txntype:-1 reqpath:n/a Error Path:/solr/overseer Er= ror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 7357 T2160 oasc.ShardLeaderElectionContext.waitForRepl= icasToComeUp Enough replicas found to continue. [junit4:junit4] 2> 7357 T2160 oasc.ShardLeaderElectionContext.runLeaderPr= ocess I may be the new leader - try and sync [junit4:junit4] 2> 7357 T2160 oasc.SyncStrategy.sync Sync replicas to htt= p://127.0.0.1:64400/collection1/ [junit4:junit4] 2> 7358 T2160 oasc.SyncStrategy.syncReplicas Sync Success= - now sync replicas to me [junit4:junit4] 2> 7358 T2160 oasc.SyncStrategy.syncToMe http://127.0.0.1= :64400/collection1/ has no replicas [junit4:junit4] 2> 7358 T2160 oasc.ShardLeaderElectionContext.runLeaderPr= ocess I am the new leader: http://127.0.0.1:64400/collection1/ [junit4:junit4] 2> 7358 T2160 oascc.SolrZkClient.makePath makePath: /coll= ections/collection1/leaders/shard1 [junit4:junit4] 2> 7362 T2122 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d66b13e920006 type:cre= ate cxid:0x53 zxid:0x61 txntype:-1 reqpath:n/a Error Path:/solr/overseer Er= ror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 8440 T2140 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 8463 T2139 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 8463 T2146 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 8463 T2159 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clus= terstate.json, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 8500 T2160 oasc.ZkController.register We are http://12= 7.0.0.1:64400/collection1/ and leader is http://127.0.0.1:64400/collection1= / [junit4:junit4] 2> 8500 T2160 oasc.ZkController.register No LogReplay nee= ded for core=3Dcollection1 baseURL=3Dhttp://127.0.0.1:64400 [junit4:junit4] 2> 8500 T2160 oasc.ZkController.checkRecovery I am the le= ader, no recovery necessary [junit4:junit4] 2> 8500 T2160 oasc.ZkController.publish publishing core= =3Dcollection1 state=3Dactive [junit4:junit4] 2> 8501 T2160 oasc.ZkController.publish numShards not fou= nd on descriptor - reading it from system property [junit4:junit4] 2> 8503 T2160 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 8504 T2117 oass.SolrDispatchFilter.init user.dir=3D/us= r/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/bui= ld/solr-core/test/J1 [junit4:junit4] 2> 8504 T2117 oass.SolrDispatchFilter.init SolrDispatchFi= lter.init() done [junit4:junit4] 2> 8505 T2117 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&fo= llowRedirects=3Dfalse [junit4:junit4] 2> 8717 T2117 oejs.Server.doStart jetty-8.1.8.v20121106 [junit4:junit4] 2> 8721 T2117 oejs.AbstractConnector.doStart Started Sock= etConnector@127.0.0.1:17755 [junit4:junit4] 2> 8722 T2117 oass.SolrDispatchFilter.init SolrDispatchFi= lter.init() [junit4:junit4] 2> 8722 T2117 oasc.SolrResourceLoader.locateSolrHome JNDI= not configured for solr (NoInitialContextEx) [junit4:junit4] 2> 8723 T2117 oasc.SolrResourceLoader.locateSolrHome usin= g system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr= .cloud.BasicDistributedZk2Test-jetty2-1363227533258 [junit4:junit4] 2> 8723 T2117 oasc.CoreContainer$Initializer.initialize l= ooking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene= -Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.clou= d.BasicDistributedZk2Test-jetty2-1363227533258/solr.xml [junit4:junit4] 2> 8724 T2117 oasc.CoreContainer. New CoreContainer= 711119566 [junit4:junit4] 2> 8724 T2117 oasc.CoreContainer.load Loading CoreContain= er using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Te= sts-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicD= istributedZk2Test-jetty2-1363227533258/' [junit4:junit4] 2> 8725 T2117 oasc.SolrResourceLoader. new SolrReso= urceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-S= olr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.= BasicDistributedZk2Test-jetty2-1363227533258/' [junit4:junit4] 2> 8779 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting socketTimeout to: 120000 [junit4:junit4] 2> 8780 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting urlScheme to: http:// [junit4:junit4] 2> 8780 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting connTimeout to: 15000 [junit4:junit4] 2> 8781 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting maxConnectionsPerHost to: 20 [junit4:junit4] 2> 8781 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting corePoolSize to: 0 [junit4:junit4] 2> 8782 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting maximumPoolSize to: 2147483647 [junit4:junit4] 2> 8782 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting maxThreadIdleTime to: 5 [junit4:junit4] 2> 8783 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting sizeOfQueue to: -1 [junit4:junit4] 2> 8783 T2117 oashc.HttpShardHandlerFactory.getParameter = Setting fairnessPolicy to: false [junit4:junit4] 2> 8783 T2117 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnectionsPerHost=3D20&maxConnections=3D10000&= socketTimeout=3D120000&connTimeout=3D15000&retry=3Dfalse [junit4:junit4] 2> 8804 T2117 oasc.CoreContainer.load Registering Log Lis= tener [junit4:junit4] 2> 8823 T2117 oasc.CoreContainer.initZooKeeper Zookeeper = client=3D127.0.0.1:16556/solr [junit4:junit4] 2> 8824 T2117 oasc.ZkController.checkChrootPath zkHost in= cludes chroot [junit4:junit4] 2> 8824 T2117 oaz.ZooKeeper. Initiating client conn= ection, connectString=3D127.0.0.1:16556 sessionTimeout=3D60000 watcher=3Dor= g.apache.solr.common.cloud.ConnectionManager@64b0093e [junit4:junit4] 2> 8825 T2117 oascc.ConnectionManager.waitForConnected Wa= iting for client to connect to ZooKeeper [junit4:junit4] 2> 8826 T2172 oaz.ClientCnxn$SendThread.logStartConnect O= pening socket connection to server localhost/127.0.0.1:16556. Will not atte= mpt to authenticate using SASL (access denied (javax.security.auth.AuthPerm= ission getLoginConfiguration)) [junit4:junit4] 2> 8827 T2172 oaz.ClientCnxn$SendThread.primeConnection S= ocket connection established to localhost/127.0.0.1:16556, initiating sessi= on [junit4:junit4] 2> 8827 T2119 oazs.NIOServerCnxnFactory.run Accepted sock= et connection from /140.211.11.196:30880 [junit4:junit4] 2> 8827 T2119 oazs.ZooKeeperServer.processConnectRequest = Client attempting to establish new session at /140.211.11.196:30880 [junit4:junit4] 2> 8830 T2121 oazs.ZooKeeperServer.finishSessionInit Esta= blished session 0x13d66b13e920007 with negotiated timeout 20000 for client = /140.211.11.196:30880 [junit4:junit4] 2> 8830 T2172 oaz.ClientCnxn$SendThread.onConnected Sessi= on establishment complete on server localhost/127.0.0.1:16556, sessionid = =3D 0x13d66b13e920007, negotiated timeout =3D 20000 [junit4:junit4] 2> 8830 T2173 oascc.ConnectionManager.process Watcher org= .apache.solr.common.cloud.ConnectionManager@64b0093e name:ZooKeeperConnecti= on Watcher:127.0.0.1:16556 got event WatchedEvent state:SyncConnected type:= None path:null path:null type:None [junit4:junit4] 2> 8830 T2117 oascc.ConnectionManager.waitForConnected Cl= ient is connected to ZooKeeper [junit4:junit4] 2> 8833 T2122 oazs.PrepRequestProcessor.pRequest2Txn Proc= essed session termination for sessionid: 0x13d66b13e920007 [junit4:junit4] 2> 8845 T2173 oaz.ClientCnxn$EventThread.run EventThread = shut down [junit4:junit4] 2> 8845 T2119 oazs.NIOServerCnxn.closeSock Closed socket = connection for client /140.211.11.196:30880 which had sessionid 0x13d66b13e= 920007 [junit4:junit4] 2> 8845 T2117 oaz.ZooKeeper.close Session: 0x13d66b13e920= 007 closed [junit4:junit4] 2> 8846 T2117 oascsi.HttpClientUtil.createClient Creating= new http client, config:maxConnections=3D500&maxConnectionsPerHost=3D16&so= cketTimeout=3D120000&connTimeout=3D15000 [junit4:junit4] 2> 8855 T2117 oaz.ZooKeeper. Initiating client conn= ection, connectString=3D127.0.0.1:16556/solr sessionTimeout=3D30000 watcher= =3Dorg.apache.solr.common.cloud.ConnectionManager@5af21858 [junit4:junit4] 2> 8856 T2117 oascc.ConnectionManager.waitForConnected Wa= iting for client to connect to ZooKeeper [junit4:junit4] 2> 8857 T2174 oaz.ClientCnxn$SendThread.logStartConnect O= pening socket connection to server localhost/127.0.0.1:16556. Will not atte= mpt to authenticate using SASL (access denied (javax.security.auth.AuthPerm= ission getLoginConfiguration)) [junit4:junit4] 2> 8857 T2174 oaz.ClientCnxn$SendThread.primeConnection S= ocket connection established to localhost/127.0.0.1:16556, initiating sessi= on [junit4:junit4] 2> 8858 T2119 oazs.NIOServerCnxnFactory.run Accepted sock= et connection from /140.211.11.196:21474 [junit4:junit4] 2> 8858 T2119 oazs.ZooKeeperServer.processConnectRequest = Client attempting to establish new session at /140.211.11.196:21474 [junit4:junit4] 2> 8859 T2121 oazs.ZooKeeperServer.finishSessionInit Esta= blished session 0x13d66b13e920008 with negotiated timeout 20000 for client = /140.211.11.196:21474 [junit4:junit4] 2> 8860 T2174 oaz.ClientCnxn$SendThread.onConnected Sessi= on establishment complete on server localhost/127.0.0.1:16556, sessionid = =3D 0x13d66b13e920008, negotiated timeout =3D 20000 [junit4:junit4] 2> 8860 T2175 oascc.ConnectionManager.process Watcher org= .apache.solr.common.cloud.ConnectionManager@5af21858 name:ZooKeeperConnecti= on Watcher:127.0.0.1:16556/solr got event WatchedEvent state:SyncConnected = type:None path:null path:null type:None [junit4:junit4] 2> 8860 T2117 oascc.ConnectionManager.waitForConnected Cl= ient is connected to ZooKeeper [junit4:junit4] 2> 8862 T2122 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d66b13e920008 type:cre= ate cxid:0x1 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 8864 T2122 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d66b13e920008 type:cre= ate cxid:0x2 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/overseer Err= or:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 8868 T2117 oascc.ZkStateReader.createClusterStateWatch= ersAndUpdate Updating cluster state from ZooKeeper...=20 [junit4:junit4] 2> 9871 T2117 oasc.ZkController.createEphemeralLiveNode R= egister node as live in ZooKeeper:/live_nodes/127.0.0.1:17755_ [junit4:junit4] 2> 9872 T2122 oazs.PrepRequestProcessor.pRequest Got user= -level KeeperException when processing sessionid:0x13d66b13e920008 type:del= ete cxid:0xb zxid:0x70 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/1= 27.0.0.1:17755_ Error:KeeperErrorCode =3D NoNode for /solr/live_nodes/127.0= .0.1:17755_ [junit4:junit4] 2> 9910 T2117 oascc.SolrZkClient.makePath makePath: /live= _nodes/127.0.0.1:17755_ [junit4:junit4] 2> 9913 T2139 oascc.ZkStateReader$2.process A cluster sta= te change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/= live_nodes, has occurred - updating... (live nodes size: 2) [junit4:junit4] 2> 9914 T2146 oascc.ZkStateReader$3.process Updating live= nodes... (3) [junit4:junit4] 2> 9914 T2159 oascc.ZkStateReader$3.process Updating live= nodes... (3) [junit4:junit4] 2> 9914 T2175 oascc.ZkStateReader$3.process Updating live= nodes... (3) [junit4:junit4] 2> 9914 T2159 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> 9914 T2146 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> 9915 T2139 oascc.ZkStateReader$3.process Updating live= nodes... (3) [junit4:junit4] 2> 9921 T2176 oasc.CoreContainer.create Creating SolrCore= 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr= .cloud.BasicDistributedZk2Test-jetty2-1363227533258/collection1 [junit4:junit4] 2> 9921 T2176 oasc.ZkController.createCollectionZkNode Ch= eck for collection zkNode:collection1 [junit4:junit4] 2> 9922 T2176 oasc.ZkController.createCollectionZkNode Co= llection zkNode exists [junit4:junit4] 2> 9922 T2176 oasc.ZkController.readConfigName Load colle= ction config from:/collections/collection1 [junit4:junit4] 2> 9924 T2176 oasc.SolrResourceLoader. new SolrReso= urceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-S= olr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.= BasicDistributedZk2Test-jetty2-1363227533258/collection1/' [junit4:junit4] 2> 9926 T2176 oasc.SolrResourceLoader.replaceClassLoader = Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trun= k-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributed= Zk2Test-jetty2-1363227533258/collection1/lib/README' to classloader [junit4:junit4] 2> 9926 T2176 oasc.SolrResourceLoader.replaceClassLoader = Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trun= k-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributed= Zk2Test-jetty2-1363227533258/collection1/lib/classes/' to classloader [junit4:junit4] 2> 9976 T2140 oascc.ZkStateReader.updateClusterState Upda= ting cloud state from ZooKeeper...=20 [junit4:junit4] 2> 9976 T2140 oasc.Overseer$ClusterStateUpdater.updateSta= te 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:64400_", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:64400"} [junit4:junit4] 2> 9979 T2176 oasc.SolrConfig. Using Lucene MatchVe= rsion: LUCENE_50 [junit4:junit4] 2> 9990 T2146 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> 9990 T2139 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> 9990 T2159 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> 9990 T2175 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> 10043 T2176 oasc.SolrConfig. Loaded SolrConfig: = solrconfig.xml [junit4:junit4] 2> 10144 T2176 oass.IndexSchema.readSchema Reading Solr S= chema [junit4:junit4] 2> 10153 T2176 oass.IndexSchema.readSchema Schema name=3D= test [junit4:junit4] 2> 10868 T2176 oass.OpenExchangeRatesOrgProvider.init Ini= tialized with rates=3Dopen-exchange-rates.json, refreshInterval=3D1440. [junit4:junit4] 2> 10877 T2176 oass.IndexSchema.readSchema default search= field in schema is text [junit4:junit4] 2> 10880 T2176 oass.IndexSchema.readSchema unique key fie= ld: id [junit4:junit4] 2> 10893 T2176 oass.FileExchangeRateProvider.reload Reloa= ding exchange rates from file currency.xml [junit4:junit4] 2> 10898 T2176 oass.FileExchangeRateProvider.reload Reloa= ding exchange rates from file currency.xml [junit4:junit4] 2> 10902 T2176 oass.OpenExchangeRatesOrgProvider.reload R= eloading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 10903 T2176 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 10903 T2176 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 10903 T2176 oass.OpenExchangeRatesOrgProvider.reload R= eloading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 10904 T2176 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 10904 T2176 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 10905 T2176 oasc.SolrCore.initDirectoryFactory org.apa= che.solr.core.MockDirectoryFactory [junit4:junit4] 2> 10905 T2176 oasc.SolrCore. [collection1] Opening= new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-= trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistr= ibutedZk2Test-jetty2-1363227533258/collection1/, dataDir=3D./org.apache.sol= r.cloud.BasicDistributedZk2Test-1363227524744/jetty2/ [junit4:junit4] 2> 10905 T2176 oasc.JmxMonitoredMap. JMX monitoring= is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxM= BeanServer@5c09624 [junit4:junit4] 2> 10905 T2176 oasc.SolrCore.initDirectoryFactory org.apa= che.solr.core.MockDirectoryFactory [junit4:junit4] 2> 10906 T2176 oasc.CachingDirectoryFactory.get return ne= w directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-13632275247= 44/jetty2 forceNew: false [junit4:junit4] 2> 10906 T2176 oasc.SolrCore.getNewIndexDir New index dir= ectory detected: old=3Dnull new=3D./org.apache.solr.cloud.BasicDistributedZ= k2Test-1363227524744/jetty2/index/ [junit4:junit4] 2> 10906 T2176 oasc.SolrCore.initIndex WARNING [collectio= n1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1= 363227524744/jetty2/index' doesn't exist. Creating new index... [junit4:junit4] 2> 10906 T2176 oasc.CachingDirectoryFactory.get return ne= w directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-13632275247= 44/jetty2/index forceNew: false [junit4:junit4] 2> 10909 T2176 oasc.SolrDeletionPolicy.onCommit SolrDelet= ionPolicy.onCommit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@6f4bd2bb lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@5f941df6; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> 10909 T2176 oasc.SolrDeletionPolicy.updateCommits newe= st commit =3D 1[segments_1] [junit4:junit4] 2> 10911 T2176 oasup.UpdateRequestProcessorChain.init ins= erting DistributedUpdateProcessorFactory into updateRequestProcessorChain "= dedupe" [junit4:junit4] 2> 10911 T2176 oasup.UpdateRequestProcessorChain.init ins= erting DistributedUpdateProcessorFactory into updateRequestProcessorChain "= stored_sig" [junit4:junit4] 2> 10911 T2176 oasup.UpdateRequestProcessorChain.init ins= erting DistributedUpdateProcessorFactory into updateRequestProcessorChain "= distrib-dup-test-chain-implicit" [junit4:junit4] 2> 10912 T2176 oasc.RequestHandlers.initHandlersFromConfi= g created standard: solr.StandardRequestHandler [junit4:junit4] 2> 10912 T2176 oasc.RequestHandlers.initHandlersFromConfi= g created /get: solr.RealTimeGetHandler [junit4:junit4] 2> 10912 T2176 oasc.RequestHandlers.initHandlersFromConfi= g adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 2> 10912 T2176 oasc.RequestHandlers.initHandlersFromConfi= g created /replication: solr.ReplicationHandler [junit4:junit4] 2> 10913 T2176 oasc.RequestHandlers.initHandlersFromConfi= g created /update: solr.UpdateRequestHandler [junit4:junit4] 2> 10913 T2176 oasc.RequestHandlers.initHandlersFromConfi= g created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4:junit4] 2> 10918 T2176 oashl.XMLLoader.init xsltCacheLifetimeSeco= nds=3D60 [junit4:junit4] 2> 10923 T2176 oass.SolrIndexSearcher. Opening Sear= cher@7016c606 main [junit4:junit4] 2> 10923 T2176 oasu.UpdateHandler.clearLog Clearing tlog = files, tlogDir=3D./org.apache.solr.cloud.BasicDistributedZk2Test-1363227524= 744/jetty2/tlog [junit4:junit4] 2> 10924 T2176 oasu.CommitTracker. Hard AutoCommit:= disabled [junit4:junit4] 2> 10924 T2176 oasu.CommitTracker. Soft AutoCommit:= disabled [junit4:junit4] 2> 10927 T2177 oasc.SolrCore.registerSearcher [collection= 1] Registered new searcher Searcher@7016c606 main{StandardDirectoryReader(s= egments_1:1)} [junit4:junit4] 2> 10928 T2176 oasc.ZkController.publish publishing core= =3Dcollection1 state=3Ddown [junit4:junit4] 2> 10929 T2176 oasc.ZkController.publish numShards not fo= und on descriptor - reading it from system property [junit4:junit4] 2> 11494 T2140 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 11495 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate 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:17755_", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:17755"} [junit4:junit4] 2> 11495 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate Collection already exists with numShards=3D2 [junit4:junit4] 2> 11495 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate Assigning new node to shard shard=3Dshard2 [junit4:junit4] 2> 11510 T2146 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 11510 T2159 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 11510 T2175 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 11510 T2139 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 11931 T2176 oasc.CoreContainer.registerCore registerin= g core: collection1 [junit4:junit4] 2> 11931 T2176 oasc.ZkController.register Register replic= a - core:collection1 address:http://127.0.0.1:17755 collection:collection1 = shard:shard2 [junit4:junit4] 2> 11932 T2176 oascc.SolrZkClient.makePath makePath: /col= lections/collection1/leader_elect/shard2/election [junit4:junit4] 2> 11985 T2122 oazs.PrepRequestProcessor.pRequest Got use= r-level KeeperException when processing sessionid:0x13d66b13e920008 type:de= lete cxid:0x47 zxid:0x7f txntype:-1 reqpath:n/a Error Path:/solr/collection= s/collection1/leaders/shard2 Error:KeeperErrorCode =3D NoNode for /solr/col= lections/collection1/leaders/shard2 [junit4:junit4] 2> 12021 T2176 oasc.ShardLeaderElectionContext.runLeaderP= rocess Running the leader process. [junit4:junit4] 2> 12022 T2122 oazs.PrepRequestProcessor.pRequest Got use= r-level KeeperException when processing sessionid:0x13d66b13e920008 type:cr= eate cxid:0x48 zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/overseer E= rror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 12046 T2176 oasc.ShardLeaderElectionContext.waitForRep= licasToComeUp Enough replicas found to continue. [junit4:junit4] 2> 12046 T2176 oasc.ShardLeaderElectionContext.runLeaderP= rocess I may be the new leader - try and sync [junit4:junit4] 2> 12046 T2176 oasc.SyncStrategy.sync Sync replicas to ht= tp://127.0.0.1:17755/collection1/ [junit4:junit4] 2> 12046 T2176 oasc.SyncStrategy.syncReplicas Sync Succes= s - now sync replicas to me [junit4:junit4] 2> 12047 T2176 oasc.SyncStrategy.syncToMe http://127.0.0.= 1:17755/collection1/ has no replicas [junit4:junit4] 2> 12047 T2176 oasc.ShardLeaderElectionContext.runLeaderP= rocess I am the new leader: http://127.0.0.1:17755/collection1/ [junit4:junit4] 2> 12047 T2176 oascc.SolrZkClient.makePath makePath: /col= lections/collection1/leaders/shard2 [junit4:junit4] 2> 12050 T2122 oazs.PrepRequestProcessor.pRequest Got use= r-level KeeperException when processing sessionid:0x13d66b13e920008 type:cr= eate cxid:0x51 zxid:0x83 txntype:-1 reqpath:n/a Error Path:/solr/overseer E= rror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 13014 T2140 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 13036 T2146 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 13036 T2139 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 13036 T2175 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 13036 T2159 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 13059 T2176 oasc.ZkController.register We are http://1= 27.0.0.1:17755/collection1/ and leader is http://127.0.0.1:17755/collection= 1/ [junit4:junit4] 2> 13059 T2176 oasc.ZkController.register No LogReplay ne= eded for core=3Dcollection1 baseURL=3Dhttp://127.0.0.1:17755 [junit4:junit4] 2> 13059 T2176 oasc.ZkController.checkRecovery I am the l= eader, no recovery necessary [junit4:junit4] 2> 13059 T2176 oasc.ZkController.publish publishing core= =3Dcollection1 state=3Dactive [junit4:junit4] 2> 13059 T2176 oasc.ZkController.publish numShards not fo= und on descriptor - reading it from system property [junit4:junit4] 2> 13061 T2176 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 13061 T2117 oass.SolrDispatchFilter.init user.dir=3D/u= sr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/bu= ild/solr-core/test/J1 [junit4:junit4] 2> 13062 T2117 oass.SolrDispatchFilter.init SolrDispatchF= ilter.init() done [junit4:junit4] 2> 13062 T2117 oascsi.HttpClientUtil.createClient Creatin= g new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&f= ollowRedirects=3Dfalse [junit4:junit4] 2> 13214 T2117 oejs.Server.doStart jetty-8.1.8.v20121106 [junit4:junit4] 2> 13217 T2117 oejs.AbstractConnector.doStart Started Soc= ketConnector@127.0.0.1:62522 [junit4:junit4] 2> 13218 T2117 oass.SolrDispatchFilter.init SolrDispatchF= ilter.init() [junit4:junit4] 2> 13218 T2117 oasc.SolrResourceLoader.locateSolrHome JND= I not configured for solr (NoInitialContextEx) [junit4:junit4] 2> 13218 T2117 oasc.SolrResourceLoader.locateSolrHome usi= ng system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/= Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.sol= r.cloud.BasicDistributedZk2Test-jetty3-1363227537813 [junit4:junit4] 2> 13219 T2117 oasc.CoreContainer$Initializer.initialize = looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucen= e-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.clo= ud.BasicDistributedZk2Test-jetty3-1363227537813/solr.xml [junit4:junit4] 2> 13219 T2117 oasc.CoreContainer. New CoreContaine= r 610197557 [junit4:junit4] 2> 13219 T2117 oasc.CoreContainer.load Loading CoreContai= ner using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-T= ests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Basic= DistributedZk2Test-jetty3-1363227537813/' [junit4:junit4] 2> 13220 T2117 oasc.SolrResourceLoader. new SolrRes= ourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-= Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud= .BasicDistributedZk2Test-jetty3-1363227537813/' [junit4:junit4] 2> 13256 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting socketTimeout to: 120000 [junit4:junit4] 2> 13257 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting urlScheme to: http:// [junit4:junit4] 2> 13257 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting connTimeout to: 15000 [junit4:junit4] 2> 13258 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting maxConnectionsPerHost to: 20 [junit4:junit4] 2> 13258 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting corePoolSize to: 0 [junit4:junit4] 2> 13258 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting maximumPoolSize to: 2147483647 [junit4:junit4] 2> 13258 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting maxThreadIdleTime to: 5 [junit4:junit4] 2> 13259 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting sizeOfQueue to: -1 [junit4:junit4] 2> 13259 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting fairnessPolicy to: false [junit4:junit4] 2> 13259 T2117 oascsi.HttpClientUtil.createClient Creatin= g new http client, config:maxConnectionsPerHost=3D20&maxConnections=3D10000= &socketTimeout=3D120000&connTimeout=3D15000&retry=3Dfalse [junit4:junit4] 2> 13275 T2117 oasc.CoreContainer.load Registering Log Li= stener [junit4:junit4] 2> 13289 T2117 oasc.CoreContainer.initZooKeeper Zookeeper= client=3D127.0.0.1:16556/solr [junit4:junit4] 2> 13289 T2117 oasc.ZkController.checkChrootPath zkHost i= ncludes chroot [junit4:junit4] 2> 13289 T2117 oaz.ZooKeeper. Initiating client con= nection, connectString=3D127.0.0.1:16556 sessionTimeout=3D60000 watcher=3Do= rg.apache.solr.common.cloud.ConnectionManager@7d33cf49 [junit4:junit4] 2> 13290 T2117 oascc.ConnectionManager.waitForConnected W= aiting for client to connect to ZooKeeper [junit4:junit4] 2> 13291 T2188 oaz.ClientCnxn$SendThread.logStartConnect = Opening socket connection to server localhost/127.0.0.1:16556. Will not att= empt to authenticate using SASL (access denied (javax.security.auth.AuthPer= mission getLoginConfiguration)) [junit4:junit4] 2> 13291 T2188 oaz.ClientCnxn$SendThread.primeConnection = Socket connection established to localhost/127.0.0.1:16556, initiating sess= ion [junit4:junit4] 2> 13292 T2119 oazs.NIOServerCnxnFactory.run Accepted soc= ket connection from /140.211.11.196:38971 [junit4:junit4] 2> 13292 T2119 oazs.ZooKeeperServer.processConnectRequest= Client attempting to establish new session at /140.211.11.196:38971 [junit4:junit4] 2> 13294 T2121 oazs.ZooKeeperServer.finishSessionInit Est= ablished session 0x13d66b13e920009 with negotiated timeout 20000 for client= /140.211.11.196:38971 [junit4:junit4] 2> 13294 T2188 oaz.ClientCnxn$SendThread.onConnected Sess= ion establishment complete on server localhost/127.0.0.1:16556, sessionid = =3D 0x13d66b13e920009, negotiated timeout =3D 20000 [junit4:junit4] 2> 13294 T2189 oascc.ConnectionManager.process Watcher or= g.apache.solr.common.cloud.ConnectionManager@7d33cf49 name:ZooKeeperConnect= ion Watcher:127.0.0.1:16556 got event WatchedEvent state:SyncConnected type= :None path:null path:null type:None [junit4:junit4] 2> 13295 T2117 oascc.ConnectionManager.waitForConnected C= lient is connected to ZooKeeper [junit4:junit4] 2> 13296 T2122 oazs.PrepRequestProcessor.pRequest2Txn Pro= cessed session termination for sessionid: 0x13d66b13e920009 [junit4:junit4] 2> 13306 T2189 oaz.ClientCnxn$EventThread.run EventThread= shut down [junit4:junit4] 2> 13306 T2119 oazs.NIOServerCnxn.closeSock Closed socket= connection for client /140.211.11.196:38971 which had sessionid 0x13d66b13= e920009 [junit4:junit4] 2> 13306 T2117 oaz.ZooKeeper.close Session: 0x13d66b13e92= 0009 closed [junit4:junit4] 2> 13307 T2117 oascsi.HttpClientUtil.createClient Creatin= g new http client, config:maxConnections=3D500&maxConnectionsPerHost=3D16&s= ocketTimeout=3D120000&connTimeout=3D15000 [junit4:junit4] 2> 13316 T2117 oaz.ZooKeeper. Initiating client con= nection, connectString=3D127.0.0.1:16556/solr sessionTimeout=3D30000 watche= r=3Dorg.apache.solr.common.cloud.ConnectionManager@312d2b53 [junit4:junit4] 2> 13317 T2117 oascc.ConnectionManager.waitForConnected W= aiting for client to connect to ZooKeeper [junit4:junit4] 2> 13317 T2190 oaz.ClientCnxn$SendThread.logStartConnect = Opening socket connection to server localhost/127.0.0.1:16556. Will not att= empt to authenticate using SASL (access denied (javax.security.auth.AuthPer= mission getLoginConfiguration)) [junit4:junit4] 2> 13317 T2190 oaz.ClientCnxn$SendThread.primeConnection = Socket connection established to localhost/127.0.0.1:16556, initiating sess= ion [junit4:junit4] 2> 13318 T2119 oazs.NIOServerCnxnFactory.run Accepted soc= ket connection from /140.211.11.196:32757 [junit4:junit4] 2> 13318 T2119 oazs.ZooKeeperServer.processConnectRequest= Client attempting to establish new session at /140.211.11.196:32757 [junit4:junit4] 2> 13319 T2121 oazs.ZooKeeperServer.finishSessionInit Est= ablished session 0x13d66b13e92000a with negotiated timeout 20000 for client= /140.211.11.196:32757 [junit4:junit4] 2> 13319 T2190 oaz.ClientCnxn$SendThread.onConnected Sess= ion establishment complete on server localhost/127.0.0.1:16556, sessionid = =3D 0x13d66b13e92000a, negotiated timeout =3D 20000 [junit4:junit4] 2> 13319 T2191 oascc.ConnectionManager.process Watcher or= g.apache.solr.common.cloud.ConnectionManager@312d2b53 name:ZooKeeperConnect= ion Watcher:127.0.0.1:16556/solr got event WatchedEvent state:SyncConnected= type:None path:null path:null type:None [junit4:junit4] 2> 13319 T2117 oascc.ConnectionManager.waitForConnected C= lient is connected to ZooKeeper [junit4:junit4] 2> 13320 T2122 oazs.PrepRequestProcessor.pRequest Got use= r-level KeeperException when processing sessionid:0x13d66b13e92000a type:cr= eate cxid:0x1 zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/overseer Er= ror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 13326 T2122 oazs.PrepRequestProcessor.pRequest Got use= r-level KeeperException when processing sessionid:0x13d66b13e92000a type:cr= eate cxid:0x2 zxid:0x91 txntype:-1 reqpath:n/a Error Path:/solr/overseer Er= ror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 13328 T2117 oascc.ZkStateReader.createClusterStateWatc= hersAndUpdate Updating cluster state from ZooKeeper...=20 [junit4:junit4] 2> 14330 T2117 oasc.ZkController.createEphemeralLiveNode = Register node as live in ZooKeeper:/live_nodes/127.0.0.1:62522_ [junit4:junit4] 2> 14331 T2122 oazs.PrepRequestProcessor.pRequest Got use= r-level KeeperException when processing sessionid:0x13d66b13e92000a type:de= lete cxid:0xb zxid:0x92 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/= 127.0.0.1:62522_ Error:KeeperErrorCode =3D NoNode for /solr/live_nodes/127.= 0.0.1:62522_ [junit4:junit4] 2> 14333 T2117 oascc.SolrZkClient.makePath makePath: /liv= e_nodes/127.0.0.1:62522_ [junit4:junit4] 2> 14346 T2139 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:= /live_nodes, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 14348 T2175 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:= /live_nodes, has occurred - updating... (live nodes size: 3) [junit4:junit4] 2> 14348 T2146 oascc.ZkStateReader$3.process Updating liv= e nodes... (4) [junit4:junit4] 2> 14348 T2191 oascc.ZkStateReader$3.process Updating liv= e nodes... (4) [junit4:junit4] 2> 14348 T2159 oascc.ZkStateReader$3.process Updating liv= e nodes... (4) [junit4:junit4] 2> 14349 T2146 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:= /live_nodes, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 14349 T2159 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:= /live_nodes, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 14349 T2139 oascc.ZkStateReader$3.process Updating liv= e nodes... (4) [junit4:junit4] 2> 14349 T2175 oascc.ZkStateReader$3.process Updating liv= e nodes... (4) [junit4:junit4] 2> 14356 T2192 oasc.CoreContainer.create Creating SolrCor= e 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/= Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.sol= r.cloud.BasicDistributedZk2Test-jetty3-1363227537813/collection1 [junit4:junit4] 2> 14356 T2192 oasc.ZkController.createCollectionZkNode C= heck for collection zkNode:collection1 [junit4:junit4] 2> 14356 T2192 oasc.ZkController.createCollectionZkNode C= ollection zkNode exists [junit4:junit4] 2> 14357 T2192 oasc.ZkController.readConfigName Load coll= ection config from:/collections/collection1 [junit4:junit4] 2> 14358 T2192 oasc.SolrResourceLoader. new SolrRes= ourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-= Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud= .BasicDistributedZk2Test-jetty3-1363227537813/collection1/' [junit4:junit4] 2> 14359 T2192 oasc.SolrResourceLoader.replaceClassLoader= Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-tru= nk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistribute= dZk2Test-jetty3-1363227537813/collection1/lib/classes/' to classloader [junit4:junit4] 2> 14360 T2192 oasc.SolrResourceLoader.replaceClassLoader= Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-tru= nk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistribute= dZk2Test-jetty3-1363227537813/collection1/lib/README' to classloader [junit4:junit4] 2> 14408 T2192 oasc.SolrConfig. Using Lucene MatchV= ersion: LUCENE_50 [junit4:junit4] 2> 14464 T2192 oasc.SolrConfig. Loaded SolrConfig: = solrconfig.xml [junit4:junit4] 2> 14549 T2140 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 14550 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate 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:17755_", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:17755"} [junit4:junit4] 2> 14564 T2146 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 14564 T2175 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 14564 T2139 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 14564 T2159 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 14565 T2191 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 14565 T2192 oass.IndexSchema.readSchema Reading Solr S= chema [junit4:junit4] 2> 14571 T2192 oass.IndexSchema.readSchema Schema name=3D= test [junit4:junit4] 2> 15198 T2192 oass.OpenExchangeRatesOrgProvider.init Ini= tialized with rates=3Dopen-exchange-rates.json, refreshInterval=3D1440. [junit4:junit4] 2> 15210 T2192 oass.IndexSchema.readSchema default search= field in schema is text [junit4:junit4] 2> 15214 T2192 oass.IndexSchema.readSchema unique key fie= ld: id [junit4:junit4] 2> 15227 T2192 oass.FileExchangeRateProvider.reload Reloa= ding exchange rates from file currency.xml [junit4:junit4] 2> 15232 T2192 oass.FileExchangeRateProvider.reload Reloa= ding exchange rates from file currency.xml [junit4:junit4] 2> 15236 T2192 oass.OpenExchangeRatesOrgProvider.reload R= eloading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 15237 T2192 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 15237 T2192 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 15238 T2192 oass.OpenExchangeRatesOrgProvider.reload R= eloading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 15239 T2192 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 15239 T2192 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 15239 T2192 oasc.SolrCore.initDirectoryFactory org.apa= che.solr.core.MockDirectoryFactory [junit4:junit4] 2> 15239 T2192 oasc.SolrCore. [collection1] Opening= new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-= trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistr= ibutedZk2Test-jetty3-1363227537813/collection1/, dataDir=3D./org.apache.sol= r.cloud.BasicDistributedZk2Test-1363227524744/jetty3/ [junit4:junit4] 2> 15240 T2192 oasc.JmxMonitoredMap. JMX monitoring= is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxM= BeanServer@5c09624 [junit4:junit4] 2> 15240 T2192 oasc.SolrCore.initDirectoryFactory org.apa= che.solr.core.MockDirectoryFactory [junit4:junit4] 2> 15241 T2192 oasc.CachingDirectoryFactory.get return ne= w directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-13632275247= 44/jetty3 forceNew: false [junit4:junit4] 2> 15241 T2192 oasc.SolrCore.getNewIndexDir New index dir= ectory detected: old=3Dnull new=3D./org.apache.solr.cloud.BasicDistributedZ= k2Test-1363227524744/jetty3/index/ [junit4:junit4] 2> 15241 T2192 oasc.SolrCore.initIndex WARNING [collectio= n1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1= 363227524744/jetty3/index' doesn't exist. Creating new index... [junit4:junit4] 2> 15242 T2192 oasc.CachingDirectoryFactory.get return ne= w directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-13632275247= 44/jetty3/index forceNew: false [junit4:junit4] 2> 15245 T2192 oasc.SolrDeletionPolicy.onCommit SolrDelet= ionPolicy.onCommit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@7eab0d73 lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@171944e1; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> 15245 T2192 oasc.SolrDeletionPolicy.updateCommits newe= st commit =3D 1[segments_1] [junit4:junit4] 2> 15248 T2192 oasup.UpdateRequestProcessorChain.init ins= erting DistributedUpdateProcessorFactory into updateRequestProcessorChain "= dedupe" [junit4:junit4] 2> 15248 T2192 oasup.UpdateRequestProcessorChain.init ins= erting DistributedUpdateProcessorFactory into updateRequestProcessorChain "= stored_sig" [junit4:junit4] 2> 15249 T2192 oasup.UpdateRequestProcessorChain.init ins= erting DistributedUpdateProcessorFactory into updateRequestProcessorChain "= distrib-dup-test-chain-implicit" [junit4:junit4] 2> 15249 T2192 oasc.RequestHandlers.initHandlersFromConfi= g created standard: solr.StandardRequestHandler [junit4:junit4] 2> 15250 T2192 oasc.RequestHandlers.initHandlersFromConfi= g created /get: solr.RealTimeGetHandler [junit4:junit4] 2> 15250 T2192 oasc.RequestHandlers.initHandlersFromConfi= g adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 2> 15250 T2192 oasc.RequestHandlers.initHandlersFromConfi= g created /replication: solr.ReplicationHandler [junit4:junit4] 2> 15251 T2192 oasc.RequestHandlers.initHandlersFromConfi= g created /update: solr.UpdateRequestHandler [junit4:junit4] 2> 15251 T2192 oasc.RequestHandlers.initHandlersFromConfi= g created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4:junit4] 2> 15259 T2192 oashl.XMLLoader.init xsltCacheLifetimeSeco= nds=3D60 [junit4:junit4] 2> 15264 T2192 oass.SolrIndexSearcher. Opening Sear= cher@33e89f61 main [junit4:junit4] 2> 15264 T2192 oasu.UpdateHandler.clearLog Clearing tlog = files, tlogDir=3D./org.apache.solr.cloud.BasicDistributedZk2Test-1363227524= 744/jetty3/tlog [junit4:junit4] 2> 15265 T2192 oasu.CommitTracker. Hard AutoCommit:= disabled [junit4:junit4] 2> 15265 T2192 oasu.CommitTracker. Soft AutoCommit:= disabled [junit4:junit4] 2> 15268 T2193 oasc.SolrCore.registerSearcher [collection= 1] Registered new searcher Searcher@33e89f61 main{StandardDirectoryReader(s= egments_1:1)} [junit4:junit4] 2> 15269 T2192 oasc.ZkController.publish publishing core= =3Dcollection1 state=3Ddown [junit4:junit4] 2> 15269 T2192 oasc.ZkController.publish numShards not fo= und on descriptor - reading it from system property [junit4:junit4] 2> 16068 T2140 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 16069 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate 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:62522_", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:62522"} [junit4:junit4] 2> 16069 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate Collection already exists with numShards=3D2 [junit4:junit4] 2> 16069 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate Assigning new node to shard shard=3Dshard1 [junit4:junit4] 2> 16088 T2139 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 16088 T2146 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 16089 T2191 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 16089 T2175 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 16089 T2159 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 16272 T2192 oasc.CoreContainer.registerCore registerin= g core: collection1 [junit4:junit4] 2> 16272 T2192 oasc.ZkController.register Register replic= a - core:collection1 address:http://127.0.0.1:62522 collection:collection1 = shard:shard1 [junit4:junit4] 2> 16275 T2192 oasc.ZkController.register We are http://1= 27.0.0.1:62522/collection1/ and leader is http://127.0.0.1:64400/collection= 1/ [junit4:junit4] 2> 16275 T2192 oasc.ZkController.register No LogReplay ne= eded for core=3Dcollection1 baseURL=3Dhttp://127.0.0.1:62522 [junit4:junit4] 2> 16275 T2192 oasc.ZkController.checkRecovery Core needs= to recover:collection1 [junit4:junit4] 2> 16276 T2192 oasu.DefaultSolrCoreState.doRecovery Runni= ng recovery - first canceling any ongoing recovery [junit4:junit4] 2> ASYNC NEW_CORE C160 name=3Dcollection1 org.apache.sol= r.core.SolrCore@55b4c83f url=3Dhttp://127.0.0.1:62522/collection1 node=3D12= 7.0.0.1:62522_ C160_STATE=3Dcoll:collection1 core:collection1 props:{state= =3Ddown, core=3Dcollection1, collection=3Dcollection1, node_name=3D127.0.0.= 1:62522_, base_url=3Dhttp://127.0.0.1:62522} [junit4:junit4] 2> 16277 T2194 C160 P62522 oasc.RecoveryStrategy.run Star= ting recovery process. core=3Dcollection1 recoveringAfterStartup=3Dtrue [junit4:junit4] 2> 16277 T2194 C160 P62522 oasc.RecoveryStrategy.doRecove= ry ###### startupVersions=3D[] [junit4:junit4] 2> 16277 T2192 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 16277 T2194 C160 P62522 oasc.ZkController.publish publ= ishing core=3Dcollection1 state=3Drecovering [junit4:junit4] 2> 16277 T2194 C160 P62522 oasc.ZkController.publish numS= hards not found on descriptor - reading it from system property [junit4:junit4] 2> 16278 T2117 oass.SolrDispatchFilter.init user.dir=3D/u= sr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/bu= ild/solr-core/test/J1 [junit4:junit4] 2> 16279 T2117 oass.SolrDispatchFilter.init SolrDispatchF= ilter.init() done [junit4:junit4] 2> 16280 T2117 oascsi.HttpClientUtil.createClient Creatin= g new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&f= ollowRedirects=3Dfalse [junit4:junit4] 2> 16291 T2194 C160 P62522 oascsi.HttpClientUtil.createCl= ient Creating new http client, config:maxConnections=3D128&maxConnectionsPe= rHost=3D32&followRedirects=3Dfalse [junit4:junit4] 2> 16480 T2117 oejs.Server.doStart jetty-8.1.8.v20121106 [junit4:junit4] 2> 16483 T2117 oejs.AbstractConnector.doStart Started Soc= ketConnector@127.0.0.1:47567 [junit4:junit4] 2> 16484 T2117 oass.SolrDispatchFilter.init SolrDispatchF= ilter.init() [junit4:junit4] 2> 16484 T2117 oasc.SolrResourceLoader.locateSolrHome JND= I not configured for solr (NoInitialContextEx) [junit4:junit4] 2> 16485 T2117 oasc.SolrResourceLoader.locateSolrHome usi= ng system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/= Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.sol= r.cloud.BasicDistributedZk2Test-jetty4-1363227541034 [junit4:junit4] 2> 16485 T2117 oasc.CoreContainer$Initializer.initialize = looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucen= e-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.clo= ud.BasicDistributedZk2Test-jetty4-1363227541034/solr.xml [junit4:junit4] 2> 16486 T2117 oasc.CoreContainer. New CoreContaine= r 1931471321 [junit4:junit4] 2> 16487 T2117 oasc.CoreContainer.load Loading CoreContai= ner using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-T= ests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.Basic= DistributedZk2Test-jetty4-1363227541034/' [junit4:junit4] 2> 16487 T2117 oasc.SolrResourceLoader. new SolrRes= ourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-= Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud= .BasicDistributedZk2Test-jetty4-1363227541034/' [junit4:junit4] 2> 16540 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting socketTimeout to: 120000 [junit4:junit4] 2> 16541 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting urlScheme to: http:// [junit4:junit4] 2> 16541 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting connTimeout to: 15000 [junit4:junit4] 2> 16542 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting maxConnectionsPerHost to: 20 [junit4:junit4] 2> 16542 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting corePoolSize to: 0 [junit4:junit4] 2> 16542 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting maximumPoolSize to: 2147483647 [junit4:junit4] 2> 16543 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting maxThreadIdleTime to: 5 [junit4:junit4] 2> 16543 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting sizeOfQueue to: -1 [junit4:junit4] 2> 16544 T2117 oashc.HttpShardHandlerFactory.getParameter= Setting fairnessPolicy to: false [junit4:junit4] 2> 16544 T2117 oascsi.HttpClientUtil.createClient Creatin= g new http client, config:maxConnectionsPerHost=3D20&maxConnections=3D10000= &socketTimeout=3D120000&connTimeout=3D15000&retry=3Dfalse [junit4:junit4] 2> 16563 T2117 oasc.CoreContainer.load Registering Log Li= stener [junit4:junit4] 2> 16576 T2117 oasc.CoreContainer.initZooKeeper Zookeeper= client=3D127.0.0.1:16556/solr [junit4:junit4] 2> 16576 T2117 oasc.ZkController.checkChrootPath zkHost i= ncludes chroot [junit4:junit4] 2> 16577 T2117 oaz.ZooKeeper. Initiating client con= nection, connectString=3D127.0.0.1:16556 sessionTimeout=3D60000 watcher=3Do= rg.apache.solr.common.cloud.ConnectionManager@3690fae2 [junit4:junit4] 2> 16578 T2117 oascc.ConnectionManager.waitForConnected W= aiting for client to connect to ZooKeeper [junit4:junit4] 2> 16578 T2205 oaz.ClientCnxn$SendThread.logStartConnect = Opening socket connection to server localhost/127.0.0.1:16556. Will not att= empt to authenticate using SASL (access denied (javax.security.auth.AuthPer= mission getLoginConfiguration)) [junit4:junit4] 2> 16580 T2205 oaz.ClientCnxn$SendThread.primeConnection = Socket connection established to localhost/127.0.0.1:16556, initiating sess= ion [junit4:junit4] 2> 16580 T2119 oazs.NIOServerCnxnFactory.run Accepted soc= ket connection from /140.211.11.196:24604 [junit4:junit4] 2> 16580 T2119 oazs.ZooKeeperServer.processConnectRequest= Client attempting to establish new session at /140.211.11.196:24604 [junit4:junit4] 2> 16582 T2121 oazs.ZooKeeperServer.finishSessionInit Est= ablished session 0x13d66b13e92000b with negotiated timeout 20000 for client= /140.211.11.196:24604 [junit4:junit4] 2> 16582 T2205 oaz.ClientCnxn$SendThread.onConnected Sess= ion establishment complete on server localhost/127.0.0.1:16556, sessionid = =3D 0x13d66b13e92000b, negotiated timeout =3D 20000 [junit4:junit4] 2> 16583 T2206 oascc.ConnectionManager.process Watcher or= g.apache.solr.common.cloud.ConnectionManager@3690fae2 name:ZooKeeperConnect= ion Watcher:127.0.0.1:16556 got event WatchedEvent state:SyncConnected type= :None path:null path:null type:None [junit4:junit4] 2> 16583 T2117 oascc.ConnectionManager.waitForConnected C= lient is connected to ZooKeeper [junit4:junit4] 2> 16586 T2122 oazs.PrepRequestProcessor.pRequest2Txn Pro= cessed session termination for sessionid: 0x13d66b13e92000b [junit4:junit4] 2> 16598 T2206 oaz.ClientCnxn$EventThread.run EventThread= shut down [junit4:junit4] 2> 16598 T2119 oazs.NIOServerCnxn.closeSock Closed socket= connection for client /140.211.11.196:24604 which had sessionid 0x13d66b13= e92000b [junit4:junit4] 2> 16598 T2117 oaz.ZooKeeper.close Session: 0x13d66b13e92= 000b closed [junit4:junit4] 2> 16599 T2117 oascsi.HttpClientUtil.createClient Creatin= g new http client, config:maxConnections=3D500&maxConnectionsPerHost=3D16&s= ocketTimeout=3D120000&connTimeout=3D15000 [junit4:junit4] 2> 16607 T2117 oaz.ZooKeeper. Initiating client con= nection, connectString=3D127.0.0.1:16556/solr sessionTimeout=3D30000 watche= r=3Dorg.apache.solr.common.cloud.ConnectionManager@13d7c16b [junit4:junit4] 2> 16608 T2117 oascc.ConnectionManager.waitForConnected W= aiting for client to connect to ZooKeeper [junit4:junit4] 2> 16608 T2207 oaz.ClientCnxn$SendThread.logStartConnect = Opening socket connection to server localhost/127.0.0.1:16556. Will not att= empt to authenticate using SASL (access denied (javax.security.auth.AuthPer= mission getLoginConfiguration)) [junit4:junit4] 2> 16609 T2207 oaz.ClientCnxn$SendThread.primeConnection = Socket connection established to localhost/127.0.0.1:16556, initiating sess= ion [junit4:junit4] 2> 16609 T2119 oazs.NIOServerCnxnFactory.run Accepted soc= ket connection from /140.211.11.196:15828 [junit4:junit4] 2> 16609 T2119 oazs.ZooKeeperServer.processConnectRequest= Client attempting to establish new session at /140.211.11.196:15828 [junit4:junit4] 2> 16610 T2121 oazs.ZooKeeperServer.finishSessionInit Est= ablished session 0x13d66b13e92000c with negotiated timeout 20000 for client= /140.211.11.196:15828 [junit4:junit4] 2> 16610 T2207 oaz.ClientCnxn$SendThread.onConnected Sess= ion establishment complete on server localhost/127.0.0.1:16556, sessionid = =3D 0x13d66b13e92000c, negotiated timeout =3D 20000 [junit4:junit4] 2> 16611 T2208 oascc.ConnectionManager.process Watcher or= g.apache.solr.common.cloud.ConnectionManager@13d7c16b name:ZooKeeperConnect= ion Watcher:127.0.0.1:16556/solr got event WatchedEvent state:SyncConnected= type:None path:null path:null type:None [junit4:junit4] 2> 16611 T2117 oascc.ConnectionManager.waitForConnected C= lient is connected to ZooKeeper [junit4:junit4] 2> 16612 T2122 oazs.PrepRequestProcessor.pRequest Got use= r-level KeeperException when processing sessionid:0x13d66b13e92000c type:cr= eate cxid:0x1 zxid:0xa3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Er= ror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 16614 T2122 oazs.PrepRequestProcessor.pRequest Got use= r-level KeeperException when processing sessionid:0x13d66b13e92000c type:cr= eate cxid:0x2 zxid:0xa4 txntype:-1 reqpath:n/a Error Path:/solr/overseer Er= ror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 16616 T2117 oascc.ZkStateReader.createClusterStateWatc= hersAndUpdate Updating cluster state from ZooKeeper...=20 [junit4:junit4] 2> 17593 T2140 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 17594 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate 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:62522_", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:62522"} [junit4:junit4] 2> 17609 T2208 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17609 T2159 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17609 T2191 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17609 T2146 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17609 T2175 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17609 T2139 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17618 T2117 oasc.ZkController.createEphemeralLiveNode = Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47567_ [junit4:junit4] 2> 17619 T2122 oazs.PrepRequestProcessor.pRequest Got use= r-level KeeperException when processing sessionid:0x13d66b13e92000c type:de= lete cxid:0xd zxid:0xa9 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/= 127.0.0.1:47567_ Error:KeeperErrorCode =3D NoNode for /solr/live_nodes/127.= 0.0.1:47567_ [junit4:junit4] 2> 17620 T2117 oascc.SolrZkClient.makePath makePath: /liv= e_nodes/127.0.0.1:47567_ [junit4:junit4] 2> 17621 T2139 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:= /live_nodes, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17622 T2191 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:= /live_nodes, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17622 T2175 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:= /live_nodes, has occurred - updating... (live nodes size: 4) [junit4:junit4] 2> 17622 T2208 oascc.ZkStateReader$3.process Updating liv= e nodes... (5) [junit4:junit4] 2> 17622 T2146 oascc.ZkStateReader$3.process Updating liv= e nodes... (5) [junit4:junit4] 2> 17622 T2208 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:= /live_nodes, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 17622 T2146 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:= /live_nodes, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 17622 T2159 oascc.ZkStateReader$3.process Updating liv= e nodes... (5) [junit4:junit4] 2> 17622 T2159 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:= /live_nodes, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 17623 T2139 oascc.ZkStateReader$3.process Updating liv= e nodes... (5) [junit4:junit4] 2> 17623 T2175 oascc.ZkStateReader$3.process Updating liv= e nodes... (5) [junit4:junit4] 2> 17623 T2191 oascc.ZkStateReader$3.process Updating liv= e nodes... (5) [junit4:junit4] 2> 18305 T2149 oass.SolrDispatchFilter.handleAdminRequest= /admin/cores {coreNodeName=3D4&state=3Drecovering&nodeName=3D127.0.0.1:625= 22_&action=3DPREPRECOVERY&checkLive=3Dtrue&core=3Dcollection1&wt=3Djavabin&= onlyIfLeader=3Dtrue&version=3D2} status=3D0 QTime=3D2002=20 [junit4:junit4] 2> 18337 T2209 oasc.CoreContainer.create Creating SolrCor= e 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/= Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.sol= r.cloud.BasicDistributedZk2Test-jetty4-1363227541034/collection1 [junit4:junit4] 2> 18337 T2209 oasc.ZkController.createCollectionZkNode C= heck for collection zkNode:collection1 [junit4:junit4] 2> 18338 T2209 oasc.ZkController.createCollectionZkNode C= ollection zkNode exists [junit4:junit4] 2> 18338 T2209 oasc.ZkController.readConfigName Load coll= ection config from:/collections/collection1 [junit4:junit4] 2> 18339 T2209 oasc.SolrResourceLoader. new SolrRes= ourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-= Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud= .BasicDistributedZk2Test-jetty4-1363227541034/collection1/' [junit4:junit4] 2> 18340 T2209 oasc.SolrResourceLoader.replaceClassLoader= Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-tru= nk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistribute= dZk2Test-jetty4-1363227541034/collection1/lib/classes/' to classloader [junit4:junit4] 2> 18340 T2209 oasc.SolrResourceLoader.replaceClassLoader= Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-tru= nk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistribute= dZk2Test-jetty4-1363227541034/collection1/lib/README' to classloader [junit4:junit4] 2> 18376 T2209 oasc.SolrConfig. Using Lucene MatchV= ersion: LUCENE_50 [junit4:junit4] 2> 18417 T2209 oasc.SolrConfig. Loaded SolrConfig: = solrconfig.xml [junit4:junit4] 2> 18517 T2209 oass.IndexSchema.readSchema Reading Solr S= chema [junit4:junit4] 2> 18521 T2209 oass.IndexSchema.readSchema Schema name=3D= test [junit4:junit4] 2> 18952 T2209 oass.OpenExchangeRatesOrgProvider.init Ini= tialized with rates=3Dopen-exchange-rates.json, refreshInterval=3D1440. [junit4:junit4] 2> 18963 T2209 oass.IndexSchema.readSchema default search= field in schema is text [junit4:junit4] 2> 18966 T2209 oass.IndexSchema.readSchema unique key fie= ld: id [junit4:junit4] 2> 18976 T2209 oass.FileExchangeRateProvider.reload Reloa= ding exchange rates from file currency.xml [junit4:junit4] 2> 18980 T2209 oass.FileExchangeRateProvider.reload Reloa= ding exchange rates from file currency.xml [junit4:junit4] 2> 18983 T2209 oass.OpenExchangeRatesOrgProvider.reload R= eloading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 18984 T2209 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 18985 T2209 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 18985 T2209 oass.OpenExchangeRatesOrgProvider.reload R= eloading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 18986 T2209 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 18986 T2209 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 18986 T2209 oasc.SolrCore.initDirectoryFactory org.apa= che.solr.core.MockDirectoryFactory [junit4:junit4] 2> 18986 T2209 oasc.SolrCore. [collection1] Opening= new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-= trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistr= ibutedZk2Test-jetty4-1363227541034/collection1/, dataDir=3D./org.apache.sol= r.cloud.BasicDistributedZk2Test-1363227524744/jetty4/ [junit4:junit4] 2> 18986 T2209 oasc.JmxMonitoredMap. JMX monitoring= is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxM= BeanServer@5c09624 [junit4:junit4] 2> 18987 T2209 oasc.SolrCore.initDirectoryFactory org.apa= che.solr.core.MockDirectoryFactory [junit4:junit4] 2> 18987 T2209 oasc.CachingDirectoryFactory.get return ne= w directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-13632275247= 44/jetty4 forceNew: false [junit4:junit4] 2> 18987 T2209 oasc.SolrCore.getNewIndexDir New index dir= ectory detected: old=3Dnull new=3D./org.apache.solr.cloud.BasicDistributedZ= k2Test-1363227524744/jetty4/index/ [junit4:junit4] 2> 18988 T2209 oasc.SolrCore.initIndex WARNING [collectio= n1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1= 363227524744/jetty4/index' doesn't exist. Creating new index... [junit4:junit4] 2> 18988 T2209 oasc.CachingDirectoryFactory.get return ne= w directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-13632275247= 44/jetty4/index forceNew: false [junit4:junit4] 2> 18990 T2209 oasc.SolrDeletionPolicy.onCommit SolrDelet= ionPolicy.onCommit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@7c67fb69 lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@d244002; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> 18990 T2209 oasc.SolrDeletionPolicy.updateCommits newe= st commit =3D 1[segments_1] [junit4:junit4] 2> 18992 T2209 oasup.UpdateRequestProcessorChain.init ins= erting DistributedUpdateProcessorFactory into updateRequestProcessorChain "= dedupe" [junit4:junit4] 2> 18992 T2209 oasup.UpdateRequestProcessorChain.init ins= erting DistributedUpdateProcessorFactory into updateRequestProcessorChain "= stored_sig" [junit4:junit4] 2> 18993 T2209 oasup.UpdateRequestProcessorChain.init ins= erting DistributedUpdateProcessorFactory into updateRequestProcessorChain "= distrib-dup-test-chain-implicit" [junit4:junit4] 2> 18993 T2209 oasc.RequestHandlers.initHandlersFromConfi= g created standard: solr.StandardRequestHandler [junit4:junit4] 2> 18993 T2209 oasc.RequestHandlers.initHandlersFromConfi= g created /get: solr.RealTimeGetHandler [junit4:junit4] 2> 18994 T2209 oasc.RequestHandlers.initHandlersFromConfi= g adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 2> 18994 T2209 oasc.RequestHandlers.initHandlersFromConfi= g created /replication: solr.ReplicationHandler [junit4:junit4] 2> 18994 T2209 oasc.RequestHandlers.initHandlersFromConfi= g created /update: solr.UpdateRequestHandler [junit4:junit4] 2> 18994 T2209 oasc.RequestHandlers.initHandlersFromConfi= g created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4:junit4] 2> 18999 T2209 oashl.XMLLoader.init xsltCacheLifetimeSeco= nds=3D60 [junit4:junit4] 2> 19004 T2209 oass.SolrIndexSearcher. Opening Sear= cher@3bc4520 main [junit4:junit4] 2> 19004 T2209 oasu.UpdateHandler.clearLog Clearing tlog = files, tlogDir=3D./org.apache.solr.cloud.BasicDistributedZk2Test-1363227524= 744/jetty4/tlog [junit4:junit4] 2> 19005 T2209 oasu.CommitTracker. Hard AutoCommit:= disabled [junit4:junit4] 2> 19005 T2209 oasu.CommitTracker. Soft AutoCommit:= disabled [junit4:junit4] 2> 19008 T2210 oasc.SolrCore.registerSearcher [collection= 1] Registered new searcher Searcher@3bc4520 main{StandardDirectoryReader(se= gments_1:1)} [junit4:junit4] 2> 19009 T2209 oasc.ZkController.publish publishing core= =3Dcollection1 state=3Ddown [junit4:junit4] 2> 19009 T2209 oasc.ZkController.publish numShards not fo= und on descriptor - reading it from system property [junit4:junit4] 2> 19114 T2140 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 19115 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate 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:47567_", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:47567"} [junit4:junit4] 2> 19115 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate Collection already exists with numShards=3D2 [junit4:junit4] 2> 19115 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate Assigning new node to shard shard=3Dshard2 [junit4:junit4] 2> 19128 T2208 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 19128 T2139 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 19128 T2159 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 19128 T2191 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 19128 T2175 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 19128 T2146 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 20012 T2209 oasc.CoreContainer.registerCore registerin= g core: collection1 [junit4:junit4] 2> 20012 T2209 oasc.ZkController.register Register replic= a - core:collection1 address:http://127.0.0.1:47567 collection:collection1 = shard:shard2 [junit4:junit4] 2> 20015 T2209 oasc.ZkController.register We are http://1= 27.0.0.1:47567/collection1/ and leader is http://127.0.0.1:17755/collection= 1/ [junit4:junit4] 2> 20015 T2209 oasc.ZkController.register No LogReplay ne= eded for core=3Dcollection1 baseURL=3Dhttp://127.0.0.1:47567 [junit4:junit4] 2> 20016 T2209 oasc.ZkController.checkRecovery Core needs= to recover:collection1 [junit4:junit4] 2> 20016 T2209 oasu.DefaultSolrCoreState.doRecovery Runni= ng recovery - first canceling any ongoing recovery [junit4:junit4] 2> ASYNC NEW_CORE C161 name=3Dcollection1 org.apache.sol= r.core.SolrCore@462fec6c url=3Dhttp://127.0.0.1:47567/collection1 node=3D12= 7.0.0.1:47567_ C161_STATE=3Dcoll:collection1 core:collection1 props:{state= =3Ddown, core=3Dcollection1, collection=3Dcollection1, node_name=3D127.0.0.= 1:47567_, base_url=3Dhttp://127.0.0.1:47567} [junit4:junit4] 2> 20016 T2211 C161 P47567 oasc.RecoveryStrategy.run Star= ting recovery process. core=3Dcollection1 recoveringAfterStartup=3Dtrue [junit4:junit4] 2> 20017 T2211 C161 P47567 oasc.RecoveryStrategy.doRecove= ry ###### startupVersions=3D[] [junit4:junit4] 2> 20016 T2209 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 20017 T2211 C161 P47567 oasc.ZkController.publish publ= ishing core=3Dcollection1 state=3Drecovering [junit4:junit4] 2> 20017 T2211 C161 P47567 oasc.ZkController.publish numS= hards not found on descriptor - reading it from system property [junit4:junit4] 2> 20018 T2117 oass.SolrDispatchFilter.init user.dir=3D/u= sr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/bu= ild/solr-core/test/J1 [junit4:junit4] 2> 20018 T2211 C161 P47567 oascsi.HttpClientUtil.createCl= ient Creating new http client, config:maxConnections=3D128&maxConnectionsPe= rHost=3D32&followRedirects=3Dfalse [junit4:junit4] 2> 20018 T2117 oass.SolrDispatchFilter.init SolrDispatchF= ilter.init() done [junit4:junit4] 2> 20019 T2117 oascsi.HttpClientUtil.createClient Creatin= g new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&f= ollowRedirects=3Dfalse [junit4:junit4] 2> 20033 T2117 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 20034 T2117 oascsi.HttpClientUtil.createClient Creatin= g new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&f= ollowRedirects=3Dfalse [junit4:junit4] 2> 20047 T2150 oasc.CoreContainer.create Creating SolrCor= e 'onenodecollectioncore' using instanceDir: /usr/home/hudson/hudson-slave/= workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.= apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363227528673/onenodecolle= ctioncore [junit4:junit4] 2> 20048 T2150 oasc.ZkController.createCollectionZkNode C= heck for collection zkNode:onenodecollection [junit4:junit4] 2> 20048 T2150 oasc.ZkController.createCollectionZkNode C= reating collection in ZooKeeper:onenodecollection [junit4:junit4] 2> 20049 T2150 oasc.ZkController.getConfName Looking for = collection configName [junit4:junit4] 2> 20050 T2150 oasc.ZkController.getConfName Only one con= fig set found in zk - using it:conf1 [junit4:junit4] 2> 20050 T2150 oascc.SolrZkClient.makePath makePath: /col= lections/onenodecollection [junit4:junit4] 2> 20052 T2150 oasc.ZkController.readConfigName Load coll= ection config from:/collections/onenodecollection [junit4:junit4] 2> 20054 T2150 oasc.SolrResourceLoader. new SolrRes= ourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-= Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud= .BasicDistributedZk2Test-jetty1-1363227528673/onenodecollectioncore/' [junit4:junit4] 2> 20128 T2150 oasc.SolrConfig. Using Lucene MatchV= ersion: LUCENE_50 [junit4:junit4] 2> 20189 T2150 oasc.SolrConfig. Loaded SolrConfig: = solrconfig.xml [junit4:junit4] 2> 20290 T2150 oass.IndexSchema.readSchema Reading Solr S= chema [junit4:junit4] 2> 20296 T2150 oass.IndexSchema.readSchema Schema name=3D= test [junit4:junit4] 2> C160_STATE=3Dcoll:collection1 core:collection1 props:= {shard=3Dshard1, state=3Drecovering, core=3Dcollection1, collection=3Dcolle= ction1, node_name=3D127.0.0.1:62522_, base_url=3Dhttp://127.0.0.1:62522} [junit4:junit4] 2> 20307 T2194 C160 P62522 oasc.RecoveryStrategy.doRecove= ry Attempting to PeerSync from http://127.0.0.1:64400/collection1/ core=3Dc= ollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 2> 20307 T2194 C160 P62522 oasu.PeerSync.sync PeerSync: c= ore=3Dcollection1 url=3Dhttp://127.0.0.1:62522 START replicas=3D[http://127= .0.0.1:64400/collection1/] nUpdates=3D100 [junit4:junit4] 2> 20307 T2194 C160 P62522 oasu.PeerSync.sync WARNING no = frame of reference to tell of we've missed updates [junit4:junit4] 2> 20308 T2194 C160 P62522 oasc.RecoveryStrategy.doRecove= ry PeerSync Recovery was not successful - trying replication. core=3Dcollec= tion1 [junit4:junit4] 2> 20308 T2194 C160 P62522 oasc.RecoveryStrategy.doRecove= ry Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 2> 20308 T2194 C160 P62522 oasc.RecoveryStrategy.doRecove= ry Begin buffering updates. core=3Dcollection1 [junit4:junit4] 2> 20309 T2194 C160 P62522 oasu.UpdateLog.bufferUpdates S= tarting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog=3Dnull} [junit4:junit4] 2> 20309 T2194 C160 P62522 oasc.RecoveryStrategy.replicat= e Attempting to replicate from http://127.0.0.1:64400/collection1/. core=3D= collection1 [junit4:junit4] 2> 20309 T2194 C160 P62522 oascsi.HttpClientUtil.createCl= ient Creating new http client, config:maxConnections=3D128&maxConnectionsPe= rHost=3D32&followRedirects=3Dfalse [junit4:junit4] 2> ASYNC NEW_CORE C162 name=3Dcollection1 org.apache.sol= r.core.SolrCore@51373b2c url=3Dhttp://127.0.0.1:64400/collection1 node=3D12= 7.0.0.1:64400_ C162_STATE=3Dcoll:collection1 core:collection1 props:{shard= =3Dshard1, state=3Dactive, core=3Dcollection1, collection=3Dcollection1, no= de_name=3D127.0.0.1:64400_, base_url=3Dhttp://127.0.0.1:64400, leader=3Dtru= e} [junit4:junit4] 2> 20315 T2151 C162 P64400 REQ /get {getVersions=3D100&di= strib=3Dfalse&wt=3Djavabin&qt=3D/get&version=3D2} status=3D0 QTime=3D0=20 [junit4:junit4] 2> 20324 T2152 C162 P64400 oasu.DirectUpdateHandler2.comm= it start commit{,optimize=3Dfalse,openSearcher=3Dfalse,waitSearcher=3Dtrue,= expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 20326 T2152 C162 P64400 oasc.SolrDeletionPolicy.onInit= SolrDeletionPolicy.onInit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@6809635b lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@f40f91d; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> 20327 T2152 C162 P64400 oasc.SolrDeletionPolicy.update= Commits newest commit =3D 1[segments_1] [junit4:junit4] 2> 20327 T2152 C162 P64400 oasc.SolrDeletionPolicy.onComm= it SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@6809635b lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@f40f91d; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@6809635b lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@f40f91d; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2= ] [junit4:junit4] 2> 20328 T2152 C162 P64400 oasc.SolrDeletionPolicy.update= Commits newest commit =3D 2[segments_2] [junit4:junit4] 2> 20328 T2152 C162 P64400 oass.SolrIndexSearcher. = Opening Searcher@4ed88b1e realtime [junit4:junit4] 2> 20329 T2152 C162 P64400 oasu.DirectUpdateHandler2.comm= it end_commit_flush [junit4:junit4] 2> 20329 T2152 C162 P64400 /update {waitSearcher=3Dtrue&o= penSearcher=3Dfalse&commit=3Dtrue&wt=3Djavabin&commit_end_point=3Dtrue&vers= ion=3D2&softCommit=3Dfalse} {commit=3D} 0 6 [junit4:junit4] 2> 20330 T2194 C160 P62522 oash.ReplicationHandler.inform= Commits will be reserved for 10000 [junit4:junit4] 2> 20330 T2194 C160 P62522 oash.SnapPuller. No val= ue set for 'pollInterval'. Timer Task not started. [junit4:junit4] 2> 20332 T2153 C162 P64400 oash.ReplicationHandler.inform= Commits will be reserved for 10000 [junit4:junit4] 2> 20332 T2153 C162 P64400 REQ /replication {command=3Din= dexversion&qt=3D/replication&wt=3Djavabin&version=3D2} status=3D0 QTime=3D1= =20 [junit4:junit4] 2> 20333 T2194 C160 P62522 oash.SnapPuller.fetchLatestInd= ex Master's generation: 2 [junit4:junit4] 2> 20333 T2194 C160 P62522 oash.SnapPuller.fetchLatestInd= ex Slave's generation: 1 [junit4:junit4] 2> 20333 T2194 C160 P62522 oash.SnapPuller.fetchLatestInd= ex Starting replication process [junit4:junit4] 2> 20335 T2153 C162 P64400 REQ /replication {command=3Dfi= lelist&qt=3D/replication&wt=3Djavabin&generation=3D2&version=3D2} status=3D= 0 QTime=3D0=20 [junit4:junit4] 2> 20336 T2194 C160 P62522 oash.SnapPuller.fetchLatestInd= ex Number of files in latest index in master: 1 [junit4:junit4] 2> 20336 T2194 C160 P62522 oasc.CachingDirectoryFactory.g= et return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test= -1363227524744/jetty3/index.20130313221905075 forceNew: false [junit4:junit4] 2> 20337 T2194 C160 P62522 oash.SnapPuller.fetchLatestInd= ex Starting download to MockDirWrapper(RateLimitedDirectoryWrapper(org.apac= he.lucene.store.RAMDirectory@132b9848 lockFactory=3Dorg.apache.lucene.store= .NativeFSLockFactory@3b403487)) fullCopy=3Dfalse [junit4:junit4] 2> 20339 T2153 C162 P64400 REQ /replication {file=3Dsegme= nts_2&command=3Dfilecontent&checksum=3Dtrue&wt=3Dfilestream&qt=3D/replicati= on&generation=3D2} status=3D0 QTime=3D0=20 [junit4:junit4] 2> 20341 T2194 C160 P62522 oash.SnapPuller.fetchLatestInd= ex Total time taken for download : 0 secs [junit4:junit4] 2> 20342 T2194 C160 P62522 oasu.DefaultSolrCoreState.newI= ndexWriter Creating new IndexWriter... [junit4:junit4] 2> 20342 T2194 C160 P62522 oasu.DefaultSolrCoreState.newI= ndexWriter Waiting until IndexWriter is unused... core=3Dcollection1 [junit4:junit4] 2> 20344 T2194 C160 P62522 oasc.SolrDeletionPolicy.onInit= SolrDeletionPolicy.onInit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@7eab0d73 lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@171944e1; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@7eab0d73 lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@171944e1; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2= ] [junit4:junit4] 2> 20345 T2194 C160 P62522 oasc.SolrDeletionPolicy.update= Commits newest commit =3D 2[segments_2] [junit4:junit4] 2> 20345 T2194 C160 P62522 oasu.DefaultSolrCoreState.newI= ndexWriter New IndexWriter is ready to be used. [junit4:junit4] 2> 20345 T2194 C160 P62522 oass.SolrIndexSearcher. = Opening Searcher@71f2887c main [junit4:junit4] 2> 20346 T2193 oasc.SolrCore.registerSearcher [collection= 1] Registered new searcher Searcher@71f2887c main{StandardDirectoryReader(s= egments_2:1:nrt)} [junit4:junit4] 2> 20347 T2194 C160 P62522 oash.SnapPuller.fetchLatestInd= ex removing temporary index download directory files MockDirWrapper(RateLim= itedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@132b9848 lockFact= ory=3Dorg.apache.lucene.store.NativeFSLockFactory@3b403487)) [junit4:junit4] 2> 20347 T2194 C160 P62522 oasc.RecoveryStrategy.replay N= o replay needed. core=3Dcollection1 [junit4:junit4] 2> 20347 T2194 C160 P62522 oasc.RecoveryStrategy.doRecove= ry Replication Recovery was successful - registering as Active. core=3Dcoll= ection1 [junit4:junit4] 2> 20347 T2194 C160 P62522 oasc.ZkController.publish publ= ishing core=3Dcollection1 state=3Dactive [junit4:junit4] 2> 20347 T2194 C160 P62522 oasc.ZkController.publish numS= hards not found on descriptor - reading it from system property [junit4:junit4] 2> 20349 T2194 C160 P62522 oasc.RecoveryStrategy.doRecove= ry Finished recovery process. core=3Dcollection1 [junit4:junit4] 2> 20632 T2140 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 20633 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate 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:47567_", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:47567"} [junit4:junit4] 2> 20642 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate 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:62522_", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:62522"} [junit4:junit4] 2> 20654 T2139 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 20654 T2191 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 20654 T2159 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 20654 T2208 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 20654 T2175 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 20654 T2146 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 20942 T2150 oass.OpenExchangeRatesOrgProvider.init Ini= tialized with rates=3Dopen-exchange-rates.json, refreshInterval=3D1440. [junit4:junit4] 2> 20953 T2150 oass.IndexSchema.readSchema default search= field in schema is text [junit4:junit4] 2> 20957 T2150 oass.IndexSchema.readSchema unique key fie= ld: id [junit4:junit4] 2> 20969 T2150 oass.FileExchangeRateProvider.reload Reloa= ding exchange rates from file currency.xml [junit4:junit4] 2> 20974 T2150 oass.FileExchangeRateProvider.reload Reloa= ding exchange rates from file currency.xml [junit4:junit4] 2> 20978 T2150 oass.OpenExchangeRatesOrgProvider.reload R= eloading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 20979 T2150 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 20980 T2150 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 20980 T2150 oass.OpenExchangeRatesOrgProvider.reload R= eloading exchange rates from open-exchange-rates.json [junit4:junit4] 2> 20981 T2150 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Unknown key IMPORTANT NOTE [junit4:junit4] 2> 20981 T2150 oass.OpenExchangeRatesOrgProvider$OpenExch= angeRates. WARNING Expected key, got STRING [junit4:junit4] 2> 20982 T2150 oasc.SolrCore.initDirectoryFactory org.apa= che.solr.core.MockDirectoryFactory [junit4:junit4] 2> 20982 T2150 oasc.SolrCore. [onenodecollectioncor= e] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-S= olr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.= BasicDistributedZk2Test-jetty1-1363227528673/onenodecollectioncore/, dataDi= r=3D/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/s= olr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-136322752474= 5/onenodecollection/ [junit4:junit4] 2> 20983 T2150 oasc.JmxMonitoredMap. JMX monitoring= is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxM= BeanServer@5c09624 [junit4:junit4] 2> 20983 T2150 oasc.SolrCore.initDirectoryFactory org.apa= che.solr.core.MockDirectoryFactory [junit4:junit4] 2> 20984 T2150 oasc.CachingDirectoryFactory.get return ne= w directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-t= runk-Java6/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-= 1363227524745/onenodecollection forceNew: false [junit4:junit4] 2> 20984 T2150 oasc.SolrCore.getNewIndexDir New index dir= ectory detected: old=3Dnull new=3D/usr/home/hudson/hudson-slave/workspace/L= ucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./solrtest-BasicD= istributedZk2Test-1363227524745/onenodecollection/index/ [junit4:junit4] 2> 20985 T2150 oasc.SolrCore.initIndex WARNING [onenodeco= llectioncore] Solr index directory '/usr/home/hudson/hudson-slave/workspace= /Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./solrtest-Basi= cDistributedZk2Test-1363227524745/onenodecollection/index' doesn't exist. C= reating new index... [junit4:junit4] 2> 20985 T2150 oasc.CachingDirectoryFactory.get return ne= w directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-t= runk-Java6/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-= 1363227524745/onenodecollection/index forceNew: false [junit4:junit4] 2> 20988 T2150 oasc.SolrDeletionPolicy.onCommit SolrDelet= ionPolicy.onCommit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@428c8e9d lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@7459376; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> 20989 T2150 oasc.SolrDeletionPolicy.updateCommits newe= st commit =3D 1[segments_1] [junit4:junit4] 2> 20991 T2150 oasup.UpdateRequestProcessorChain.init ins= erting DistributedUpdateProcessorFactory into updateRequestProcessorChain "= dedupe" [junit4:junit4] 2> 20991 T2150 oasup.UpdateRequestProcessorChain.init ins= erting DistributedUpdateProcessorFactory into updateRequestProcessorChain "= stored_sig" [junit4:junit4] 2> 20992 T2150 oasup.UpdateRequestProcessorChain.init ins= erting DistributedUpdateProcessorFactory into updateRequestProcessorChain "= distrib-dup-test-chain-implicit" [junit4:junit4] 2> 20993 T2150 oasc.RequestHandlers.initHandlersFromConfi= g created standard: solr.StandardRequestHandler [junit4:junit4] 2> 20993 T2150 oasc.RequestHandlers.initHandlersFromConfi= g created /get: solr.RealTimeGetHandler [junit4:junit4] 2> 20994 T2150 oasc.RequestHandlers.initHandlersFromConfi= g adding lazy requestHandler: solr.ReplicationHandler [junit4:junit4] 2> 20994 T2150 oasc.RequestHandlers.initHandlersFromConfi= g created /replication: solr.ReplicationHandler [junit4:junit4] 2> 20995 T2150 oasc.RequestHandlers.initHandlersFromConfi= g created /update: solr.UpdateRequestHandler [junit4:junit4] 2> 20995 T2150 oasc.RequestHandlers.initHandlersFromConfi= g created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4:junit4] 2> 21003 T2150 oashl.XMLLoader.init xsltCacheLifetimeSeco= nds=3D60 [junit4:junit4] 2> 21010 T2150 oass.SolrIndexSearcher. Opening Sear= cher@5041595e main [junit4:junit4] 2> 21010 T2150 oasu.UpdateHandler.clearLog Clearing tlog = files, tlogDir=3D/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-= trunk-Java6/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test= -1363227524745/onenodecollection/tlog [junit4:junit4] 2> 21011 T2150 oasu.CommitTracker. Hard AutoCommit:= disabled [junit4:junit4] 2> 21012 T2150 oasu.CommitTracker. Soft AutoCommit:= disabled [junit4:junit4] 2> 21014 T2215 oasc.SolrCore.registerSearcher [onenodecol= lectioncore] Registered new searcher Searcher@5041595e main{StandardDirecto= ryReader(segments_1:1)} [junit4:junit4] 2> 21016 T2150 oasc.ZkController.publish publishing core= =3Donenodecollectioncore state=3Ddown [junit4:junit4] 2> 21034 T2165 oass.SolrDispatchFilter.handleAdminRequest= /admin/cores {coreNodeName=3D5&state=3Drecovering&nodeName=3D127.0.0.1:475= 67_&action=3DPREPRECOVERY&checkLive=3Dtrue&core=3Dcollection1&wt=3Djavabin&= onlyIfLeader=3Dtrue&version=3D2} status=3D0 QTime=3D1001=20 [junit4:junit4] 2> 22159 T2140 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 22160 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate 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:64400_", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:64400"} [junit4:junit4] 2> 22160 T2140 oasc.Overseer$ClusterStateUpdater.createCo= llection Create collection onenodecollection with numShards 1 [junit4:junit4] 2> 22160 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate Assigning new node to shard shard=3Dshard1 [junit4:junit4] 2> 22173 T2139 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 22173 T2208 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 22173 T2191 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 22173 T2146 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 22173 T2159 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 22173 T2175 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 23020 T2150 oasc.CoreContainer.registerCore registerin= g core: onenodecollectioncore [junit4:junit4] 2> 23020 T2150 oasc.ZkController.register Register replic= a - core:onenodecollectioncore address:http://127.0.0.1:64400 collection:on= enodecollection shard:shard1 [junit4:junit4] 2> 23021 T2150 oascc.SolrZkClient.makePath makePath: /col= lections/onenodecollection/leader_elect/shard1/election [junit4:junit4] 2> C161_STATE=3Dcoll:collection1 core:collection1 props:= {shard=3Dshard2, state=3Drecovering, core=3Dcollection1, collection=3Dcolle= ction1, node_name=3D127.0.0.1:47567_, base_url=3Dhttp://127.0.0.1:47567} [junit4:junit4] 2> 23035 T2211 C161 P47567 oasc.RecoveryStrategy.doRecove= ry Attempting to PeerSync from http://127.0.0.1:17755/collection1/ core=3Dc= ollection1 - recoveringAfterStartup=3Dtrue [junit4:junit4] 2> 23035 T2211 C161 P47567 oasu.PeerSync.sync PeerSync: c= ore=3Dcollection1 url=3Dhttp://127.0.0.1:47567 START replicas=3D[http://127= .0.0.1:17755/collection1/] nUpdates=3D100 [junit4:junit4] 2> 23035 T2211 C161 P47567 oasu.PeerSync.sync WARNING no = frame of reference to tell of we've missed updates [junit4:junit4] 2> 23035 T2211 C161 P47567 oasc.RecoveryStrategy.doRecove= ry PeerSync Recovery was not successful - trying replication. core=3Dcollec= tion1 [junit4:junit4] 2> 23036 T2211 C161 P47567 oasc.RecoveryStrategy.doRecove= ry Starting Replication Recovery. core=3Dcollection1 [junit4:junit4] 2> 23036 T2211 C161 P47567 oasc.RecoveryStrategy.doRecove= ry Begin buffering updates. core=3Dcollection1 [junit4:junit4] 2> 23036 T2211 C161 P47567 oasu.UpdateLog.bufferUpdates S= tarting to buffer updates. FSUpdateLog{state=3DACTIVE, tlog=3Dnull} [junit4:junit4] 2> 23036 T2211 C161 P47567 oasc.RecoveryStrategy.replicat= e Attempting to replicate from http://127.0.0.1:17755/collection1/. core=3D= collection1 [junit4:junit4] 2> 23036 T2211 C161 P47567 oascsi.HttpClientUtil.createCl= ient Creating new http client, config:maxConnections=3D128&maxConnectionsPe= rHost=3D32&followRedirects=3Dfalse [junit4:junit4] 2> 23039 T2122 oazs.PrepRequestProcessor.pRequest Got use= r-level KeeperException when processing sessionid:0x13d66b13e920006 type:de= lete cxid:0xaa zxid:0xc5 txntype:-1 reqpath:n/a Error Path:/solr/collection= s/onenodecollection/leaders Error:KeeperErrorCode =3D NoNode for /solr/coll= ections/onenodecollection/leaders [junit4:junit4] 2> 23040 T2150 oasc.ShardLeaderElectionContext.runLeaderP= rocess Running the leader process. [junit4:junit4] 2> 23040 T2122 oazs.PrepRequestProcessor.pRequest Got use= r-level KeeperException when processing sessionid:0x13d66b13e920006 type:cr= eate cxid:0xab zxid:0xc6 txntype:-1 reqpath:n/a Error Path:/solr/overseer E= rror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 23043 T2150 oasc.ShardLeaderElectionContext.waitForRep= licasToComeUp Enough replicas found to continue. [junit4:junit4] 2> 23043 T2150 oasc.ShardLeaderElectionContext.runLeaderP= rocess I may be the new leader - try and sync [junit4:junit4] 2> ASYNC NEW_CORE C163 name=3Dcollection1 org.apache.sol= r.core.SolrCore@5f5ce228 url=3Dhttp://127.0.0.1:17755/collection1 node=3D12= 7.0.0.1:17755_ C163_STATE=3Dcoll:collection1 core:collection1 props:{shard= =3Dshard2, state=3Dactive, core=3Dcollection1, collection=3Dcollection1, no= de_name=3D127.0.0.1:17755_, base_url=3Dhttp://127.0.0.1:17755, leader=3Dtru= e} [junit4:junit4] 2> 23043 T2166 C163 P17755 REQ /get {getVersions=3D100&di= strib=3Dfalse&wt=3Djavabin&qt=3D/get&version=3D2} status=3D0 QTime=3D0=20 [junit4:junit4] 2> 23043 T2150 oasc.SyncStrategy.sync Sync replicas to ht= tp://127.0.0.1:64400/onenodecollectioncore/ [junit4:junit4] 2> 23044 T2150 oasc.SyncStrategy.syncReplicas Sync Succes= s - now sync replicas to me [junit4:junit4] 2> 23044 T2150 oasc.SyncStrategy.syncToMe http://127.0.0.= 1:64400/onenodecollectioncore/ has no replicas [junit4:junit4] 2> 23044 T2150 oasc.ShardLeaderElectionContext.runLeaderP= rocess I am the new leader: http://127.0.0.1:64400/onenodecollectioncore/ [junit4:junit4] 2> 23045 T2150 oascc.SolrZkClient.makePath makePath: /col= lections/onenodecollection/leaders/shard1 [junit4:junit4] 2> 23049 T2122 oazs.PrepRequestProcessor.pRequest Got use= r-level KeeperException when processing sessionid:0x13d66b13e920006 type:cr= eate cxid:0xb5 zxid:0xca txntype:-1 reqpath:n/a Error Path:/solr/overseer E= rror:KeeperErrorCode =3D NodeExists for /solr/overseer [junit4:junit4] 2> 23053 T2167 C163 P17755 oasu.DirectUpdateHandler2.comm= it start commit{,optimize=3Dfalse,openSearcher=3Dfalse,waitSearcher=3Dtrue,= expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 23055 T2167 C163 P17755 oasc.SolrDeletionPolicy.onInit= SolrDeletionPolicy.onInit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@6f4bd2bb lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@5f941df6; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> 23056 T2167 C163 P17755 oasc.SolrDeletionPolicy.update= Commits newest commit =3D 1[segments_1] [junit4:junit4] 2> 23056 T2167 C163 P17755 oasc.SolrDeletionPolicy.onComm= it SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@6f4bd2bb lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@5f941df6; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@6f4bd2bb lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@5f941df6; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2= ] [junit4:junit4] 2> 23057 T2167 C163 P17755 oasc.SolrDeletionPolicy.update= Commits newest commit =3D 2[segments_2] [junit4:junit4] 2> 23057 T2167 C163 P17755 oass.SolrIndexSearcher. = Opening Searcher@684bea7e realtime [junit4:junit4] 2> 23058 T2167 C163 P17755 oasu.DirectUpdateHandler2.comm= it end_commit_flush [junit4:junit4] 2> 23058 T2167 C163 P17755 /update {waitSearcher=3Dtrue&o= penSearcher=3Dfalse&commit=3Dtrue&wt=3Djavabin&commit_end_point=3Dtrue&vers= ion=3D2&softCommit=3Dfalse} {commit=3D} 0 5 [junit4:junit4] 2> 23059 T2211 C161 P47567 oash.ReplicationHandler.inform= Commits will be reserved for 10000 [junit4:junit4] 2> 23059 T2211 C161 P47567 oash.SnapPuller. No val= ue set for 'pollInterval'. Timer Task not started. [junit4:junit4] 2> 23060 T2168 C163 P17755 oash.ReplicationHandler.inform= Commits will be reserved for 10000 [junit4:junit4] 2> 23061 T2168 C163 P17755 REQ /replication {command=3Din= dexversion&qt=3D/replication&wt=3Djavabin&version=3D2} status=3D0 QTime=3D1= =20 [junit4:junit4] 2> 23061 T2211 C161 P47567 oash.SnapPuller.fetchLatestInd= ex Master's generation: 2 [junit4:junit4] 2> 23061 T2211 C161 P47567 oash.SnapPuller.fetchLatestInd= ex Slave's generation: 1 [junit4:junit4] 2> 23062 T2211 C161 P47567 oash.SnapPuller.fetchLatestInd= ex Starting replication process [junit4:junit4] 2> 23064 T2168 C163 P17755 REQ /replication {command=3Dfi= lelist&qt=3D/replication&wt=3Djavabin&generation=3D2&version=3D2} status=3D= 0 QTime=3D0=20 [junit4:junit4] 2> 23065 T2211 C161 P47567 oash.SnapPuller.fetchLatestInd= ex Number of files in latest index in master: 1 [junit4:junit4] 2> 23066 T2211 C161 P47567 oasc.CachingDirectoryFactory.g= et return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test= -1363227524744/jetty4/index.20130313221907804 forceNew: false [junit4:junit4] 2> 23066 T2211 C161 P47567 oash.SnapPuller.fetchLatestInd= ex Starting download to MockDirWrapper(RateLimitedDirectoryWrapper(org.apac= he.lucene.store.RAMDirectory@4cdbfd25 lockFactory=3Dorg.apache.lucene.store= .NativeFSLockFactory@297dd4a9)) fullCopy=3Dfalse [junit4:junit4] 2> 23069 T2168 C163 P17755 REQ /replication {file=3Dsegme= nts_2&command=3Dfilecontent&checksum=3Dtrue&wt=3Dfilestream&qt=3D/replicati= on&generation=3D2} status=3D0 QTime=3D0=20 [junit4:junit4] 2> 23070 T2211 C161 P47567 oash.SnapPuller.fetchLatestInd= ex Total time taken for download : 0 secs [junit4:junit4] 2> 23071 T2211 C161 P47567 oasu.DefaultSolrCoreState.newI= ndexWriter Creating new IndexWriter... [junit4:junit4] 2> 23071 T2211 C161 P47567 oasu.DefaultSolrCoreState.newI= ndexWriter Waiting until IndexWriter is unused... core=3Dcollection1 [junit4:junit4] 2> 23072 T2211 C161 P47567 oasc.SolrDeletionPolicy.onInit= SolrDeletionPolicy.onInit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@7c67fb69 lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@d244002; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@7c67fb69 lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@d244002; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2= ] [junit4:junit4] 2> 23073 T2211 C161 P47567 oasc.SolrDeletionPolicy.update= Commits newest commit =3D 2[segments_2] [junit4:junit4] 2> 23073 T2211 C161 P47567 oasu.DefaultSolrCoreState.newI= ndexWriter New IndexWriter is ready to be used. [junit4:junit4] 2> 23073 T2211 C161 P47567 oass.SolrIndexSearcher. = Opening Searcher@493e8270 main [junit4:junit4] 2> 23074 T2210 oasc.SolrCore.registerSearcher [collection= 1] Registered new searcher Searcher@493e8270 main{StandardDirectoryReader(s= egments_2:1:nrt)} [junit4:junit4] 2> 23075 T2211 C161 P47567 oash.SnapPuller.fetchLatestInd= ex removing temporary index download directory files MockDirWrapper(RateLim= itedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@4cdbfd25 lockFact= ory=3Dorg.apache.lucene.store.NativeFSLockFactory@297dd4a9)) [junit4:junit4] 2> 23075 T2211 C161 P47567 oasc.RecoveryStrategy.replay N= o replay needed. core=3Dcollection1 [junit4:junit4] 2> 23075 T2211 C161 P47567 oasc.RecoveryStrategy.doRecove= ry Replication Recovery was successful - registering as Active. core=3Dcoll= ection1 [junit4:junit4] 2> 23075 T2211 C161 P47567 oasc.ZkController.publish publ= ishing core=3Dcollection1 state=3Dactive [junit4:junit4] 2> 23075 T2211 C161 P47567 oasc.ZkController.publish numS= hards not found on descriptor - reading it from system property [junit4:junit4] 2> 23077 T2211 C161 P47567 oasc.RecoveryStrategy.doRecove= ry Finished recovery process. core=3Dcollection1 [junit4:junit4] 2> 23677 T2140 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 23693 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate 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:47567_", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:47567"} [junit4:junit4] 2> 23705 T2139 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 23705 T2191 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 23705 T2146 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 23705 T2175 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 23705 T2208 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 23705 T2159 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 23714 T2150 oasc.ZkController.register We are http://1= 27.0.0.1:64400/onenodecollectioncore/ and leader is http://127.0.0.1:64400/= onenodecollectioncore/ [junit4:junit4] 2> 23714 T2150 oasc.ZkController.register No LogReplay ne= eded for core=3Donenodecollectioncore baseURL=3Dhttp://127.0.0.1:64400 [junit4:junit4] 2> 23714 T2150 oasc.ZkController.checkRecovery I am the l= eader, no recovery necessary [junit4:junit4] 2> 23715 T2150 oasc.ZkController.publish publishing core= =3Donenodecollectioncore state=3Dactive [junit4:junit4] 2> 23719 T2150 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 23720 T2150 oass.SolrDispatchFilter.handleAdminRequest= /admin/cores {numShards=3D1&roles=3Dnone&name=3Donenodecollectioncore&acti= on=3DCREATE&collection=3Donenodecollection&dataDir=3D/usr/home/hudson/hudso= n-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J= 1/./solrtest-BasicDistributedZk2Test-1363227524745/onenodecollection&wt=3Dj= avabin&version=3D2} status=3D0 QTime=3D3672=20 [junit4:junit4] 2> 23720 T2117 oasc.AbstractDistribZkTestBase.waitForReco= veriesToFinish Wait for recoveries to finish - collection: onenodecollectio= n failOnTimeout:true timeout (sec):230 [junit4:junit4] 2> 23721 T2117 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 24723 T2117 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 25220 T2140 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 25221 T2140 oasc.Overseer$ClusterStateUpdater.updateSt= ate 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:64400_", [junit4:junit4] 2> =09 "base_url":"http://127.0.0.1:64400"} [junit4:junit4] 2> 25233 T2208 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 25233 T2146 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 25233 T2159 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 25233 T2191 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 25233 T2175 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 25233 T2139 oascc.ZkStateReader$2.process A cluster st= ate change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clu= sterstate.json, has occurred - updating... (live nodes size: 5) [junit4:junit4] 2> 25725 T2117 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 25727 T2117 oasc.AbstractDistribZkTestBase.waitForReco= veriesToFinish Recoveries finished - collection: onenodecollection [junit4:junit4] 2> 25727 T2117 oascsi.HttpClientUtil.createClient Creatin= g new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&f= ollowRedirects=3Dfalse [junit4:junit4] 2> ASYNC NEW_CORE C164 name=3Donenodecollectioncore org.= apache.solr.core.SolrCore@483f6e20 url=3Dhttp://127.0.0.1:64400/onenodecoll= ectioncore node=3D127.0.0.1:64400_ C164_STATE=3Dcoll:onenodecollection core= :onenodecollectioncore props:{shard=3Dshard1, roles=3Dnone, state=3Dactive,= core=3Donenodecollectioncore, collection=3Donenodecollection, node_name=3D= 127.0.0.1:64400_, base_url=3Dhttp://127.0.0.1:64400, leader=3Dtrue} [junit4:junit4] 2> 25753 T2154 C164 P64400 oasc.SolrDeletionPolicy.onInit= SolrDeletionPolicy.onInit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@428c8e9d lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@7459376; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> 25754 T2154 C164 P64400 oasc.SolrDeletionPolicy.update= Commits newest commit =3D 1[segments_1] [junit4:junit4] 2> 25756 T2154 C164 P64400 /update {wt=3Djavabin&version= =3D2} {add=3D[1 (1429447691982602240)]} 0 6 [junit4:junit4] 2> 25763 T2154 C164 P64400 oasu.DirectUpdateHandler2.comm= it start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,e= xpungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 25766 T2154 C164 P64400 oasc.SolrDeletionPolicy.onComm= it SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@428c8e9d lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@7459376; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@428c8e9d lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@7459376; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_2,generation=3D2,filenames=3D[_0.fnm, _0= _Disk_0.dvdd, _0_MockSep_0.pos, _0_Memory_0.ram, _0.nvm, _0_Disk_0.dvdm, _0= _MockSep_0.tib, _0_Pulsing41_0.doc, _0_Pulsing41_0.pos, _0_MockSep_0.skp, _= 0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0_SimpleText_0.pst, _0.nvd, _0_Mock= Sep_0.frq, segments_2, _0.fdx, _0_MockSep_0.tii, _0.si, _0_MockSep_0.doc, _= 0_MockSep_0.pyl, _0.fdt] [junit4:junit4] 2> 25767 T2154 C164 P64400 oasc.SolrDeletionPolicy.update= Commits newest commit =3D 2[_0.fnm, _0_Disk_0.dvdd, _0_MockSep_0.pos, _0_Me= mory_0.ram, _0.nvm, _0_Disk_0.dvdm, _0_MockSep_0.tib, _0_Pulsing41_0.doc, _= 0_Pulsing41_0.pos, _0_MockSep_0.skp, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip= , _0_SimpleText_0.pst, _0.nvd, _0_MockSep_0.frq, segments_2, _0.fdx, _0_Moc= kSep_0.tii, _0.si, _0_MockSep_0.doc, _0_MockSep_0.pyl, _0.fdt] [junit4:junit4] 2> 25769 T2154 C164 P64400 oass.SolrIndexSearcher. = Opening Searcher@15d6296a main [junit4:junit4] 2> 25769 T2154 C164 P64400 oasu.DirectUpdateHandler2.comm= it end_commit_flush [junit4:junit4] 2> 25770 T2215 oasc.SolrCore.registerSearcher [onenodecol= lectioncore] Registered new searcher Searcher@15d6296a main{StandardDirecto= ryReader(segments_2:3 _0(5.0):C1)} [junit4:junit4] 2> 25770 T2154 C164 P64400 /update {waitSearcher=3Dtrue&c= ommit=3Dtrue&wt=3Djavabin&version=3D2&softCommit=3Dfalse} {commit=3D} 0 7 [junit4:junit4] 2> 25774 T2154 C164 P64400 REQ /select {q=3D*:*&wt=3Djava= bin&version=3D2} hits=3D1 status=3D0 QTime=3D1=20 [junit4:junit4] 2> 25775 T2117 oascsi.HttpClientUtil.createClient Creatin= g new http client, config:maxConnections=3D128&maxConnectionsPerHost=3D32&f= ollowRedirects=3Dfalse [junit4:junit4] 2> 25784 T2154 C164 P64400 REQ /select {q=3D*:*&wt=3Djava= bin&version=3D2} hits=3D1 status=3D0 QTime=3D1=20 [junit4:junit4] 2> ASYNC NEW_CORE C165 name=3Dcollection1 org.apache.sol= r.core.SolrCore@19e99c0f url=3Dhttp://127.0.0.1:14029/collection1 node=3D12= 7.0.0.1:14029_ C165_STATE=3Dcoll:control_collection core:collection1 props:= {shard=3Dshard1, state=3Dactive, core=3Dcollection1, collection=3Dcontrol_c= ollection, node_name=3D127.0.0.1:14029_, base_url=3Dhttp://127.0.0.1:14029,= leader=3Dtrue} [junit4:junit4] 2> 25793 T2129 C165 P14029 oasc.SolrDeletionPolicy.onInit= SolrDeletionPolicy.onInit: commits:num=3D1 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@fdd241a lockFactory=3Dorg.apache.lucen= e.store.NativeFSLockFactory@69a1c8d6; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> 25794 T2129 C165 P14029 oasc.SolrDeletionPolicy.update= Commits newest commit =3D 1[segments_1] [junit4:junit4] 2> 25797 T2129 C165 P14029 /update {wt=3Djavabin&version= =3D2} {add=3D[1 (1429447692024545280)]} 0 6 [junit4:junit4] 2> C160_STATE=3Dcoll:collection1 core:collection1 props:= {shard=3Dshard1, state=3Dactive, core=3Dcollection1, collection=3Dcollectio= n1, node_name=3D127.0.0.1:62522_, base_url=3Dhttp://127.0.0.1:62522} [junit4:junit4] 2> 25817 T2181 C160 P62522 /update {distrib.from=3Dhttp:/= /127.0.0.1:64400/collection1/&update.distrib=3DFROMLEADER&wt=3Djavabin&vers= ion=3D2} {add=3D[1 (1429447692040273920)]} 0 2 [junit4:junit4] 2> 25818 T2155 C162 P64400 /update {distrib.from=3Dhttp:/= /127.0.0.1:17755/collection1/&update.distrib=3DTOLEADER&wt=3Djavabin&versio= n=3D2} {add=3D[1 (1429447692040273920)]} 0 13 [junit4:junit4] 2> 25819 T2171 C163 P17755 /update {wt=3Djavabin&version= =3D2} {add=3D[1]} 0 16 [junit4:junit4] 2> 25821 T2129 C165 P14029 oasu.DirectUpdateHandler2.comm= it start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,e= xpungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 25827 T2129 C165 P14029 oasc.SolrDeletionPolicy.onComm= it SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@fdd241a lockFactory=3Dorg.apache.lucen= e.store.NativeFSLockFactory@69a1c8d6; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_1,generation=3D1,filenames=3D[segments_1= ] [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@fdd241a lockFactory=3Dorg.apache.lucen= e.store.NativeFSLockFactory@69a1c8d6; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_2,generation=3D2,filenames=3D[_0.fnm, _0= _Disk_0.dvdd, _0_MockSep_0.pos, _0_Memory_0.ram, _0.nvm, _0_Disk_0.dvdm, _0= _MockSep_0.tib, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_Pulsing41_0.tim,= _0_MockSep_0.skp, _0_Pulsing41_0.tip, _0_SimpleText_0.pst, _0.nvd, _0_Mock= Sep_0.frq, segments_2, _0.fdx, _0_MockSep_0.tii, _0.si, _0_MockSep_0.pyl, _= 0_MockSep_0.doc, _0.fdt] [junit4:junit4] 2> 25828 T2129 C165 P14029 oasc.SolrDeletionPolicy.update= Commits newest commit =3D 2[_0.fnm, _0_Disk_0.dvdd, _0_MockSep_0.pos, _0_Me= mory_0.ram, _0.nvm, _0_Disk_0.dvdm, _0_MockSep_0.tib, _0_Pulsing41_0.pos, _= 0_Pulsing41_0.doc, _0_Pulsing41_0.tim, _0_MockSep_0.skp, _0_Pulsing41_0.tip= , _0_SimpleText_0.pst, _0.nvd, _0_MockSep_0.frq, segments_2, _0.fdx, _0_Moc= kSep_0.tii, _0.si, _0_MockSep_0.pyl, _0_MockSep_0.doc, _0.fdt] [junit4:junit4] 2> 25829 T2129 C165 P14029 oass.SolrIndexSearcher. = Opening Searcher@2aad2530 main [junit4:junit4] 2> 25830 T2129 C165 P14029 oasu.DirectUpdateHandler2.comm= it end_commit_flush [junit4:junit4] 2> 25831 T2143 oasc.SolrCore.registerSearcher [collection= 1] Registered new searcher Searcher@2aad2530 main{StandardDirectoryReader(s= egments_2:3 _0(5.0):C1)} [junit4:junit4] 2> 25831 T2129 C165 P14029 /update {waitSearcher=3Dtrue&c= ommit=3Dtrue&wt=3Djavabin&version=3D2&softCommit=3Dfalse} {commit=3D} 0 10 [junit4:junit4] 2> 25834 T2171 C163 P17755 oasu.DirectUpdateHandler2.comm= it start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,e= xpungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 25835 T2171 C163 P17755 oasc.SolrDeletionPolicy.onComm= it SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@6f4bd2bb lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@5f941df6; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2= ] [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@6f4bd2bb lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@5f941df6; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_3,generation=3D3,filenames=3D[segments_3= ] [junit4:junit4] 2> 25836 T2171 C163 P17755 oasc.SolrDeletionPolicy.update= Commits newest commit =3D 3[segments_3] [junit4:junit4] 2> 25836 T2171 C163 P17755 oass.SolrIndexSearcher. = Opening Searcher@68a9f8a1 main [junit4:junit4] 2> 25837 T2171 C163 P17755 oasu.DirectUpdateHandler2.comm= it end_commit_flush [junit4:junit4] 2> 25837 T2177 oasc.SolrCore.registerSearcher [collection= 1] Registered new searcher Searcher@68a9f8a1 main{StandardDirectoryReader(s= egments_2:1:nrt)} [junit4:junit4] 2> 25837 T2171 C163 P17755 oasu.SolrCmdDistributor.distri= bCommit Distrib commit to:[StdNode: http://127.0.0.1:64400/collection1/, St= dNode: http://127.0.0.1:62522/collection1/, StdNode: http://127.0.0.1:47567= /collection1/] params:commit_end_point=3Dtrue&commit=3Dtrue&softCommit=3Dfa= lse&waitSearcher=3Dtrue&expungeDeletes=3Dfalse [junit4:junit4] 2> 25839 T2182 C160 P62522 oasu.DirectUpdateHandler2.comm= it start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,e= xpungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 25840 T2155 C162 P64400 oasu.DirectUpdateHandler2.comm= it start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,e= xpungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 25845 T2155 C162 P64400 oasc.SolrDeletionPolicy.onComm= it SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@6809635b lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@f40f91d; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2= ] [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@6809635b lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@f40f91d; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_3,generation=3D3,filenames=3D[_0.fnm, _0= _Disk_0.dvdd, _0_MockSep_0.pos, _0_Memory_0.ram, _0.nvm, _0_Disk_0.dvdm, _0= _MockSep_0.tib, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_Pulsing41_0.tim,= _0_MockSep_0.skp, _0_Pulsing41_0.tip, _0_SimpleText_0.pst, _0.nvd, _0_Mock= Sep_0.frq, _0.fdx, _0_MockSep_0.tii, _0.si, _0_MockSep_0.pyl, _0_MockSep_0.= doc, _0.fdt, segments_3] [junit4:junit4] 2> 25846 T2155 C162 P64400 oasc.SolrDeletionPolicy.update= Commits newest commit =3D 3[_0.fnm, _0_Disk_0.dvdd, _0_MockSep_0.pos, _0_Me= mory_0.ram, _0.nvm, _0_Disk_0.dvdm, _0_MockSep_0.tib, _0_Pulsing41_0.pos, _= 0_Pulsing41_0.doc, _0_Pulsing41_0.tim, _0_MockSep_0.skp, _0_Pulsing41_0.tip= , _0_SimpleText_0.pst, _0.nvd, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, = _0.si, _0_MockSep_0.pyl, _0_MockSep_0.doc, _0.fdt, segments_3] [junit4:junit4] 2> C161_STATE=3Dcoll:collection1 core:collection1 props:= {shard=3Dshard2, state=3Dactive, core=3Dcollection1, collection=3Dcollectio= n1, node_name=3D127.0.0.1:47567_, base_url=3Dhttp://127.0.0.1:47567} [junit4:junit4] 2> 25846 T2198 C161 P47567 oasu.DirectUpdateHandler2.comm= it start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,e= xpungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4:junit4] 2> 25846 T2182 C160 P62522 oasc.SolrDeletionPolicy.onComm= it SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@7eab0d73 lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@171944e1; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2= ] [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@7eab0d73 lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@171944e1; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_3,generation=3D3,filenames=3D[_0.fnm, _0= _Disk_0.dvdd, _0_MockSep_0.pos, _0_Memory_0.ram, _0.nvm, _0_Disk_0.dvdm, _0= _MockSep_0.tib, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_Pulsing41_0.tim,= _0_MockSep_0.skp, _0_Pulsing41_0.tip, _0_SimpleText_0.pst, _0.nvd, _0_Mock= Sep_0.frq, _0.fdx, _0_MockSep_0.tii, _0.si, _0_MockSep_0.pyl, _0_MockSep_0.= doc, _0.fdt, segments_3] [junit4:junit4] 2> 25847 T2182 C160 P62522 oasc.SolrDeletionPolicy.update= Commits newest commit =3D 3[_0.fnm, _0_Disk_0.dvdd, _0_MockSep_0.pos, _0_Me= mory_0.ram, _0.nvm, _0_Disk_0.dvdm, _0_MockSep_0.tib, _0_Pulsing41_0.pos, _= 0_Pulsing41_0.doc, _0_Pulsing41_0.tim, _0_MockSep_0.skp, _0_Pulsing41_0.tip= , _0_SimpleText_0.pst, _0.nvd, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, = _0.si, _0_MockSep_0.pyl, _0_MockSep_0.doc, _0.fdt, segments_3] [junit4:junit4] 2> 25847 T2155 C162 P64400 oass.SolrIndexSearcher. = Opening Searcher@740f07b7 main [junit4:junit4] 2> 25847 T2198 C161 P47567 oasc.SolrDeletionPolicy.onComm= it SolrDeletionPolicy.onCommit: commits:num=3D2 [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@7c67fb69 lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@d244002; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_2,generation=3D2,filenames=3D[segments_2= ] [junit4:junit4] 2> =09=09commit{dir=3DMockDirWrapper(NRTCachingDirectory(= org.apache.lucene.store.RAMDirectory@7c67fb69 lockFactory=3Dorg.apache.luce= ne.store.NativeFSLockFactory@d244002; maxCacheMB=3D0.578125 maxMergeSizeMB= =3D0.6806640625)),segFN=3Dsegments_3,generation=3D3,filenames=3D[segments_3= ] [junit4:junit4] 2> 25848 T2155 C162 P64400 oasu.DirectUpdateHandler2.comm= it end_commit_flush [junit4:junit4] 2> 25848 T2198 C161 P47567 oasc.SolrDeletionPolicy.update= Commits newest commit =3D 3[segments_3] [junit4:junit4] 2> 25848 T2161 oasc.SolrCore.registerSearcher [collection= 1] Registered new searcher Searcher@740f07b7 main{StandardDirectoryReader(s= egments_3:3:nrt _0(5.0):C1)} [junit4:junit4] 2> 25848 T2198 C161 P47567 oass.SolrIndexSearcher. = Opening Searcher@32bd7a8d main [junit4:junit4] 2> 25849 T2155 C162 P64400 /update {waitSearcher=3Dtrue&c= ommit=3Dtrue&wt=3Djavabin&expungeDeletes=3Dfalse&commit_end_point=3Dtrue&ve= rsion=3D2&softCommit=3Dfalse} {commit=3D} 0 9 [junit4:junit4] 2> 25849 T2198 C161 P47567 oasu.DirectUpdateHandler2.comm= it end_commit_flush [junit4:junit4] 2> 25849 T2210 oasc.SolrCore.registerSearcher [collection= 1] Registered new searcher Searcher@32bd7a8d main{StandardDirectoryReader(s= egments_2:1:nrt)} [junit4:junit4] 2> 25850 T2198 C161 P47567 /update {waitSearcher=3Dtrue&c= ommit=3Dtrue&wt=3Djavabin&expungeDeletes=3Dfalse&commit_end_point=3Dtrue&ve= rsion=3D2&softCommit=3Dfalse} {commit=3D} 0 4 [junit4:junit4] 2> 25899 T2182 C160 P62522 oass.SolrIndexSearcher. = Opening Searcher@1de2ef31 main [junit4:junit4] 2> 25900 T2182 C160 P62522 oasu.DirectUpdateHandler2.comm= it end_commit_flush [junit4:junit4] 2> 25900 T2193 oasc.SolrCore.registerSearcher [collection= 1] Registered new searcher Searcher@1de2ef31 main{StandardDirectoryReader(s= egments_3:3:nrt _0(5.0):C1)} [junit4:junit4] 2> 25901 T2182 C160 P62522 /update {waitSearcher=3Dtrue&c= ommit=3Dtrue&wt=3Djavabin&expungeDeletes=3Dfalse&commit_end_point=3Dtrue&ve= rsion=3D2&softCommit=3Dfalse} {commit=3D} 0 62 [junit4:junit4] 2> 25901 T2171 C163 P17755 /update {waitSearcher=3Dtrue&c= ommit=3Dtrue&wt=3Djavabin&version=3D2&softCommit=3Dfalse} {commit=3D} 0 67 [junit4:junit4] 2> 25902 T2117 oasc.AbstractDistribZkTestBase.waitForReco= veriesToFinish Wait for recoveries to finish - collection: collection1 fail= OnTimeout:true timeout (sec):230 [junit4:junit4] 2> 25903 T2117 oascc.ZkStateReader.updateClusterState Upd= ating cloud state from ZooKeeper...=20 [junit4:junit4] 2> 25904 T2117 oasc.AbstractDistribZkTestBase.waitForReco= veriesToFinish Recoveries finished - collection: collection1 [junit4:junit4] 2> 25906 T2129 C165 P14029 REQ /select {q=3D*:*&wt=3Djava= bin&version=3D2} hits=3D1 status=3D0 QTime=3D0=20 [junit4:junit4] 2> 25907 T2117 oaz.ZooKeeper. Initiating client con= nection, connectString=3D127.0.0.1:16556/solr sessionTimeout=3D10000 watche= r=3Dorg.apache.solr.common.cloud.ConnectionManager@1dc5894b [junit4:junit4] 2> 25908 T2117 oascc.ConnectionManager.waitForConnected W= aiting for client to connect to ZooKeeper [junit4:junit4] 2> 25909 T2223 oaz.ClientCnxn$SendThread.logStartConnect = Opening socket connection to server localhost/127.0.0.1:16556. Will not att= empt to authenticate using SASL (access denied (javax.security.auth.AuthPer= mission getLoginConfiguration)) [junit4:junit4] 2> 25909 T2223 oaz.ClientCnxn$SendThread.primeConnection = Socket connection established to localhost/127.0.0.1:16556, initiating sess= ion [junit4:junit4] 2> 25909 T2119 oazs.NIOServerCnxnFactory.run Accepted soc= ket connection from /140.211.11.196:55208 [junit4:junit4] 2> 25910 T2119 oazs.ZooKeeperServer.processConnectRequest= Client attempting to establish new session at /140.211.11.196:55208 [junit4:junit4] 2> 25936 T2121 oazs.ZooKeeperServer.finishSessionInit Est= ablished session 0x13d66b13e92000d with negotiated timeout 10000 for client= /140.211.11.196:55208 [junit4:junit4] 2> 25936 T2223 oaz.ClientCnxn$SendThread.onConnected Sess= ion establishment complete on server localhost/127.0.0.1:16556, sessionid = =3D 0x13d66b13e92000d, negotiated timeout =3D 10000 [junit4:junit4] 2> 25936 T2224 oascc.ConnectionManager.process Watcher or= g.apache.solr.common.cloud.ConnectionManager@1dc5894b name:ZooKeeperConnect= ion Watcher:127.0.0.1:16556/solr got event WatchedEvent state:SyncConnected= type:None path:null path:null type:None [junit4:junit4] 2> 25936 T2117 oascc.ConnectionManager.waitForConnected C= lient is connected to ZooKeeper [junit4:junit4] 2> 25938 T2117 oascc.ZkStateReader.createClusterStateWatc= hersAndUpdate Updating cluster state from ZooKeeper...=20 [junit4:junit4] 2> 25940 T2122 oazs.PrepRequestProcessor.pRequest2Txn Pro= cessed session termination for sessionid: 0x13d66b13e92000d [junit4:junit4] 2> 25941 T2224 oaz.ClientCnxn$EventThread.run EventThread= shut down [junit4:junit4] 2> 25941 T2119 oazs.NIOServerCnxn.closeSock Closed socket= connection for client /140.211.11.196:55208 which had sessionid 0x13d66b13= e92000d [junit4:junit4] 2> 25941 T2117 oaz.ZooKeeper.close Session: 0x13d66b13e92= 000d closed [junit4:junit4] 2> 25943 T2149 C162 P64400 REQ /select {q=3D*:*&distrib= =3Dfalse&wt=3Djavabin&version=3D2} hits=3D1 status=3D0 QTime=3D0=20 [junit4:junit4] 2> 25945 T2165 C163 P17755 REQ /select {q=3D*:*&distrib= =3Dfalse&wt=3Djavabin&version=3D2} hits=3D0 status=3D0 QTime=3D1=20 [junit4:junit4] 2> 25949 T2152 C162 P64400 REQ /select {NOW=3D13632275506= 86&shard.url=3D127.0.0.1:64400/collection1/|127.0.0.1:62522/collection1/&fl= =3Did,score&start=3D0&q=3D*:*&distrib=3Dfals [...truncated too long message...] .reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.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> 139245 T2117 oas.SolrTestCaseJ4.deleteCore ###deleteCo= re [junit4:junit4] 2> 139252 T2116 ccr.ThreadLeakControl.checkThreadLeaks WA= RNING Will linger awaiting termination of 1 leaked thread(s). [junit4:junit4] 2> 139306 T2208 oascc.ZkStateReader$3.process WARNING Zoo= Keeper watch triggered, but Solr cannot talk to ZK [junit4:junit4] 2> 139306 T2208 oascc.ZkStateReader$2.process A cluster s= tate change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path= :/live_nodes, has occurred - updating... (live nodes size: 1) [junit4:junit4] 2> 139306 T2208 oascc.ZkStateReader$2.process WARNING Zoo= Keeper watch triggered, but Solr cannot talk to ZK [junit4:junit4] 2> 139306 T2208 oaz.ClientCnxn$EventThread.run EventThrea= d shut down [junit4:junit4] 2> NOTE: test params are: codec=3DLucene42: {foo_b=3DPost= ingsFormat(name=3DMockSep), n_f1=3DPostingsFormat(name=3DMemory doPackFST= =3D true), foo_d=3DPulsing41(freqCutoff=3D17 minBlockSize=3D96 maxBlockSize= =3D270), foo_f=3DPostingsFormat(name=3DMockSep), n_tl1=3DPostingsFormat(nam= e=3DMemory doPackFST=3D true), n_d1=3DPostingsFormat(name=3DSimpleText), rn= d_b=3DPulsing41(freqCutoff=3D17 minBlockSize=3D96 maxBlockSize=3D270), intD= efault=3DPostingsFormat(name=3DSimpleText), n_td1=3DPostingsFormat(name=3DM= emory doPackFST=3D true), timestamp=3DPostingsFormat(name=3DSimpleText), id= =3DPulsing41(freqCutoff=3D17 minBlockSize=3D96 maxBlockSize=3D270), range_f= acet_sl=3DPostingsFormat(name=3DMockSep), range_facet_si=3DPostingsFormat(n= ame=3DMemory doPackFST=3D true), oddField_s=3DPostingsFormat(name=3DMockSep= ), multiDefault=3DPostingsFormat(name=3DMemory doPackFST=3D true), n_tf1=3D= PostingsFormat(name=3DSimpleText), n_dt1=3DPostingsFormat(name=3DMemory doP= ackFST=3D true), range_facet_l=3DPostingsFormat(name=3DSimpleText), n_ti1= =3DPulsing41(freqCutoff=3D17 minBlockSize=3D96 maxBlockSize=3D270), text=3D= PostingsFormat(name=3DMockSep), _version_=3DPostingsFormat(name=3DSimpleTex= t), SubjectTerms_mfacet=3DPostingsFormat(name=3DSimpleText), a_t=3DPostings= Format(name=3DSimpleText), n_tdt1=3DPostingsFormat(name=3DSimpleText), othe= r_tl1=3DPostingsFormat(name=3DSimpleText), n_l1=3DPostingsFormat(name=3DSim= pleText), a_si=3DPostingsFormat(name=3DMemory doPackFST=3D true)}, docValue= s:{timestamp=3DDocValuesFormat(name=3DDisk)}, sim=3DDefaultSimilarity, loca= le=3Den_IE, timezone=3DAmerica/Antigua [junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. = 1.6.0_32 (64-bit)/cpus=3D16,threads=3D1,free=3D74297848,total=3D456196096 [junit4:junit4] 2> NOTE: All tests run in this JVM: [TestJmxIntegration, = CollectionsAPIDistributedZkTest, TestRangeQuery, TestDistributedGrouping, P= ingRequestHandlerTest, TestBM25SimilarityFactory, CachingDirectoryFactoryTe= st, TestFieldCollectionResource, TestPropInject, TestLMJelinekMercerSimilar= ityFactory, XsltUpdateRequestHandlerTest, CurrencyFieldXmlFileTest, TestZkC= hroot, RequestHandlersTest, NoCacheHeaderTest, TestSuggestSpellingConverter= , SpellCheckComponentTest, SolrRequestParserTest, TermVectorComponentDistri= butedTest, TestCodecSupport, ClusterStateTest, TestIndexingPerformance, Tes= tMultiCoreConfBootstrap, TestWordDelimiterFilterFactory, TestDefaultSimilar= ityFactory, TestComponentsName, TestLazyCores, SortByFunctionTest, UniqFiel= dsUpdateProcessorFactoryTest, TestLuceneMatchVersion, XmlUpdateRequestHandl= erTest, TestPartialUpdateDeduplication, TestFoldingMultitermQuery, TestCSVR= esponseWriter, SuggesterTSTTest, TestArbitraryIndexDir, EchoParamsTest, Tes= tDistributedSearch, TestSystemIdResolver, TestUtils, UpdateParamsTest, Test= PostingsSolrHighlighter, BadIndexSchemaTest, TestSolrJ, TestHashPartitioner= , ShardRoutingCustomTest, ConvertedLegacyTest, TestSolr4Spatial, IndexReade= rFactoryTest, DocValuesMultiTest, OpenExchangeRatesOrgProviderTest, TestFie= ldTypeCollectionResource, TestQueryTypes, IndexSchemaRuntimeFieldTest, URLC= lassifyProcessorTest, TestFiltering, TestSolrDiscoveryProperties, ZkNodePro= psTest, TestStressLucene, TestBinaryResponseWriter, TestIndexSearcher, Test= DFRSimilarityFactory, TestJmxMonitoredMap, BasicDistributedZkTest, ChaosMon= keySafeLeaderTest, BasicDistributedZk2Test] [junit4:junit4] Completed on J1 in 139.54s, 1 test, 1 error <<< FAILURES! [...truncated 424 lines...] BUILD FAILED /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/build= .xml:381: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/build= .xml:361: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/build= .xml:39: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/= build.xml:183: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/= common-build.xml:449: The following error occurred while executing this lin= e: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/lucen= e/common-build.xml:1213: The following error occurred while executing this = line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/lucen= e/common-build.xml:877: There were test failures: 271 suites, 1142 tests, 1= error, 27 ignored (8 assumptions) Total time: 51 minutes 31 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_4198_1899652021.1363228193534 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_4198_1899652021.1363228193534--