Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id E0809200BD6 for ; Sun, 4 Dec 2016 12:25:54 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id DEFCC160B18; Sun, 4 Dec 2016 11:25:54 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 19648160AE4 for ; Sun, 4 Dec 2016 12:25:51 +0100 (CET) Received: (qmail 95679 invoked by uid 500); 4 Dec 2016 11:25:51 -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 95665 invoked by uid 99); 4 Dec 2016 11:25:50 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 04 Dec 2016 11:25:50 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id 18EC6C03A1 for ; Sun, 4 Dec 2016 11:25:50 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 2.001 X-Spam-Level: ** X-Spam-Status: No, score=2.001 tagged_above=-999 required=6.31 tests=[KAM_BADIPHTTP=2, SPF_PASS=-0.001, URIBL_BLOCKED=0.001, WEIRD_PORT=0.001] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id OO1Cj99I8vuu for ; Sun, 4 Dec 2016 11:25:34 +0000 (UTC) Received: from serv1.sd-datasolutions.de (serv1.sd-datasolutions.de [188.138.57.78]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTPS id 122225F19B for ; Sun, 4 Dec 2016 11:25:33 +0000 (UTC) Received: from serv1 (localhost.localdomain [127.0.0.1]) by serv1.sd-datasolutions.de (Postfix) with ESMTP id 81D494C03EB for ; Sun, 4 Dec 2016 11:25:23 +0000 (UTC) Date: Sun, 4 Dec 2016 11:23:26 +0000 (UTC) From: Policeman Jenkins Server To: dev@lucene.apache.org Message-ID: <640344244.97.1480850723533.JavaMail.jenkins@serv1> Subject: [JENKINS] Lucene-Solr-6.x-Windows (64bit/jdk1.8.0_102) - Build # 601 - Unstable! MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----=_Part_96_2019253692.1480850723468" X-Jenkins-Job: Lucene-Solr-6.x-Windows X-Jenkins-Result: UNSTABLE archived-at: Sun, 04 Dec 2016 11:25:55 -0000 ------=_Part_96_2019253692.1480850723468 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Windows/601/ Java: 64bit/jdk1.8.0_102 -XX:-UseCompressedOops -XX:+UseG1GC 1 tests failed. FAILED: org.apache.solr.cloud.HttpPartitionTest.test Error Message: Captured an uncaught exception in thread: Thread[id=3D14312, name=3DSocketP= roxy-Response-57622:58005, state=3DRUNNABLE, group=3DTGRP-HttpPartitionTest= ] Stack Trace: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an unca= ught exception in thread: Thread[id=3D14312, name=3DSocketProxy-Response-57= 622:58005, state=3DRUNNABLE, group=3DTGRP-HttpPartitionTest] Caused by: java.lang.RuntimeException: java.net.SocketException: Socket is = closed =09at __randomizedtesting.SeedInfo.seed([A6700AA91C60A879]:0) =09at org.apache.solr.cloud.SocketProxy$Bridge$Pump.run(SocketProxy.java:34= 7) Caused by: java.net.SocketException: Socket is closed =09at java.net.Socket.setSoTimeout(Socket.java:1137) =09at org.apache.solr.cloud.SocketProxy$Bridge$Pump.run(SocketProxy.java:34= 4) Build Log: [...truncated 12268 lines...] [junit4] Suite: org.apache.solr.cloud.HttpPartitionTest [junit4] 2> Creating dataDir: C:\Users\jenkins\workspace\Lucene-Solr-6= .x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.HttpPartitionTest_A= 6700AA91C60A879-001\init-core-data-001 [junit4] 2> 2312620 INFO (SUITE-HttpPartitionTest-seed#[A6700AA91C60A= 879]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientA= uth (false) via: @org.apache.solr.SolrTestCaseJ4$SuppressSSL(bugUrl=3Dhttps= ://issues.apache.org/jira/browse/SOLR-5776) [junit4] 2> 2312620 INFO (SUITE-HttpPartitionTest-seed#[A6700AA91C60A= 879]-worker) [ ] o.a.s.BaseDistributedSearchTestCase Setting hostContext= system property: /jm_pnl/b [junit4] 2> 2312623 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER [junit4] 2> 2312623 INFO (Thread-3965) [ ] o.a.s.c.ZkTestServer cl= ient port:0.0.0.0/0.0.0.0:0 [junit4] 2> 2312623 INFO (Thread-3965) [ ] o.a.s.c.ZkTestServer St= arting server [junit4] 2> 2312723 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.ZkTestServer start zk server on port:57611 [junit4] 2> 2312742 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\= Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\solr= config-tlog.xml to /configs/conf1/solrconfig.xml [junit4] 2> 2312745 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\= Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\sche= ma.xml to /configs/conf1/schema.xml [junit4] 2> 2312747 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\= Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\solr= config.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.r= andomindexconfig.xml [junit4] 2> 2312749 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\= Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\stop= words.txt to /configs/conf1/stopwords.txt [junit4] 2> 2312750 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\= Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\prot= words.txt to /configs/conf1/protwords.txt [junit4] 2> 2312752 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\= Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\curr= ency.xml to /configs/conf1/currency.xml [junit4] 2> 2312754 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\= Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\enum= sConfig.xml to /configs/conf1/enumsConfig.xml [junit4] 2> 2312755 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\= Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\open= -exchange-rates.json to /configs/conf1/open-exchange-rates.json [junit4] 2> 2312757 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\= Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\mapp= ing-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt [junit4] 2> 2312759 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\= Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\old_= synonyms.txt to /configs/conf1/old_synonyms.txt [junit4] 2> 2312761 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\= Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\syno= nyms.txt to /configs/conf1/synonyms.txt [junit4] 2> 2313437 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to C:\Us= ers\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\= temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\control-001\cores\co= llection1 [junit4] 2> 2313441 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 2313442 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHan= dler@4ffcee82{/jm_pnl/b,null,AVAILABLE} [junit4] 2> 2313443 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@31550109= {HTTP/1.1,[http/1.1]}{127.0.0.1:57622} [junit4] 2> 2313443 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.Server Started @2318257ms [junit4] 2> 2313443 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.d= ir=3DC:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-cor= e\test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\tempDir-00= 1/control/data, hostContext=3D/jm_pnl/b, hostPort=3D57621, coreRootDirector= y=3DC:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core= \test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\control-001= \cores} [junit4] 2> 2313443 ERROR (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.d= ir. Logging may be missing or incomplete. [junit4] 2> 2313443 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Ap= ache Solr? version 6.4.0 [junit4] 2> 2313443 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in c= loud mode on port null [junit4] 2> 2313443 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: = null [junit4] 2> 2313443 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2= 016-12-04T10:44:59.092Z [junit4] 2> 2313453 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome = (not found in ZooKeeper) [junit4] 2> 2313453 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from= C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\te= st\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\control-001\so= lr.xml [junit4] 2> 2313478 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTT= P client with params: socketTimeout=3D340000&connTimeout=3D45000&retry=3Dtr= ue [junit4] 2> 2313480 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.ZkContainer Zookeeper client=3D127.0.0.1:57611/sol= r [junit4] 2> 2313575 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.s.c.OverseerElectionContex= t I am going to be the leader 127.0.0.1:57621_jm_pnl%2Fb [junit4] 2> 2313576 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.s.c.Overseer Overseer (id= =3D97048874075815940-127.0.0.1:57621_jm_pnl%2Fb-n_0000000000) starting [junit4] 2> 2313584 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.s.c.ZkController Register = node as live in ZooKeeper:/live_nodes/127.0.0.1:57621_jm_pnl%2Fb [junit4] 2> 2313589 INFO (zkCallback-2269-thread-1-processing-n:127.0= .0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.s.c.c.ZkState= Reader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 2313646 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.s.c.CorePropertiesLocator = Found 1 core definitions underneath C:\Users\jenkins\workspace\Lucene-Solr-= 6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.HttpPartitionTest_= A6700AA91C60A879-001\control-001\cores [junit4] 2> 2313646 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.s.c.CorePropertiesLocator = Cores are: [collection1] [junit4] 2> 2313650 INFO (OverseerStateUpdate-97048874075815940-127.0= .0.1:57621_jm_pnl%2Fb-n_0000000000) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.= s.c.o.ReplicaMutator Assigning new node to shard shard=3Dshard1 [junit4] 2> 2314666 WARN (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion x:collection1] o.a.s.c.Config Beginning with Solr 5.5, = is deprecated, use instead. [junit4] 2> 2314667 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0 [junit4] 2> 2314681 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=3Dtest [junit4] 2> 2314812 WARN (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion x:collection1] o.a.s.s.IndexSchema [collection1] default search fiel= d in schema is text. WARNING: Deprecated, please use 'df' on request instea= d. [junit4] 2> 2314814 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqu= eid field id [junit4] 2> 2314835 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1'= using configuration from collection control_collection [junit4] 2> 2314836 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore [[collection1] ]= Opening new SolrCore at [C:\Users\jenkins\workspace\Lucene-Solr-6.x-Window= s\solr\build\solr-core\test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C= 60A879-001\control-001\cores\collection1], dataDir=3D[C:\Users\jenkins\work= space\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.= HttpPartitionTest_A6700AA91C60A879-001\control-001\cores\collection1\data\] [junit4] 2> 2314836 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion s:shard1 r:core_node1 x:collection1] o.a.s.c.JmxMonitoredMap JMX monit= oring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver= .JmxMBeanServer@8ada15b [junit4] 2> 2314836 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion s:shard1 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomM= ergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [= LogByteSizeMergePolicy: minMergeSize=3D1677721, mergeFactor=3D39, maxMergeS= ize=3D2147483648, maxMergeSizeForForcedMerge=3D9223372036854775807, calibra= teSizeByDeletes=3Dfalse, maxMergeDocs=3D2147483647, maxCFSSegmentSizeMB=3D8= .796093022207999E12, noCFSRatio=3D1.0] [junit4] 2> 2314839 WARN (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion s:shard1 r:core_node1 x:collection1] o.a.s.c.RequestHandlers INVALID p= aramSet a in requestHandler {type =3D requestHandler,name =3D /dump,class = =3D DumpRequestHandler,args =3D {defaults=3D{a=3DA,b=3DB}}} [junit4] 2> 2314852 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateHandler Using Updat= eLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 2314852 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Initializing Up= dateLog: dataDir=3D defaultSyncLevel=3DFLUSH numRecordsToKeep=3D100 maxNumL= ogsToKeep=3D10 numVersionBuckets=3D65536 [junit4] 2> 2314854 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion s:shard1 r:core_node1 x:collection1] o.a.s.u.CommitTracker Hard AutoCo= mmit: disabled [junit4] 2> 2314854 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion s:shard1 r:core_node1 x:collection1] o.a.s.u.CommitTracker Soft AutoCo= mmit: disabled [junit4] 2> 2314854 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion s:shard1 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomM= ergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDo= cMergePolicy: minMergeSize=3D1000, mergeFactor=3D12, maxMergeSize=3D9223372= 036854775807, maxMergeSizeForForcedMerge=3D9223372036854775807, calibrateSi= zeByDeletes=3Dtrue, maxMergeDocs=3D2147483647, maxCFSSegmentSizeMB=3D8.7960= 93022207999E12, noCFSRatio=3D0.5478978904233723] [junit4] 2> 2314855 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion s:shard1 r:core_node1 x:collection1] o.a.s.s.SolrIndexSearcher Opening= [Searcher@603c09ac[collection1] main] [junit4] 2> 2314856 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Co= nfigured ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 2314856 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Lo= aded null at path _rest_managed.json using ZooKeeperStorageIO:path=3D/confi= gs/conf1 [junit4] 2> 2314856 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion s:shard1 r:core_node1 x:collection1] o.a.s.h.ReplicationHandler Commit= s will be reserved for 10000 [junit4] 2> 2314857 INFO (searcherExecutor-6485-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb x:collection1 s:shard1 c:control_collection r:c= ore_node1) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collection s:shard1 r:co= re_node1 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searc= her Searcher@603c09ac[collection1] main{ExitableDirectoryReader(Uninverting= DirectoryReader())} [junit4] 2> 2314858 INFO (coreLoadExecutor-6484-thread-1-processing-n= :127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collec= tion s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Could not find = max version in index or recent updates, using new clock 1552781987552428032 [junit4] 2> 2314869 INFO (coreZkRegister-6477-thread-1-processing-n:1= 27.0.0.1:57621_jm_pnl%2Fb x:collection1 s:shard1 c:control_collection r:cor= e_node1) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collection s:shard1 r:core= _node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Enough replicas fo= und to continue. [junit4] 2> 2314869 INFO (coreZkRegister-6477-thread-1-processing-n:1= 27.0.0.1:57621_jm_pnl%2Fb x:collection1 s:shard1 c:control_collection r:cor= e_node1) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collection s:shard1 r:core= _node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I may be the new l= eader - try and sync [junit4] 2> 2314869 INFO (coreZkRegister-6477-thread-1-processing-n:1= 27.0.0.1:57621_jm_pnl%2Fb x:collection1 s:shard1 c:control_collection r:cor= e_node1) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collection s:shard1 r:core= _node1 x:collection1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.= 1:57621/jm_pnl/b/collection1/ [junit4] 2> 2314869 INFO (coreZkRegister-6477-thread-1-processing-n:1= 27.0.0.1:57621_jm_pnl%2Fb x:collection1 s:shard1 c:control_collection r:cor= e_node1) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collection s:shard1 r:core= _node1 x:collection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas= to me [junit4] 2> 2314869 INFO (coreZkRegister-6477-thread-1-processing-n:1= 27.0.0.1:57621_jm_pnl%2Fb x:collection1 s:shard1 c:control_collection r:cor= e_node1) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collection s:shard1 r:core= _node1 x:collection1] o.a.s.c.SyncStrategy http://127.0.0.1:57621/jm_pnl/b/= collection1/ has no replicas [junit4] 2> 2314875 INFO (coreZkRegister-6477-thread-1-processing-n:1= 27.0.0.1:57621_jm_pnl%2Fb x:collection1 s:shard1 c:control_collection r:cor= e_node1) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collection s:shard1 r:core= _node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I am the new leade= r: http://127.0.0.1:57621/jm_pnl/b/collection1/ shard1 [junit4] 2> 2315031 INFO (coreZkRegister-6477-thread-1-processing-n:1= 27.0.0.1:57621_jm_pnl%2Fb x:collection1 s:shard1 c:control_collection r:cor= e_node1) [n:127.0.0.1:57621_jm_pnl%2Fb c:control_collection s:shard1 r:core= _node1 x:collection1] o.a.s.c.ZkController I am the leader, no recovery nec= essary [junit4] 2> 2315185 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper.= .. (0) -> (1) [junit4] 2> 2315187 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.= 0.1:57611/solr ready [junit4] 2> 2315187 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.ChaosMonkey monkey: init - expire sessions:false c= ause connection loss:false [junit4] 2> 2315958 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to C:\Us= ers\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\= temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\shard-1-001\cores\co= llection1 [junit4] 2> 2315962 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 1 in di= rectory C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-= core\test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\shard-1= -001 [junit4] 2> 2315963 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 2315964 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHan= dler@a4a0cf2{/jm_pnl/b,null,AVAILABLE} [junit4] 2> 2315965 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@60dc94e5= {HTTP/1.1,[http/1.1]}{127.0.0.1:57652} [junit4] 2> 2315965 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.Server Started @2320779ms [junit4] 2> 2315965 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.d= ir=3DC:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-cor= e\test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\tempDir-00= 1/jetty1, solrconfig=3Dsolrconfig.xml, hostContext=3D/jm_pnl/b, hostPort=3D= 57651, coreRootDirectory=3DC:\Users\jenkins\workspace\Lucene-Solr-6.x-Windo= ws\solr\build\solr-core\test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91= C60A879-001\shard-1-001\cores} [junit4] 2> 2315965 ERROR (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.d= ir. Logging may be missing or incomplete. [junit4] 2> 2315965 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Ap= ache Solr? version 6.4.0 [junit4] 2> 2315967 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in c= loud mode on port null [junit4] 2> 2315967 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: = null [junit4] 2> 2315967 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2= 016-12-04T10:45:01.616Z [junit4] 2> 2315975 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome = (not found in ZooKeeper) [junit4] 2> 2315976 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from= C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\te= st\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\shard-1-001\so= lr.xml [junit4] 2> 2316000 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTT= P client with params: socketTimeout=3D340000&connTimeout=3D45000&retry=3Dtr= ue [junit4] 2> 2316001 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.ZkContainer Zookeeper client=3D127.0.0.1:57611/sol= r [junit4] 2> 2316019 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57651_jm_pnl%2Fb ] o.a.s.c.c.ZkStateReader Update= d live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 2316027 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57651_jm_pnl%2Fb ] o.a.s.c.ZkController Register = node as live in ZooKeeper:/live_nodes/127.0.0.1:57651_jm_pnl%2Fb [junit4] 2> 2316029 INFO (zkCallback-2278-thread-1-processing-n:127.0= .0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb ] o.a.s.c.c.ZkState= Reader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 2316031 INFO (zkCallback-2273-thread-1) [ ] o.a.s.c.c.= ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 2316031 INFO (zkCallback-2269-thread-2-processing-n:127.0= .0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.s.c.c.ZkState= Reader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 2316174 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57651_jm_pnl%2Fb ] o.a.s.c.CorePropertiesLocator = Found 1 core definitions underneath C:\Users\jenkins\workspace\Lucene-Solr-= 6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.HttpPartitionTest_= A6700AA91C60A879-001\shard-1-001\cores [junit4] 2> 2316174 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57651_jm_pnl%2Fb ] o.a.s.c.CorePropertiesLocator = Cores are: [collection1] [junit4] 2> 2316181 INFO (OverseerStateUpdate-97048874075815940-127.0= .0.1:57621_jm_pnl%2Fb-n_0000000000) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.= s.c.o.ReplicaMutator Assigning new node to shard shard=3Dshard2 [junit4] 2> 2317209 WARN (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.c.Config Beginning with Solr 5.5, is dep= recated, use instead. [junit4] 2> 2317210 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0 [junit4] 2> 2317230 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=3Dtest [junit4] 2> 2317359 WARN (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.s.IndexSchema [collection1] default search field in sc= hema is text. WARNING: Deprecated, please use 'df' on request instead. [junit4] 2> 2317361 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid fie= ld id [junit4] 2> 2317382 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using = configuration from collection collection1 [junit4] 2> 2317382 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Openin= g new SolrCore at [C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\= build\solr-core\test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-= 001\shard-1-001\cores\collection1], dataDir=3D[C:\Users\jenkins\workspace\L= ucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.HttpPar= titionTest_A6700AA91C60A879-001\shard-1-001\cores\collection1\data\] [junit4] 2> 2317382 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node1 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring i= s enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBe= anServer@8ada15b [junit4] 2> 2317383 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePol= icy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByte= SizeMergePolicy: minMergeSize=3D1677721, mergeFactor=3D39, maxMergeSize=3D2= 147483648, maxMergeSizeForForcedMerge=3D9223372036854775807, calibrateSizeB= yDeletes=3Dfalse, maxMergeDocs=3D2147483647, maxCFSSegmentSizeMB=3D8.796093= 022207999E12, noCFSRatio=3D1.0] [junit4] 2> 2317389 WARN (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node1 x:collection1] o.a.s.c.RequestHandlers INVALID paramSet= a in requestHandler {type =3D requestHandler,name =3D /dump,class =3D Dump= RequestHandler,args =3D {defaults=3D{a=3DA,b=3DB}}} [junit4] 2> 2317405 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node1 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog im= plementation: org.apache.solr.update.UpdateLog [junit4] 2> 2317405 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node1 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog= : dataDir=3D defaultSyncLevel=3DFLUSH numRecordsToKeep=3D100 maxNumLogsToKe= ep=3D10 numVersionBuckets=3D65536 [junit4] 2> 2317406 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node1 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: d= isabled [junit4] 2> 2317407 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node1 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: d= isabled [junit4] 2> 2317407 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePol= icy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergeP= olicy: minMergeSize=3D1000, mergeFactor=3D12, maxMergeSize=3D92233720368547= 75807, maxMergeSizeForForcedMerge=3D9223372036854775807, calibrateSizeByDel= etes=3Dtrue, maxMergeDocs=3D2147483647, maxCFSSegmentSizeMB=3D8.79609302220= 7999E12, noCFSRatio=3D0.5478978904233723] [junit4] 2> 2317408 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node1 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searc= her@6093944b[collection1] main] [junit4] 2> 2317409 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Configure= d ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 2317410 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Loaded nu= ll at path _rest_managed.json using ZooKeeperStorageIO:path=3D/configs/conf= 1 [junit4] 2> 2317410 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node1 x:collection1] o.a.s.h.ReplicationHandler Commits will = be reserved for 10000 [junit4] 2> 2317411 INFO (searcherExecutor-6496-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e1) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:shard2 r:core_node1 x:col= lection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@6= 093944b[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReade= r())} [junit4] 2> 2317412 INFO (coreLoadExecutor-6495-thread-1-processing-n= :127.0.0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node1 x:collection1] o.a.s.u.UpdateLog Could not find max ver= sion in index or recent updates, using new clock 1552781990230491136 [junit4] 2> 2317421 INFO (coreZkRegister-6490-thread-1-processing-n:1= 27.0.0.1:57651_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_node1= ) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:shard2 r:core_node1 x:colle= ction1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continu= e. [junit4] 2> 2317421 INFO (coreZkRegister-6490-thread-1-processing-n:1= 27.0.0.1:57651_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_node1= ) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:shard2 r:core_node1 x:colle= ction1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try an= d sync [junit4] 2> 2317421 INFO (coreZkRegister-6490-thread-1-processing-n:1= 27.0.0.1:57651_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_node1= ) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:shard2 r:core_node1 x:colle= ction1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:57651/jm_pnl= /b/collection1/ [junit4] 2> 2317421 INFO (coreZkRegister-6490-thread-1-processing-n:1= 27.0.0.1:57651_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_node1= ) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:shard2 r:core_node1 x:colle= ction1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 2317421 INFO (coreZkRegister-6490-thread-1-processing-n:1= 27.0.0.1:57651_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_node1= ) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:shard2 r:core_node1 x:colle= ction1] o.a.s.c.SyncStrategy http://127.0.0.1:57651/jm_pnl/b/collection1/ h= as no replicas [junit4] 2> 2317427 INFO (coreZkRegister-6490-thread-1-processing-n:1= 27.0.0.1:57651_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_node1= ) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:shard2 r:core_node1 x:colle= ction1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.= 0.0.1:57651/jm_pnl/b/collection1/ shard2 [junit4] 2> 2317598 INFO (coreZkRegister-6490-thread-1-processing-n:1= 27.0.0.1:57651_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_node1= ) [n:127.0.0.1:57651_jm_pnl%2Fb c:collection1 s:shard2 r:core_node1 x:colle= ction1] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 2318305 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to C:\Us= ers\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\= temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\shard-2-001\cores\co= llection1 [junit4] 2> 2318308 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 2 in di= rectory C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-= core\test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\shard-2= -001 [junit4] 2> 2318308 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 2318309 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHan= dler@1bd55b20{/jm_pnl/b,null,AVAILABLE} [junit4] 2> 2318311 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@6725b22c= {HTTP/1.1,[http/1.1]}{127.0.0.1:57680} [junit4] 2> 2318312 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.Server Started @2323126ms [junit4] 2> 2318312 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.d= ir=3DC:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-cor= e\test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\tempDir-00= 1/jetty2, solrconfig=3Dsolrconfig.xml, hostContext=3D/jm_pnl/b, hostPort=3D= 57679, coreRootDirectory=3DC:\Users\jenkins\workspace\Lucene-Solr-6.x-Windo= ws\solr\build\solr-core\test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91= C60A879-001\shard-2-001\cores} [junit4] 2> 2318312 ERROR (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.d= ir. Logging may be missing or incomplete. [junit4] 2> 2318312 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Ap= ache Solr? version 6.4.0 [junit4] 2> 2318313 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in c= loud mode on port null [junit4] 2> 2318313 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: = null [junit4] 2> 2318313 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2= 016-12-04T10:45:03.962Z [junit4] 2> 2318319 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome = (not found in ZooKeeper) [junit4] 2> 2318319 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from= C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\te= st\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\shard-2-001\so= lr.xml [junit4] 2> 2318335 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTT= P client with params: socketTimeout=3D340000&connTimeout=3D45000&retry=3Dtr= ue [junit4] 2> 2318336 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.ZkContainer Zookeeper client=3D127.0.0.1:57611/sol= r [junit4] 2> 2318350 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57679_jm_pnl%2Fb ] o.a.s.c.c.ZkStateReader Update= d live nodes from ZooKeeper... (0) -> (2) [junit4] 2> 2318355 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57679_jm_pnl%2Fb ] o.a.s.c.ZkController Register = node as live in ZooKeeper:/live_nodes/127.0.0.1:57679_jm_pnl%2Fb [junit4] 2> 2318360 INFO (zkCallback-2269-thread-3-processing-n:127.0= .0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.s.c.c.ZkState= Reader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 2318360 INFO (zkCallback-2273-thread-1) [ ] o.a.s.c.c.= ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 2318363 INFO (zkCallback-2284-thread-1-processing-n:127.0= .0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb ] o.a.s.c.c.ZkState= Reader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 2318363 INFO (zkCallback-2278-thread-1-processing-n:127.0= .0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb ] o.a.s.c.c.ZkState= Reader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 2318399 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57679_jm_pnl%2Fb ] o.a.s.c.CorePropertiesLocator = Found 1 core definitions underneath C:\Users\jenkins\workspace\Lucene-Solr-= 6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.HttpPartitionTest_= A6700AA91C60A879-001\shard-2-001\cores [junit4] 2> 2318400 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57679_jm_pnl%2Fb ] o.a.s.c.CorePropertiesLocator = Cores are: [collection1] [junit4] 2> 2318401 INFO (OverseerStateUpdate-97048874075815940-127.0= .0.1:57621_jm_pnl%2Fb-n_0000000000) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.= s.c.o.ReplicaMutator Assigning new node to shard shard=3Dshard1 [junit4] 2> 2319422 WARN (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.c.Config Beginning with Solr 5.5, is dep= recated, use instead. [junit4] 2> 2319423 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0 [junit4] 2> 2319446 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=3Dtest [junit4] 2> 2319625 WARN (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.s.IndexSchema [collection1] default search field in sc= hema is text. WARNING: Deprecated, please use 'df' on request instead. [junit4] 2> 2319629 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid fie= ld id [junit4] 2> 2319656 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using = configuration from collection collection1 [junit4] 2> 2319656 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:= shard1 r:core_node2 x:collection1] o.a.s.c.SolrCore [[collection1] ] Openin= g new SolrCore at [C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\= build\solr-core\test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-= 001\shard-2-001\cores\collection1], dataDir=3D[C:\Users\jenkins\workspace\L= ucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.HttpPar= titionTest_A6700AA91C60A879-001\shard-2-001\cores\collection1\data\] [junit4] 2> 2319656 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:= shard1 r:core_node2 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring i= s enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBe= anServer@8ada15b [junit4] 2> 2319658 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:= shard1 r:core_node2 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePol= icy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByte= SizeMergePolicy: minMergeSize=3D1677721, mergeFactor=3D39, maxMergeSize=3D2= 147483648, maxMergeSizeForForcedMerge=3D9223372036854775807, calibrateSizeB= yDeletes=3Dfalse, maxMergeDocs=3D2147483647, maxCFSSegmentSizeMB=3D8.796093= 022207999E12, noCFSRatio=3D1.0] [junit4] 2> 2319664 WARN (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:= shard1 r:core_node2 x:collection1] o.a.s.c.RequestHandlers INVALID paramSet= a in requestHandler {type =3D requestHandler,name =3D /dump,class =3D Dump= RequestHandler,args =3D {defaults=3D{a=3DA,b=3DB}}} [junit4] 2> 2319690 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:= shard1 r:core_node2 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog im= plementation: org.apache.solr.update.UpdateLog [junit4] 2> 2319690 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:= shard1 r:core_node2 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog= : dataDir=3D defaultSyncLevel=3DFLUSH numRecordsToKeep=3D100 maxNumLogsToKe= ep=3D10 numVersionBuckets=3D65536 [junit4] 2> 2319693 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:= shard1 r:core_node2 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: d= isabled [junit4] 2> 2319693 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:= shard1 r:core_node2 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: d= isabled [junit4] 2> 2319694 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:= shard1 r:core_node2 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePol= icy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergeP= olicy: minMergeSize=3D1000, mergeFactor=3D12, maxMergeSize=3D92233720368547= 75807, maxMergeSizeForForcedMerge=3D9223372036854775807, calibrateSizeByDel= etes=3Dtrue, maxMergeDocs=3D2147483647, maxCFSSegmentSizeMB=3D8.79609302220= 7999E12, noCFSRatio=3D0.5478978904233723] [junit4] 2> 2319695 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:= shard1 r:core_node2 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searc= her@e6389e[collection1] main] [junit4] 2> 2319696 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:= shard1 r:core_node2 x:collection1] o.a.s.r.ManagedResourceStorage Configure= d ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 2319696 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:= shard1 r:core_node2 x:collection1] o.a.s.r.ManagedResourceStorage Loaded nu= ll at path _rest_managed.json using ZooKeeperStorageIO:path=3D/configs/conf= 1 [junit4] 2> 2319696 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:= shard1 r:core_node2 x:collection1] o.a.s.h.ReplicationHandler Commits will = be reserved for 10000 [junit4] 2> 2319698 INFO (searcherExecutor-6507-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb x:collection1 s:shard1 c:collection1 r:core_nod= e2) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:shard1 r:core_node2 x:col= lection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@e= 6389e[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(= ))} [junit4] 2> 2319698 INFO (coreLoadExecutor-6506-thread-1-processing-n= :127.0.0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:= shard1 r:core_node2 x:collection1] o.a.s.u.UpdateLog Could not find max ver= sion in index or recent updates, using new clock 1552781992627535872 [junit4] 2> 2319711 INFO (coreZkRegister-6501-thread-1-processing-n:1= 27.0.0.1:57679_jm_pnl%2Fb x:collection1 s:shard1 c:collection1 r:core_node2= ) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:shard1 r:core_node2 x:colle= ction1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continu= e. [junit4] 2> 2319711 INFO (coreZkRegister-6501-thread-1-processing-n:1= 27.0.0.1:57679_jm_pnl%2Fb x:collection1 s:shard1 c:collection1 r:core_node2= ) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:shard1 r:core_node2 x:colle= ction1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try an= d sync [junit4] 2> 2319711 INFO (coreZkRegister-6501-thread-1-processing-n:1= 27.0.0.1:57679_jm_pnl%2Fb x:collection1 s:shard1 c:collection1 r:core_node2= ) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:shard1 r:core_node2 x:colle= ction1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:57679/jm_pnl= /b/collection1/ [junit4] 2> 2319711 INFO (coreZkRegister-6501-thread-1-processing-n:1= 27.0.0.1:57679_jm_pnl%2Fb x:collection1 s:shard1 c:collection1 r:core_node2= ) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:shard1 r:core_node2 x:colle= ction1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 2319711 INFO (coreZkRegister-6501-thread-1-processing-n:1= 27.0.0.1:57679_jm_pnl%2Fb x:collection1 s:shard1 c:collection1 r:core_node2= ) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:shard1 r:core_node2 x:colle= ction1] o.a.s.c.SyncStrategy http://127.0.0.1:57679/jm_pnl/b/collection1/ h= as no replicas [junit4] 2> 2319722 INFO (coreZkRegister-6501-thread-1-processing-n:1= 27.0.0.1:57679_jm_pnl%2Fb x:collection1 s:shard1 c:collection1 r:core_node2= ) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:shard1 r:core_node2 x:colle= ction1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.= 0.0.1:57679/jm_pnl/b/collection1/ shard1 [junit4] 2> 2319875 INFO (coreZkRegister-6501-thread-1-processing-n:1= 27.0.0.1:57679_jm_pnl%2Fb x:collection1 s:shard1 c:collection1 r:core_node2= ) [n:127.0.0.1:57679_jm_pnl%2Fb c:collection1 s:shard1 r:core_node2 x:colle= ction1] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 2320580 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to C:\Us= ers\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\= temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\shard-3-001\cores\co= llection1 [junit4] 2> 2320583 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 3 in di= rectory C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-= core\test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\shard-3= -001 [junit4] 2> 2320584 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028 [junit4] 2> 2320585 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHan= dler@3eea92ce{/jm_pnl/b,null,AVAILABLE} [junit4] 2> 2320587 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@5484d989= {HTTP/1.1,[http/1.1]}{127.0.0.1:57708} [junit4] 2> 2320587 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.e.j.s.Server Started @2325400ms [junit4] 2> 2320587 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.d= ir=3DC:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-cor= e\test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\tempDir-00= 1/jetty3, solrconfig=3Dsolrconfig.xml, hostContext=3D/jm_pnl/b, hostPort=3D= 57707, coreRootDirectory=3DC:\Users\jenkins\workspace\Lucene-Solr-6.x-Windo= ws\solr\build\solr-core\test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91= C60A879-001\shard-3-001\cores} [junit4] 2> 2320587 ERROR (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.d= ir. Logging may be missing or incomplete. [junit4] 2> 2320588 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Ap= ache Solr? version 6.4.0 [junit4] 2> 2320588 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in c= loud mode on port null [junit4] 2> 2320588 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: = null [junit4] 2> 2320588 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2= 016-12-04T10:45:06.237Z [junit4] 2> 2320596 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ = ] o.a.z.s.NIOServerCnxn caught end of stream exception [junit4] 2> EndOfStreamException: Unable to read additional data from = client sessionid 0x158c96fd124000c, likely client has closed socket [junit4] 2> =09at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOSe= rverCnxn.java:228) [junit4] 2> =09at org.apache.zookeeper.server.NIOServerCnxnFactory.run= (NIOServerCnxnFactory.java:208) [junit4] 2> =09at java.lang.Thread.run(Thread.java:745) [junit4] 2> 2320597 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome = (not found in ZooKeeper) [junit4] 2> 2320597 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from= C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\te= st\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\shard-3-001\so= lr.xml [junit4] 2> 2320614 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTT= P client with params: socketTimeout=3D340000&connTimeout=3D45000&retry=3Dtr= ue [junit4] 2> 2320615 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.ZkContainer Zookeeper client=3D127.0.0.1:57611/sol= r [junit4] 2> 2320634 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57707_jm_pnl%2Fb ] o.a.s.c.c.ZkStateReader Update= d live nodes from ZooKeeper... (0) -> (3) [junit4] 2> 2320642 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57707_jm_pnl%2Fb ] o.a.s.c.ZkController Register = node as live in ZooKeeper:/live_nodes/127.0.0.1:57707_jm_pnl%2Fb [junit4] 2> 2320646 INFO (zkCallback-2273-thread-1) [ ] o.a.s.c.c.= ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 2320646 INFO (zkCallback-2284-thread-1-processing-n:127.0= .0.1:57679_jm_pnl%2Fb) [n:127.0.0.1:57679_jm_pnl%2Fb ] o.a.s.c.c.ZkState= Reader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 2320646 INFO (zkCallback-2278-thread-1-processing-n:127.0= .0.1:57651_jm_pnl%2Fb) [n:127.0.0.1:57651_jm_pnl%2Fb ] o.a.s.c.c.ZkState= Reader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 2320646 INFO (zkCallback-2269-thread-1-processing-n:127.0= .0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.s.c.c.ZkState= Reader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 2320647 INFO (zkCallback-2290-thread-1-processing-n:127.0= .0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb ] o.a.s.c.c.ZkState= Reader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 2320744 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57707_jm_pnl%2Fb ] o.a.s.c.CorePropertiesLocator = Found 1 core definitions underneath C:\Users\jenkins\workspace\Lucene-Solr-= 6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.HttpPartitionTest_= A6700AA91C60A879-001\shard-3-001\cores [junit4] 2> 2320744 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [n:127.0.0.1:57707_jm_pnl%2Fb ] o.a.s.c.CorePropertiesLocator = Cores are: [collection1] [junit4] 2> 2320748 INFO (OverseerStateUpdate-97048874075815940-127.0= .0.1:57621_jm_pnl%2Fb-n_0000000000) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.= s.c.o.ReplicaMutator Assigning new node to shard shard=3Dshard2 [junit4] 2> 2321771 WARN (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.c.Config Beginning with Solr 5.5, is dep= recated, use instead. [junit4] 2> 2321773 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0 [junit4] 2> 2321798 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=3Dtest [junit4] 2> 2321963 WARN (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.s.IndexSchema [collection1] default search field in sc= hema is text. WARNING: Deprecated, please use 'df' on request instead. [junit4] 2> 2321966 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid fie= ld id [junit4] 2> 2322008 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 = x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using = configuration from collection collection1 [junit4] 2> 2322009 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node3 x:collection1] o.a.s.c.SolrCore [[collection1] ] Openin= g new SolrCore at [C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\= build\solr-core\test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-= 001\shard-3-001\cores\collection1], dataDir=3D[C:\Users\jenkins\workspace\L= ucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.HttpPar= titionTest_A6700AA91C60A879-001\shard-3-001\cores\collection1\data\] [junit4] 2> 2322009 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node3 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring i= s enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBe= anServer@8ada15b [junit4] 2> 2322010 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node3 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePol= icy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByte= SizeMergePolicy: minMergeSize=3D1677721, mergeFactor=3D39, maxMergeSize=3D2= 147483648, maxMergeSizeForForcedMerge=3D9223372036854775807, calibrateSizeB= yDeletes=3Dfalse, maxMergeDocs=3D2147483647, maxCFSSegmentSizeMB=3D8.796093= 022207999E12, noCFSRatio=3D1.0] [junit4] 2> 2322016 WARN (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node3 x:collection1] o.a.s.c.RequestHandlers INVALID paramSet= a in requestHandler {type =3D requestHandler,name =3D /dump,class =3D Dump= RequestHandler,args =3D {defaults=3D{a=3DA,b=3DB}}} [junit4] 2> 2322041 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node3 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog im= plementation: org.apache.solr.update.UpdateLog [junit4] 2> 2322041 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node3 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog= : dataDir=3D defaultSyncLevel=3DFLUSH numRecordsToKeep=3D100 maxNumLogsToKe= ep=3D10 numVersionBuckets=3D65536 [junit4] 2> 2322043 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node3 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: d= isabled [junit4] 2> 2322043 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node3 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: d= isabled [junit4] 2> 2322044 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node3 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePol= icy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergeP= olicy: minMergeSize=3D1000, mergeFactor=3D12, maxMergeSize=3D92233720368547= 75807, maxMergeSizeForForcedMerge=3D9223372036854775807, calibrateSizeByDel= etes=3Dtrue, maxMergeDocs=3D2147483647, maxCFSSegmentSizeMB=3D8.79609302220= 7999E12, noCFSRatio=3D0.5478978904233723] [junit4] 2> 2322045 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node3 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searc= her@5495097[collection1] main] [junit4] 2> 2322047 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node3 x:collection1] o.a.s.r.ManagedResourceStorage Configure= d ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 2322048 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node3 x:collection1] o.a.s.r.ManagedResourceStorage Loaded nu= ll at path _rest_managed.json using ZooKeeperStorageIO:path=3D/configs/conf= 1 [junit4] 2> 2322048 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node3 x:collection1] o.a.s.h.ReplicationHandler Commits will = be reserved for 10000 [junit4] 2> 2322049 INFO (searcherExecutor-6518-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@5= 495097[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader= ())} [junit4] 2> 2322049 INFO (coreLoadExecutor-6517-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:= shard2 r:core_node3 x:collection1] o.a.s.u.UpdateLog Could not find max ver= sion in index or recent updates, using new clock 1552781995092738048 [junit4] 2> 2322056 INFO (coreZkRegister-6512-thread-1-processing-n:1= 27.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_node3= ) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:colle= ction1] o.a.s.c.ZkController Core needs to recover:collection1 [junit4] 2> 2322057 INFO (updateExecutor-2287-thread-1-processing-n:1= 27.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_node3= ) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:colle= ction1] o.a.s.u.DefaultSolrCoreState Running recovery [junit4] 2> 2322058 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.c.RecoveryStrategy Starting recovery process. recoveringAft= erStartup=3Dtrue [junit4] 2> 2322060 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.c.RecoveryStrategy ###### startupVersions=3D[[]] [junit4] 2> 2322060 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.c.RecoveryStrategy Begin buffering updates. core=3D[collect= ion1] [junit4] 2> 2322060 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state= =3DACTIVE, tlog=3Dnull} [junit4] 2> 2322060 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.c.RecoveryStrategy Publishing state of core [collection1] a= s recovering, leader is [http://127.0.0.1:57651/jm_pnl/b/collection1/] and = I am [http://127.0.0.1:57707/jm_pnl/b/collection1/] [junit4] 2> 2322063 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http:/= /127.0.0.1:57651/jm_pnl/b]; [WaitForState: action=3DPREPRECOVERY&core=3Dcol= lection1&nodeName=3D127.0.0.1:57707_jm_pnl%252Fb&coreNodeName=3Dcore_node3&= state=3Drecovering&checkLive=3Dtrue&onlyIfLeader=3Dtrue&onlyIfLeaderActive= =3Dtrue] [junit4] 2> 2322066 INFO (SocketProxy-Acceptor-57651) [ ] o.a.s.c.= SocketProxy accepted Socket[addr=3D/127.0.0.1,port=3D57733,localport=3D5765= 1], receiveBufferSize:65536 [junit4] 2> 2322067 INFO (SocketProxy-Acceptor-57651) [ ] o.a.s.c.= SocketProxy proxy connection Socket[addr=3D/127.0.0.1,port=3D57652,localpor= t=3D57734], receiveBufferSize=3D65536 [junit4] 2> 2322071 INFO (qtp495002130-14039) [n:127.0.0.1:57651_jm_p= nl%2Fb ] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_n= ode3, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderA= ctive: true [junit4] 2> 2322071 INFO (qtp495002130-14039) [n:127.0.0.1:57651_jm_p= nl%2Fb ] o.a.s.h.a.PrepRecoveryOp Will wait a max of 183 seconds to see = collection1 (shard2 of collection1) have state: recovering [junit4] 2> 2322071 INFO (qtp495002130-14039) [n:127.0.0.1:57651_jm_p= nl%2Fb ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collectio= n=3Dcollection1, shard=3Dshard2, thisCore=3Dcollection1, leaderDoesNotNeedR= ecovery=3Dfalse, isLeader? true, live=3Dtrue, checkLive=3Dtrue, currentStat= e=3Ddown, localState=3Dactive, nodeName=3D127.0.0.1:57707_jm_pnl%2Fb, coreN= odeName=3Dcore_node3, onlyIfActiveCheckResult=3Dfalse, nodeProps: core_node= 3:{"core":"collection1","base_url":"http://127.0.0.1:57707/jm_pnl/b","node_= name":"127.0.0.1:57707_jm_pnl%2Fb","state":"down"} [junit4] 2> 2322289 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.SolrTestCaseJ4 ###Starting test [junit4] 2> 2322289 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractFullDistribZkTestBase Wait for recoveries = to finish - wait 30000 for each attempt [junit4] 2> 2322289 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractDistribZkTestBase Wait for recoveries to f= inish - collection: collection1 failOnTimeout:true timeout (sec):30000 [junit4] 2> 2323071 INFO (qtp495002130-14039) [n:127.0.0.1:57651_jm_p= nl%2Fb ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collectio= n=3Dcollection1, shard=3Dshard2, thisCore=3Dcollection1, leaderDoesNotNeedR= ecovery=3Dfalse, isLeader? true, live=3Dtrue, checkLive=3Dtrue, currentStat= e=3Drecovering, localState=3Dactive, nodeName=3D127.0.0.1:57707_jm_pnl%2Fb,= coreNodeName=3Dcore_node3, onlyIfActiveCheckResult=3Dfalse, nodeProps: cor= e_node3:{"core":"collection1","base_url":"http://127.0.0.1:57707/jm_pnl/b",= "node_name":"127.0.0.1:57707_jm_pnl%2Fb","state":"recovering"} [junit4] 2> 2323071 INFO (qtp495002130-14039) [n:127.0.0.1:57651_jm_p= nl%2Fb ] o.a.s.h.a.PrepRecoveryOp Waited coreNodeName: core_node3, state= : recovering, checkLive: true, onlyIfLeader: true for: 1 seconds. [junit4] 2> 2323071 INFO (qtp495002130-14039) [n:127.0.0.1:57651_jm_p= nl%2Fb ] o.a.s.s.HttpSolrCall [admin] webapp=3Dnull path=3D/admin/cores = params=3D{nodeName=3D127.0.0.1:57707_jm_pnl%252Fb&onlyIfLeaderActive=3Dtrue= &core=3Dcollection1&coreNodeName=3Dcore_node3&action=3DPREPRECOVERY&checkLi= ve=3Dtrue&state=3Drecovering&onlyIfLeader=3Dtrue&wt=3Djavabin&version=3D2} = status=3D0 QTime=3D1000 [junit4] 2> 2330073 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.c.RecoveryStrategy Attempting to PeerSync from [http://127.= 0.0.1:57651/jm_pnl/b/collection1/] - recoveringAfterStartup=3D[true] [junit4] 2> 2330073 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.u.PeerSync PeerSync: core=3Dcollection1 url=3Dhttp://127.0.= 0.1:57707/jm_pnl/b START replicas=3D[http://127.0.0.1:57651/jm_pnl/b/collec= tion1/] nUpdates=3D100 [junit4] 2> 2330075 INFO (SocketProxy-Acceptor-57651) [ ] o.a.s.c.= SocketProxy accepted Socket[addr=3D/127.0.0.1,port=3D57760,localport=3D5765= 1], receiveBufferSize:65536 [junit4] 2> 2330076 INFO (SocketProxy-Acceptor-57651) [ ] o.a.s.c.= SocketProxy proxy connection Socket[addr=3D/127.0.0.1,port=3D57652,localpor= t=3D57761], receiveBufferSize=3D65536 [junit4] 2> 2330077 INFO (qtp495002130-14031) [n:127.0.0.1:57651_jm_p= nl%2Fb c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.IndexFing= erprint IndexFingerprint millis:0.0 result:{maxVersionSpecified=3D922337203= 6854775807, maxVersionEncountered=3D0, maxInHash=3D0, versionsHash=3D0, num= Versions=3D0, numDocs=3D0, maxDoc=3D0} [junit4] 2> 2330077 INFO (qtp495002130-14031) [n:127.0.0.1:57651_jm_p= nl%2Fb c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.S.Request= [collection1] webapp=3D/jm_pnl/b path=3D/get params=3D{distrib=3Dfalse&qt= =3D/get&getFingerprint=3D9223372036854775807&wt=3Djavabin&version=3D2} stat= us=3D0 QTime=3D0 [junit4] 2> 2330079 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.u.IndexFingerprint IndexFingerprint millis:1.0 result:{maxV= ersionSpecified=3D9223372036854775807, maxVersionEncountered=3D0, maxInHash= =3D0, versionsHash=3D0, numVersions=3D0, numDocs=3D0, maxDoc=3D0} [junit4] 2> 2330079 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.u.PeerSync We are already in sync. No need to do a PeerSync= =20 [junit4] 2> 2330079 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=3Dfalse,openS= earcher=3Dtrue,waitSearcher=3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfals= e,prepareCommit=3Dfalse} [junit4] 2> 2330079 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.= commit. [junit4] 2> 2330080 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 2330080 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.c.RecoveryStrategy PeerSync stage of recovery was successfu= l. [junit4] 2> 2330080 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.c.RecoveryStrategy Replaying updates buffered during PeerSy= nc. [junit4] 2> 2330080 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.c.RecoveryStrategy No replay needed. [junit4] 2> 2330081 INFO (recoveryExecutor-2288-thread-1-processing-n= :127.0.0.1:57707_jm_pnl%2Fb x:collection1 s:shard2 c:collection1 r:core_nod= e3) [n:127.0.0.1:57707_jm_pnl%2Fb c:collection1 s:shard2 r:core_node3 x:col= lection1] o.a.s.c.RecoveryStrategy Registering as Active after recovery. [junit4] 2> 2330326 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractDistribZkTestBase Recoveries finished - co= llection: collection1 [junit4] 2> 2330327 INFO (SocketProxy-Acceptor-57621) [ ] o.a.s.c.= SocketProxy accepted Socket[addr=3D/127.0.0.1,port=3D57762,localport=3D5762= 1], receiveBufferSize:65536 [junit4] 2> 2330328 INFO (SocketProxy-Acceptor-57621) [ ] o.a.s.c.= SocketProxy proxy connection Socket[addr=3D/127.0.0.1,port=3D57622,localpor= t=3D57763], receiveBufferSize=3D65536 [junit4] 2> 2330330 INFO (qtp1684334374-13986) [n:127.0.0.1:57621_jm_= pnl%2Fb c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.D= irectUpdateHandler2 start commit{,optimize=3Dfalse,openSearcher=3Dtrue,wait= Searcher=3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Df= alse} [junit4] 2> 2330330 INFO (qtp1684334374-13986) [n:127.0.0.1:57621_jm_= pnl%2Fb c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.D= irectUpdateHandler2 No uncommitted changes. Skipping IW.commit. [junit4] 2> 2330332 INFO (qtp1684334374-13986) [n:127.0.0.1:57621_jm_= pnl%2Fb c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.D= irectUpdateHandler2 end_commit_flush [junit4] 2> 2330332 INFO (qtp1684334374-13986) [n:127.0.0.1:57621_jm_= pnl%2Fb c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p= .LogUpdateProcessorFactory [collection1] webapp=3D/jm_pnl/b path=3D/update= params=3D{waitSearcher=3Dtrue&commit=3Dtrue&softCommit=3Dfalse&wt=3Djavabi= n&version=3D2}{commit=3D} 0 3 [junit4] 2> 2330333 INFO (SocketProxy-Acceptor-57651) [ ] o.a.s.c.= SocketProxy accepted Socket[addr=3D/127.0.0.1,port=3D57764,localport=3D5765= 1], receiveBufferSize:65536 [junit4] 2> 2330334 INFO (SocketProxy-Acceptor-57651) [ ] o.a.s.c.= SocketProxy proxy connection Socket[addr=3D/127.0.0.1,port=3D57652,localpor= t=3D57765], receiveBufferSize=3D65536 [junit4] 2> 2330339 INFO (SocketProxy-Acceptor-57707) [ ] o.a.s.c.= SocketProxy accepted Socket[addr=3D/127.0.0.1,port=3D57767,localport=3D5770= 7], receiveBufferSize:65536 [junit4] 2> 2330339 INFO (SocketProxy-Acceptor-57679) [ ] o.a.s.c.= SocketProxy accepted Socket[addr=3D/127.0.0.1,port=3D57766,localport=3D5767= 9], receiveBufferSize:65536 [junit4] 2> 2330339 INFO (SocketProxy-Acceptor-57651) [ ] o.a.s.c.= SocketProxy accepted Socket[addr=3D/127.0.0.1,port=3D57768,localport=3D5765= 1], receiveBufferSize:65536 [junit4] 2> 2330340 INFO (SocketProxy-Acceptor-57707) [ ] o.a.s.c.= SocketProxy proxy connection Socket[addr=3D/127.0.0.1,port=3D57708,localpor= t=3D57769], receiveBufferSize=3D65536 [junit4] 2> 2330340 INFO (SocketProxy-Acceptor-57679) [ ] o.a.s.c.= SocketProxy proxy connection Socket[addr=3D/127.0.0.1,port=3D57680,localpor= t=3D57770], receiveBufferSize=3D65536 [junit4] 2> 2330340 INFO (SocketProxy-Acceptor-57651) [ ] o.a.s.c.= SocketProxy proxy connection Socket[addr=3D/127.0.0.1,port=3D57652,localpor= t=3D57771], receiveBufferSize=3D65536 [junit4] 2> 2330348 INFO (qtp495002130-14028) [n:127.0.0.1:57651_jm_p= nl%2Fb c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.DirectUpd= ateHandler2 start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher= =3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4] 2> 2330348 INFO (qtp495002130-14028) [n:127.0.0.1:57651_jm_p= nl%2Fb c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.DirectUpd= ateHandler2 No uncommitted changes. Skipping IW.commit. [junit4] 2> 2330352 INFO (qtp541982504-14091) [n:127.0.0.1:57707_jm_p= nl%2Fb c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.DirectUpd= ateHandler2 start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher= =3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4] 2> 2330352 INFO (qtp495002130-14028) [n:127.0.0.1:57651_jm_p= nl%2Fb c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.DirectUpd= ateHandler2 end_commit_flush [junit4] 2> 2330352 INFO (qtp541982504-14091) [n:127.0.0.1:57707_jm_p= nl%2Fb c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.DirectUpd= ateHandler2 No uncommitted changes. Skipping IW.commit. [junit4] 2> 2330354 INFO (qtp541982504-14091) [n:127.0.0.1:57707_jm_p= nl%2Fb c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.DirectUpd= ateHandler2 end_commit_flush [junit4] 2> 2330354 INFO (qtp495002130-14028) [n:127.0.0.1:57651_jm_p= nl%2Fb c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.p.LogUpda= teProcessorFactory [collection1] webapp=3D/jm_pnl/b path=3D/update params= =3D{update.distrib=3DFROMLEADER&waitSearcher=3Dtrue&openSearcher=3Dtrue&com= mit=3Dtrue&softCommit=3Dfalse&distrib.from=3Dhttp://127.0.0.1:57651/jm_pnl/= b/collection1/&commit_end_point=3Dtrue&wt=3Djavabin&version=3D2&expungeDele= tes=3Dfalse}{commit=3D} 0 7 [junit4] 2> 2330354 INFO (qtp532029177-14059) [n:127.0.0.1:57679_jm_p= nl%2Fb c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.DirectUpd= ateHandler2 start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher= =3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4] 2> 2330355 INFO (qtp532029177-14059) [n:127.0.0.1:57679_jm_p= nl%2Fb c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.DirectUpd= ateHandler2 No uncommitted changes. Skipping IW.commit. [junit4] 2> 2330355 INFO (qtp541982504-14091) [n:127.0.0.1:57707_jm_p= nl%2Fb c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.p.LogUpda= teProcessorFactory [collection1] webapp=3D/jm_pnl/b path=3D/update params= =3D{update.distrib=3DFROMLEADER&waitSearcher=3Dtrue&openSearcher=3Dtrue&com= mit=3Dtrue&softCommit=3Dfalse&distrib.from=3Dhttp://127.0.0.1:57651/jm_pnl/= b/collection1/&commit_end_point=3Dtrue&wt=3Djavabin&version=3D2&expungeDele= tes=3Dfalse}{commit=3D} 0 7 [junit4] 2> 2330356 INFO (qtp532029177-14059) [n:127.0.0.1:57679_jm_p= nl%2Fb c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.DirectUpd= ateHandler2 end_commit_flush [junit4] 2> 2330357 INFO (qtp532029177-14059) [n:127.0.0.1:57679_jm_p= nl%2Fb c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.LogUpda= teProcessorFactory [collection1] webapp=3D/jm_pnl/b path=3D/update params= =3D{update.distrib=3DFROMLEADER&waitSearcher=3Dtrue&openSearcher=3Dtrue&com= mit=3Dtrue&softCommit=3Dfalse&distrib.from=3Dhttp://127.0.0.1:57651/jm_pnl/= b/collection1/&commit_end_point=3Dtrue&wt=3Djavabin&version=3D2&expungeDele= tes=3Dfalse}{commit=3D} 0 2 [junit4] 2> 2330357 INFO (qtp495002130-14041) [n:127.0.0.1:57651_jm_p= nl%2Fb c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.p.LogUpda= teProcessorFactory [collection1] webapp=3D/jm_pnl/b path=3D/update params= =3D{waitSearcher=3Dtrue&commit=3Dtrue&softCommit=3Dfalse&wt=3Djavabin&versi= on=3D2}{commit=3D} 0 20 [junit4] 2> 2330360 INFO (SocketProxy-Acceptor-57651) [ ] o.a.s.c.= SocketProxy accepted Socket[addr=3D/127.0.0.1,port=3D57772,localport=3D5765= 1], receiveBufferSize:65536 [junit4] 2> 2330360 INFO (SocketProxy-Acceptor-57651) [ ] o.a.s.c.= SocketProxy proxy connection Socket[addr=3D/127.0.0.1,port=3D57652,localpor= t=3D57773], receiveBufferSize=3D65536 [junit4] 2> 2330361 INFO (qtp495002130-14034) [n:127.0.0.1:57651_jm_p= nl%2Fb c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.S.Request= [collection1] webapp=3D/jm_pnl/b path=3D/select params=3D{q=3D*:*&distrib= =3Dfalse&tests=3DcheckShardConsistency&rows=3D0&wt=3Djavabin&version=3D2} h= its=3D0 status=3D0 QTime=3D0 [junit4] 2> 2330362 INFO (SocketProxy-Acceptor-57707) [ ] o.a.s.c.= SocketProxy accepted Socket[addr=3D/127.0.0.1,port=3D57774,localport=3D5770= 7], receiveBufferSize:65536 [junit4] 2> 2330362 INFO (SocketProxy-Acceptor-57707) [ ] o.a.s.c.= SocketProxy proxy connection Socket[addr=3D/127.0.0.1,port=3D57708,localpor= t=3D57775], receiveBufferSize=3D65536 [junit4] 2> 2330365 INFO (qtp541982504-14095) [n:127.0.0.1:57707_jm_p= nl%2Fb c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.S.Request= [collection1] webapp=3D/jm_pnl/b path=3D/select params=3D{q=3D*:*&distrib= =3Dfalse&tests=3DcheckShardConsistency&rows=3D0&wt=3Djavabin&version=3D2} h= its=3D0 status=3D0 QTime=3D0 [junit4] 2> 2330367 INFO (SocketProxy-Acceptor-57679) [ ] o.a.s.c.= SocketProxy accepted Socket[addr=3D/127.0.0.1,port=3D57776,localport=3D5767= 9], receiveBufferSize:65536 [junit4] 2> 2330367 INFO (SocketProxy-Acceptor-57679) [ ] o.a.s.c.= SocketProxy proxy connection Socket[addr=3D/127.0.0.1,port=3D57680,localpor= t=3D57777], receiveBufferSize=3D65536 [junit4] 2> 2330369 INFO (qtp532029177-14072) [n:127.0.0.1:57679_jm_p= nl%2Fb c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.S.Request= [collection1] webapp=3D/jm_pnl/b path=3D/select params=3D{q=3D*:*&distrib= =3Dfalse&tests=3DcheckShardConsistency&rows=3D0&wt=3Djavabin&version=3D2} h= its=3D0 status=3D0 QTime=3D0 [junit4] 2> 2332370 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.AbstractFullDistribZkTestBase Creating collection = with stateFormat=3D1: c8n_crud_1x2 [junit4] 2> 2332372 INFO (SocketProxy-Acceptor-57679) [ ] o.a.s.c.= SocketProxy accepted Socket[addr=3D/127.0.0.1,port=3D57790,localport=3D5767= 9], receiveBufferSize:65536 [junit4] 2> 2332372 INFO (SocketProxy-Acceptor-57679) [ ] o.a.s.c.= SocketProxy proxy connection Socket[addr=3D/127.0.0.1,port=3D57680,localpor= t=3D57791], receiveBufferSize=3D65536 [junit4] 2> 2332374 INFO (qtp532029177-14062) [n:127.0.0.1:57679_jm_p= nl%2Fb ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create = with params replicationFactor=3D2&maxShardsPerNode=3D1&name=3Dc8n_crud_1x2&= action=3DCREATE&numShards=3D1&stateFormat=3D1&wt=3Djavabin&version=3D2 and = sendToOCPQueue=3Dtrue [junit4] 2> 2332380 INFO (OverseerThreadFactory-6482-thread-1-process= ing-n:127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.s.= c.CreateCollectionCmd Create collection c8n_crud_1x2 [junit4] 2> 2332381 INFO (OverseerThreadFactory-6482-thread-1-process= ing-n:127.0.0.1:57621_jm_pnl%2Fb) [n:127.0.0.1:57621_jm_pnl%2Fb ] o.a.s.= c.CreateCollectionCmd Only one config set found in zk - using it:conf1 [junit4] 2> 2332489 INFO (SocketProxy-Acceptor-57621) [ ] o.a.s.c.= SocketProxy accepted Socket[addr=3D/127.0.0.1,port=3D57793,localport=3D5762= 1], receiveBufferSize:65536 [junit4] 2> 2332489 INFO (SocketProxy-Acceptor-57679) [ ] o.a.s.c.= SocketProxy accepted Socket[addr=3D/127.0.0.1,port=3D57792,localport=3D5767= 9], receiveBufferSize:65536 [junit4] 2> 2332490 INFO (SocketProxy-Acceptor-57679) [ ] o.a.s.c.= SocketProxy proxy connection Socket[addr=3D/127.0.0.1,port=3D57680,localpor= t=3D57795], receiveBufferSize=3D65536 [junit4] 2> 2332490 INFO (SocketProxy-Acceptor-57621) [ ] o.a.s.c.= SocketProxy proxy connection Socket[addr=3D/127.0.0.1,port=3D57622,localpor= t=3D57794], receiveBufferSize=3D65536 [junit4] 2> 2332491 INFO (qtp532029177-14064) [n:127.0.0.1:57679_jm_p= nl%2Fb ] o.a.s.h.a.CoreAdminOperation core create command qt=3D/admin/co= res&collection.configName=3Dconf1&newCollection=3Dtrue&name=3Dc8n_crud_1x2_= shard1_replica2&action=3DCREATE&numShards=3D1&collection=3Dc8n_crud_1x2&sha= rd=3Dshard1&wt=3Djavabin&version=3D2 [junit4] 2> 2332491 INFO (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb ] o.a.s.h.a.CoreAdminOperation core create command qt=3D/admin/c= ores&collection.configName=3Dconf1&newCollection=3Dtrue&name=3Dc8n_crud_1x2= _shard1_replica1&action=3DCREATE&numShards=3D1&collection=3Dc8n_crud_1x2&sh= ard=3Dshard1&wt=3Djavabin&version=3D2 [junit4] 2> 2333611 WARN (qtp532029177-14064) [n:127.0.0.1:57679_jm_p= nl%2Fb c:c8n_crud_1x2 s:shard1 x:c8n_crud_1x2_shard1_replica2] o.a.s.c.Con= fig Beginning with Solr 5.5, is deprecated, use instead. [junit4] 2> 2333612 INFO (qtp532029177-14064) [n:127.0.0.1:57679_jm_p= nl%2Fb c:c8n_crud_1x2 s:shard1 x:c8n_crud_1x2_shard1_replica2] o.a.s.c.Sol= rConfig Using Lucene MatchVersion: 6.4.0 [junit4] 2> 2333618 WARN (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 x:c8n_crud_1x2_shard1_replica1] o.a.s.c.Co= nfig Beginning with Solr 5.5, is deprecated, use instead. [junit4] 2> 2333618 INFO (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 x:c8n_crud_1x2_shard1_replica1] o.a.s.c.So= lrConfig Using Lucene MatchVersion: 6.4.0 [junit4] 2> 2333649 INFO (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 x:c8n_crud_1x2_shard1_replica1] o.a.s.s.In= dexSchema [c8n_crud_1x2_shard1_replica1] Schema name=3Dtest [junit4] 2> 2333810 WARN (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 x:c8n_crud_1x2_shard1_replica1] o.a.s.s.In= dexSchema [c8n_crud_1x2_shard1_replica1] default search field in schema is = text. WARNING: Deprecated, please use 'df' on request instead. [junit4] 2> 2333811 INFO (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 x:c8n_crud_1x2_shard1_replica1] o.a.s.s.In= dexSchema Loaded schema test/1.0 with uniqueid field id [junit4] 2> 2333813 INFO (qtp532029177-14064) [n:127.0.0.1:57679_jm_p= nl%2Fb c:c8n_crud_1x2 s:shard1 x:c8n_crud_1x2_shard1_replica2] o.a.s.s.Ind= exSchema [c8n_crud_1x2_shard1_replica2] Schema name=3Dtest [junit4] 2> 2333964 WARN (qtp532029177-14064) [n:127.0.0.1:57679_jm_p= nl%2Fb c:c8n_crud_1x2 s:shard1 x:c8n_crud_1x2_shard1_replica2] o.a.s.s.Ind= exSchema [c8n_crud_1x2_shard1_replica2] default search field in schema is t= ext. WARNING: Deprecated, please use 'df' on request instead. [junit4] 2> 2333966 INFO (qtp532029177-14064) [n:127.0.0.1:57679_jm_p= nl%2Fb c:c8n_crud_1x2 s:shard1 x:c8n_crud_1x2_shard1_replica2] o.a.s.s.Ind= exSchema Loaded schema test/1.0 with uniqueid field id [junit4] 2> 2333968 INFO (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 x:c8n_crud_1x2_shard1_replica1] o.a.s.c.Co= reContainer Creating SolrCore 'c8n_crud_1x2_shard1_replica1' using configur= ation from collection c8n_crud_1x2 [junit4] 2> 2333969 INFO (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 r:core_node2 x:c8n_crud_1x2_shard1_replica1= ] o.a.s.c.SolrCore [[c8n_crud_1x2_shard1_replica1] ] Opening new SolrCore a= t [C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\= test\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\control-001\= cores\c8n_crud_1x2_shard1_replica1], dataDir=3D[C:\Users\jenkins\workspace\= Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.HttpPa= rtitionTest_A6700AA91C60A879-001\control-001\cores\c8n_crud_1x2_shard1_repl= ica1\data\] [junit4] 2> 2333969 INFO (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 r:core_node2 x:c8n_crud_1x2_shard1_replica1= ] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to = JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@8ada15b [junit4] 2> 2333986 INFO (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 r:core_node2 x:c8n_crud_1x2_shard1_replica1= ] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.luc= ene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=3D1= 677721, mergeFactor=3D39, maxMergeSize=3D2147483648, maxMergeSizeForForcedM= erge=3D9223372036854775807, calibrateSizeByDeletes=3Dfalse, maxMergeDocs=3D= 2147483647, maxCFSSegmentSizeMB=3D8.796093022207999E12, noCFSRatio=3D1.0] [junit4] 2> 2333988 INFO (qtp532029177-14064) [n:127.0.0.1:57679_jm_p= nl%2Fb c:c8n_crud_1x2 s:shard1 x:c8n_crud_1x2_shard1_replica2] o.a.s.c.Cor= eContainer Creating SolrCore 'c8n_crud_1x2_shard1_replica2' using configura= tion from collection c8n_crud_1x2 [junit4] 2> 2333989 INFO (qtp532029177-14064) [n:127.0.0.1:57679_jm_p= nl%2Fb c:c8n_crud_1x2 s:shard1 r:core_node1 x:c8n_crud_1x2_shard1_replica2]= o.a.s.c.SolrCore [[c8n_crud_1x2_shard1_replica2] ] Opening new SolrCore at= [C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\t= est\J0\temp\solr.cloud.HttpPartitionTest_A6700AA91C60A879-001\shard-2-001\c= ores\c8n_crud_1x2_shard1_replica2], dataDir=3D[C:\Users\jenkins\workspace\L= ucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.HttpPar= titionTest_A6700AA91C60A879-001\shard-2-001\cores\c8n_crud_1x2_shard1_repli= ca2\data\] [junit4] 2> 2333989 INFO (qtp532029177-14064) [n:127.0.0.1:57679_jm_p= nl%2Fb c:c8n_crud_1x2 s:shard1 r:core_node1 x:c8n_crud_1x2_shard1_replica2]= o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to J= MX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@8ada15b [junit4] 2> 2334013 INFO (qtp532029177-14064) [n:127.0.0.1:57679_jm_p= nl%2Fb c:c8n_crud_1x2 s:shard1 r:core_node1 x:c8n_crud_1x2_shard1_replica2]= o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.luce= ne.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=3D16= 77721, mergeFactor=3D39, maxMergeSize=3D2147483648, maxMergeSizeForForcedMe= rge=3D9223372036854775807, calibrateSizeByDeletes=3Dfalse, maxMergeDocs=3D2= 147483647, maxCFSSegmentSizeMB=3D8.796093022207999E12, noCFSRatio=3D1.0] [junit4] 2> 2334044 WARN (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 r:core_node2 x:c8n_crud_1x2_shard1_replica1= ] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type =3D re= questHandler,name =3D /dump,class =3D DumpRequestHandler,args =3D {defaults= =3D{a=3DA,b=3DB}}} [junit4] 2> 2334060 INFO (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 r:core_node2 x:c8n_crud_1x2_shard1_replica1= ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.upd= ate.UpdateLog [junit4] 2> 2334061 INFO (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 r:core_node2 x:c8n_crud_1x2_shard1_replica1= ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=3D defaultSyncLevel=3DF= LUSH numRecordsToKeep=3D100 maxNumLogsToKeep=3D10 numVersionBuckets=3D65536 [junit4] 2> 2334063 INFO (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 r:core_node2 x:c8n_crud_1x2_shard1_replica1= ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 2334063 INFO (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 r:core_node2 x:c8n_crud_1x2_shard1_replica1= ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 2334088 INFO (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 r:core_node2 x:c8n_crud_1x2_shard1_replica1= ] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.luc= ene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=3D1000, merge= Factor=3D12, maxMergeSize=3D9223372036854775807, maxMergeSizeForForcedMerge= =3D9223372036854775807, calibrateSizeByDeletes=3Dtrue, maxMergeDocs=3D21474= 83647, maxCFSSegmentSizeMB=3D8.796093022207999E12, noCFSRatio=3D0.547897890= 4233723] [junit4] 2> 2334092 INFO (qtp1684334374-13992) [n:127.0.0.1:57621_jm_= pnl%2Fb c:c8n_crud_1x2 s:shard1 r:core_node [...truncated too long message...] tpPartitionTest.test-seed#[A6700AA91C60A879]) [ ] o.e.j.s.h.ContextHandl= er Stopped o.e.j.s.ServletContextHandler@3eea92ce{/jm_pnl/b,null,UNAVAILABL= E} [junit4] 2> 2451371 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.ChaosMonkey monkey: stop shard! 57621 [junit4] 2> 2451372 INFO (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:57611 57611 [junit4] 2> 2451374 INFO (Thread-3965) [ ] o.a.s.c.ZkTestServer co= nnecting to 127.0.0.1:57611 57611 [junit4] 2> 2451375 WARN (Thread-3965) [ ] o.a.s.c.ZkTestServer Wa= tch limit violations:=20 [junit4] 2> Maximum concurrent create/delete watches above limit: [junit4] 2>=20 [junit4] 2> =096=09/solr/clusterprops.json [junit4] 2> =096=09/solr/aliases.json [junit4] 2> =095=09/solr/security.json [junit4] 2> =094=09/solr/configs/conf1 [junit4] 2> =093=09/solr/collections/collection1/state.json [junit4] 2> =093=09/solr/collections/c8n_1x3/state.json [junit4] 2> =093=09/solr/collections/collMinRf_1x3/state.json [junit4] 2> =093=09/solr/collections/c8n_1x2_leader_session_loss/state= .json [junit4] 2> =092=09/solr/collections/c8n_1x2/state.json [junit4] 2> =092=09/solr/collections/c8n_crud_1x2/state.json [junit4] 2> =092=09/solr/collections/control_collection/state.json [junit4] 2>=20 [junit4] 2> Maximum concurrent data watches above limit: [junit4] 2>=20 [junit4] 2> =096=09/solr/clusterstate.json [junit4] 2>=20 [junit4] 2> Maximum concurrent children watches above limit: [junit4] 2>=20 [junit4] 2> =09130=09/solr/overseer/queue [junit4] 2> =09114=09/solr/overseer/collection-queue-work [junit4] 2> =0924=09/solr/overseer/queue-work [junit4] 2> =096=09/solr/collections [junit4] 2> =095=09/solr/live_nodes [junit4] 2>=20 [junit4] 2> 2451375 WARN (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.SocketProxy Closing 3 connections to: http://127.0= .0.1:57651/jm_pnl/b, target: http://127.0.0.1:57652/jm_pnl/b [junit4] 2> 2451376 WARN (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.SocketProxy Closing 4 connections to: http://127.0= .0.1:57621/jm_pnl/b, target: http://127.0.0.1:57622/jm_pnl/b [junit4] 2> 2451376 WARN (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.SocketProxy Closing 12 connections to: http://127.= 0.0.1:57707/jm_pnl/b, target: http://127.0.0.1:57708/jm_pnl/b [junit4] 2> 2451376 WARN (TEST-HttpPartitionTest.test-seed#[A6700AA91= C60A879]) [ ] o.a.s.c.SocketProxy Closing 9 connections to: http://127.0= .0.1:57679/jm_pnl/b, target: http://127.0.0.1:57680/jm_pnl/b [junit4] 2> NOTE: reproduce with: ant test -Dtestcase=3DHttpPartition= Test -Dtests.method=3Dtest -Dtests.seed=3DA6700AA91C60A879 -Dtests.slow=3Dt= rue -Dtests.locale=3Dlt -Dtests.timezone=3DEET -Dtests.asserts=3Dtrue -Dtes= ts.file.encoding=3DISO-8859-1 [junit4] ERROR 139s J0 | HttpPartitionTest.test <<< [junit4] > Throwable #1: com.carrotsearch.randomizedtesting.UncaughtE= xceptionError: Captured an uncaught exception in thread: Thread[id=3D14312,= name=3DSocketProxy-Response-57622:58005, state=3DRUNNABLE, group=3DTGRP-Ht= tpPartitionTest] [junit4] > Caused by: java.lang.RuntimeException: java.net.SocketExce= ption: Socket is closed [junit4] > =09at __randomizedtesting.SeedInfo.seed([A6700AA91C60A879]= :0) [junit4] > =09at org.apache.solr.cloud.SocketProxy$Bridge$Pump.run(So= cketProxy.java:347) [junit4] > Caused by: java.net.SocketException: Socket is closed [junit4] > =09at java.net.Socket.setSoTimeout(Socket.java:1137) [junit4] > =09at org.apache.solr.cloud.SocketProxy$Bridge$Pump.run(So= cketProxy.java:344)Throwable #2: com.carrotsearch.randomizedtesting.Uncaugh= tExceptionError: Captured an uncaught exception in thread: Thread[id=3D1431= 1, name=3DSocketProxy-Request-58005:57622, state=3DRUNNABLE, group=3DTGRP-H= ttpPartitionTest] [junit4] > Caused by: java.lang.RuntimeException: java.net.SocketExce= ption: Socket is closed [junit4] > =09at __randomizedtesting.SeedInfo.seed([A6700AA91C60A879]= :0) [junit4] > =09at org.apache.solr.cloud.SocketProxy$Bridge$Pump.run(So= cketProxy.java:347) [junit4] > Caused by: java.net.SocketException: Socket is closed [junit4] > =09at java.net.Socket.setSoTimeout(Socket.java:1137) [junit4] > =09at org.apache.solr.cloud.SocketProxy$Bridge$Pump.run(So= cketProxy.java:344) [junit4] 2> 2451384 INFO (SUITE-HttpPartitionTest-seed#[A6700AA91C60A= 879]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore [junit4] 2> Dec 04, 2016 10:47:17 AM com.carrotsearch.randomizedtestin= g.ThreadLeakControl checkThreadLeaks [junit4] 2> WARNING: Will linger awaiting termination of 1 leaked thre= ad(s). [junit4] 2> NOTE: test params are: codec=3DAsserting(Lucene62): {range= _facet_l_dv=3DPostingsFormat(name=3DMockRandom), _version_=3DPostingsFormat= (name=3DAsserting), multiDefault=3DPostingsFormat(name=3DDirect), a_t=3DPos= tingsFormat(name=3DAsserting), intDefault=3DPostingsFormat(name=3DAsserting= ), id=3DPostingsFormat(name=3DMockRandom), range_facet_i_dv=3DPostingsForma= t(name=3DAsserting), text=3DPostingsFormat(name=3DMemory doPackFST=3D false= ), range_facet_l=3DPostingsFormat(name=3DAsserting), timestamp=3DPostingsFo= rmat(name=3DAsserting)}, docValues:{range_facet_l_dv=3DDocValuesFormat(name= =3DMemory), _version_=3DDocValuesFormat(name=3DLucene54), multiDefault=3DDo= cValuesFormat(name=3DAsserting), a_t=3DDocValuesFormat(name=3DLucene54), in= tDefault=3DDocValuesFormat(name=3DLucene54), range_facet_i_dv=3DDocValuesFo= rmat(name=3DLucene54), id=3DDocValuesFormat(name=3DMemory), text=3DDocValue= sFormat(name=3DDirect), timestamp=3DDocValuesFormat(name=3DLucene54), range= _facet_l=3DDocValuesFormat(name=3DLucene54)}, maxPointsInLeafNode=3D1080, m= axMBSortInHeap=3D7.730937331099966, sim=3DRandomSimilarity(queryNorm=3Dfals= e,coord=3Dcrazy): {}, locale=3Dlt, timezone=3DEET [junit4] 2> NOTE: Windows 10 10.0 amd64/Oracle Corporation 1.8.0_102 (= 64-bit)/cpus=3D3,threads=3D1,free=3D272230104,total=3D536870912 [junit4] 2> NOTE: All tests run in this JVM: [PeerSyncTest, Distribute= dQueryElevationComponentTest, AlternateDirectoryTest, DeleteStatusTest, Tes= tConfigReload, TestFieldCacheReopen, TestCustomDocTransformer, CollectionsA= PIAsyncDistributedZkTest, TestComplexPhraseQParserPlugin, DistributedMLTCom= ponentTest, TestSolr4Spatial2, TimeZoneUtilsTest, TestAnalyzedSuggestions, = IgnoreCommitOptimizeUpdateProcessorFactoryTest, TestSolrQueryResponse, Test= BulkSchemaConcurrent, TestXIncludeConfig, DOMUtilTest, HighlighterTest, Clo= udMLTQParserTest, TestRandomDVFaceting, TestUseDocValuesAsStored2, TestSolr= CLIRunExample, SolrPluginUtilsTest, TestRestoreCore, StressHdfsTest, TestRT= GBase, TestReplicationHandler, TestCSVLoader, BlockJoinFacetRandomTest, Rep= licaListTransformerTest, ShardSplitTest, TestBulkSchemaAPI, DistributedSugg= estComponentTest, TestTolerantSearch, OutOfBoxZkACLAndCredentialsProvidersT= est, TestManagedResourceStorage, SchemaVersionSpecificBehaviorTest, Suggest= erFSTTest, ExitableDirectoryReaderTest, GraphQueryTest, TestSimpleQParserPl= ugin, StatelessScriptUpdateProcessorFactoryTest, ChaosMonkeyNothingIsSafeTe= st, TestSurroundQueryParser, TestGraphTermsQParserPlugin, SoftAutoCommitTes= t, NumericFieldsTest, DirectSolrSpellCheckerTest, SparseHLLTest, SpatialFil= terTest, TestCollationFieldDocValues, TestScoreJoinQPScore, CoreSorterTest,= IndexBasedSpellCheckerTest, AssignTest, TestPostingsSolrHighlighter, TestC= ollationField, PKIAuthenticationIntegrationTest, TestTrackingShardHandlerFa= ctory, TestConfigSetProperties, TestCryptoKeys, DocumentBuilderTest, TestDi= stribDocBasedVersion, RecoveryZkTest, CdcrRequestHandlerTest, TestFieldSort= Values, OverseerCollectionConfigSetProcessorTest, TestComponentsName, DocVa= luesTest, QueryEqualityTest, HdfsRestartWhileUpdatingTest, RecoveryAfterSof= tCommitTest, TestSweetSpotSimilarityFactory, DocValuesMultiTest, TestLeader= InitiatedRecoveryThread, TestDynamicLoading, TestFieldCacheSort, SharedFSAu= toReplicaFailoverUtilsTest, TestLockTree, TestOverriddenPrefixQueryForCusto= mFieldType, TestLegacyFieldCache, TestHighFrequencyDictionaryFactory, TestC= loudPivotFacet, TestPartialUpdateDeduplication, DistributedSpellCheckCompon= entTest, TestSolrDynamicMBean, TermsComponentTest, UtilsToolTest, TestToler= antUpdateProcessorRandomCloud, LeaderFailoverAfterPartitionTest, XsltUpdate= RequestHandlerTest, TestExpandComponent, TestSubQueryTransformer, TestPerFi= eldSimilarityWithDefaultOverride, TestLeaderElectionWithEmptyReplica, Shard= RoutingTest, UUIDUpdateProcessorFallbackTest, TestDefaultStatsCache, TestSo= lrIndexConfig, TriLevelCompositeIdRoutingTest, TestSolrCloudSnapshots, Solr= TestCaseJ4Test, HLLSerializationTest, OverseerTaskQueueTest, HdfsCollection= sAPIDistributedZkTest, TestSolrQueryParserResource, TestPKIAuthenticationPl= ugin, HdfsChaosMonkeyNothingIsSafeTest, PolyFieldTest, AtomicUpdatesTest, T= estSort, TestCollectionAPI, TestNonDefinedSimilarityFactory, TestMissingGro= ups, TestRawResponseWriter, AnalyticsQueryTest, SmileWriterTest, TestJavabi= nTupleStreamParser, VersionInfoTest, TestSolrConfigHandlerConcurrent, TestE= xtendedDismaxParser, TestOnReconnectListenerSupport, ConnectionManagerTest,= TestLRUCache, ExplicitHLLTest, TestConfigOverlay, PrimUtilsTest, TestCharF= ilters, TestBM25SimilarityFactory, SuggestComponentTest, TestFastOutputStre= am, QueryResultKeyTest, ClusterStateUpdateTest, TestRemoteStreaming, UniqFi= eldsUpdateProcessorFactoryTest, TestLFUCache, TestMacros, TestRequestStatus= CollectionAPI, UnloadDistributedZkTest, SpatialHeatmapFacetsTest, TestDistr= ibutedSearch, TestNamedUpdateProcessors, CollectionStateFormat2Test, CloudE= xitableDirectoryReaderTest, TestInfoStreamLogging, TestCloudDeleteByQuery, = TestReRankQParserPlugin, TestCursorMarkWithoutUniqueKey, TestSchemaNameReso= urce, TestWordDelimiterFilterFactory, DeleteLastCustomShardedReplicaTest, X= mlUpdateRequestHandlerTest, HttpPartitionTest] [junit4] Completed [481/658 (1!)] on J0 in 139.78s, 1 test, 1 error <<< = FAILURES! [...truncated 61364 lines...] ------=_Part_96_2019253692.1480850723468 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_96_2019253692.1480850723468--