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 4DDC2200B63 for ; Mon, 15 Aug 2016 15:37:52 +0200 (CEST) Received: by cust-asf.ponee.io (Postfix) id 47D54160AA7; Mon, 15 Aug 2016 13:37:52 +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 2E259160A8A for ; Mon, 15 Aug 2016 15:37:49 +0200 (CEST) Received: (qmail 20494 invoked by uid 500); 15 Aug 2016 13:37:48 -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 20480 invoked by uid 99); 15 Aug 2016 13:37:47 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd1-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 15 Aug 2016 13:37:47 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd1-us-west.apache.org (ASF Mail Server at spamd1-us-west.apache.org) with ESMTP id 31B8EC11B5 for ; Mon, 15 Aug 2016 13:37:47 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd1-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 2 X-Spam-Level: ** X-Spam-Status: No, score=2 tagged_above=-999 required=6.31 tests=[KAM_BADIPHTTP=2, SPF_PASS=-0.001, WEIRD_PORT=0.001] autolearn=disabled Received: from mx2-lw-eu.apache.org ([10.40.0.8]) by localhost (spamd1-us-west.apache.org [10.40.0.7]) (amavisd-new, port 10024) with ESMTP id vn411bJ_Zm5A for ; Mon, 15 Aug 2016 13:37:40 +0000 (UTC) Received: from serv1.sd-datasolutions.de (serv1.sd-datasolutions.de [188.138.57.78]) by mx2-lw-eu.apache.org (ASF Mail Server at mx2-lw-eu.apache.org) with ESMTPS id D049F5FBC7 for ; Mon, 15 Aug 2016 13:37:39 +0000 (UTC) Received: from serv1 (localhost.localdomain [127.0.0.1]) by serv1.sd-datasolutions.de (Postfix) with ESMTP id 8C2CA4C00DF; Mon, 15 Aug 2016 13:37:39 +0000 (UTC) Date: Mon, 15 Aug 2016 13:36:40 +0000 (UTC) From: Policeman Jenkins Server To: cpoerschke@apache.org, arafalov@gmail.com, dev@lucene.apache.org Message-ID: <959663656.177.1471268259576.JavaMail.jenkins@serv1> In-Reply-To: <864220453.171.1471259305770.JavaMail.jenkins@serv1> References: <864220453.171.1471259305770.JavaMail.jenkins@serv1> Subject: [JENKINS] Lucene-Solr-master-Linux (32bit/jdk1.8.0_102) - Build # 17571 - Still Unstable! MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----=_Part_176_222535611.1471268259476" X-Jenkins-Job: Lucene-Solr-master-Linux X-Jenkins-Result: UNSTABLE archived-at: Mon, 15 Aug 2016 13:37:52 -0000 ------=_Part_176_222535611.1471268259476 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Build: http://jenkins.thetaphi.de/job/Lucene-Solr-master-Linux/17571/ Java: 32bit/jdk1.8.0_102 -server -XX:+UseSerialGC 1 tests failed. FAILED: org.apache.solr.cloud.RecoveryZkTest.test Error Message: Captured an uncaught exception in thread: Thread[id=3D9352, name=3DupdateEx= ecutor-1763-thread-3, state=3DRUNNABLE, group=3DTGRP-RecoveryZkTest] Stack Trace: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an unca= ught exception in thread: Thread[id=3D9352, name=3DupdateExecutor-1763-thre= ad-3, state=3DRUNNABLE, group=3DTGRP-RecoveryZkTest] =09at __randomizedtesting.SeedInfo.seed([FF7B6D4FA437E1D5:772F52950ACB8C2D]= :0) Caused by: org.apache.solr.common.SolrException: Replica: https://127.0.0.1= :32925/z/k/collection1/ should have been marked under leader initiated reco= very in ZkController but wasn't. =09at __randomizedtesting.SeedInfo.seed([FF7B6D4FA437E1D5]:0) =09at org.apache.solr.cloud.LeaderInitiatedRecoveryThread.run(LeaderInitiat= edRecoveryThread.java:88) =09at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.l= ambda$execute$0(ExecutorUtil.java:229) =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.= java:1142) =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor= .java:617) =09at java.lang.Thread.run(Thread.java:745) Build Log: [...truncated 11440 lines...] [junit4] Suite: org.apache.solr.cloud.RecoveryZkTest [junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-mast= er-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D= 4FA437E1D5-001/init-core-data-001 [junit4] 2> 1053766 INFO (SUITE-RecoveryZkTest-seed#[FF7B6D4FA437E1D5= ]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth = (false) via: @org.apache.solr.util.RandomizeSSL(reason=3D, ssl=3DNaN, value= =3DNaN, clientAuth=3DNaN) [junit4] 2> 1053767 INFO (SUITE-RecoveryZkTest-seed#[FF7B6D4FA437E1D5= ]-worker) [ ] o.a.s.BaseDistributedSearchTestCase Setting hostContext sy= stem property: /z/k [junit4] 2> 1053769 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER [junit4] 2> 1053769 INFO (Thread-2124) [ ] o.a.s.c.ZkTestServer cl= ient port:0.0.0.0/0.0.0.0:0 [junit4] 2> 1053769 INFO (Thread-2124) [ ] o.a.s.c.ZkTestServer St= arting server [junit4] 2> 1053869 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.ZkTestServer start zk server on port:43126 [junit4] 2> 1053869 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider [junit4] 2> 1053869 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to = ZooKeeper [junit4] 2> 1053871 INFO (zkCallback-1749-thread-1) [ ] o.a.s.c.c.= ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@a8= 478c name:ZooKeeperConnection Watcher:127.0.0.1:43126 got event WatchedEven= t state:SyncConnected type:None path:null path:null type:None [junit4] 2> 1053871 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper [junit4] 2> 1053871 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider [junit4] 2> 1053871 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /solr [junit4] 2> 1053872 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider [junit4] 2> 1053872 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to = ZooKeeper [junit4] 2> 1053873 INFO (zkCallback-1750-thread-1) [ ] o.a.s.c.c.= ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@1c= aad34 name:ZooKeeperConnection Watcher:127.0.0.1:43126/solr got event Watch= edEvent state:SyncConnected type:None path:null path:null type:None [junit4] 2> 1053873 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper [junit4] 2> 1053873 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider [junit4] 2> 1053873 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/collection1 [junit4] 2> 1053873 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/collection1/sha= rds [junit4] 2> 1053874 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/control_collect= ion [junit4] 2> 1053874 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/control_collect= ion/shards [junit4] 2> 1053874 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene= -Solr-master-Linux/solr/core/src/test-files/solr/collection1/conf/solrconfi= g-tlog.xml to /configs/conf1/solrconfig.xml [junit4] 2> 1053875 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /configs/conf1/solrconfig.xm= l [junit4] 2> 1053876 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene= -Solr-master-Linux/solr/core/src/test-files/solr/collection1/conf/schema15.= xml to /configs/conf1/schema.xml [junit4] 2> 1053876 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /configs/conf1/schema.xml [junit4] 2> 1053876 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene= -Solr-master-Linux/solr/core/src/test-files/solr/collection1/conf/solrconfi= g.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.random= indexconfig.xml [junit4] 2> 1053876 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /configs/conf1/solrconfig.sn= ippet.randomindexconfig.xml [junit4] 2> 1053877 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene= -Solr-master-Linux/solr/core/src/test-files/solr/collection1/conf/stopwords= .txt to /configs/conf1/stopwords.txt [junit4] 2> 1053877 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /configs/conf1/stopwords.txt [junit4] 2> 1053877 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene= -Solr-master-Linux/solr/core/src/test-files/solr/collection1/conf/protwords= .txt to /configs/conf1/protwords.txt [junit4] 2> 1053877 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /configs/conf1/protwords.txt [junit4] 2> 1053878 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene= -Solr-master-Linux/solr/core/src/test-files/solr/collection1/conf/currency.= xml to /configs/conf1/currency.xml [junit4] 2> 1053878 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /configs/conf1/currency.xml [junit4] 2> 1053878 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene= -Solr-master-Linux/solr/core/src/test-files/solr/collection1/conf/enumsConf= ig.xml to /configs/conf1/enumsConfig.xml [junit4] 2> 1053879 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /configs/conf1/enumsConfig.x= ml [junit4] 2> 1053879 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene= -Solr-master-Linux/solr/core/src/test-files/solr/collection1/conf/open-exch= ange-rates.json to /configs/conf1/open-exchange-rates.json [junit4] 2> 1053879 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /configs/conf1/open-exchange= -rates.json [junit4] 2> 1053880 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene= -Solr-master-Linux/solr/core/src/test-files/solr/collection1/conf/mapping-I= SOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt [junit4] 2> 1053880 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /configs/conf1/mapping-ISOLa= tin1Accent.txt [junit4] 2> 1053880 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene= -Solr-master-Linux/solr/core/src/test-files/solr/collection1/conf/old_synon= yms.txt to /configs/conf1/old_synonyms.txt [junit4] 2> 1053880 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /configs/conf1/old_synonyms.= txt [junit4] 2> 1053881 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene= -Solr-master-Linux/solr/core/src/test-files/solr/collection1/conf/synonyms.= txt to /configs/conf1/synonyms.txt [junit4] 2> 1053881 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient makePath: /configs/conf1/synonyms.txt [junit4] 2> 1053881 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider [junit4] 2> 1053882 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to = ZooKeeper [junit4] 2> 1053882 INFO (zkCallback-1752-thread-1) [ ] o.a.s.c.c.= ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@19= bbc6d name:ZooKeeperConnection Watcher:127.0.0.1:43126/solr got event Watch= edEvent state:SyncConnected type:None path:null path:null type:None [junit4] 2> 1053882 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper [junit4] 2> 1053882 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider [junit4] 2> 1053941 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/je= nkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/= solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/control-001/cores/collection= 1 [junit4] 2> 1053943 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314 [junit4] 2> 1053944 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandle= r@3c4f22{/z/k,null,AVAILABLE} [junit4] 2> 1053947 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.e.j.s.ServerConnector Started ServerConnector@1fd19aa{SSL,[= ssl, http/1.1]}{127.0.0.1:38523} [junit4] 2> 1053947 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.e.j.s.Server Started @1055874ms [junit4] 2> 1053947 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir= =3D/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/te= st/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/tempDir-001/contr= ol/data, hostContext=3D/z/k, hostPort=3D38523, coreRootDirectory=3D/home/je= nkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/../..= /../../../../../../../home/jenkins/workspace/Lucene-Solr-master-Linux/solr/= build/solr-core/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001= /control-001/cores} [junit4] 2> 1053947 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.s.SolrDispatchFilter SolrDispatchFilter.init(): sun.mis= c.Launcher$AppClassLoader@1d16e93 [junit4] 2> 1053947 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.SolrResourceLoader new SolrResourceLoader for directo= ry: '/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/= test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/control-001' [junit4] 2> 1053947 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.SolrResourceLoader JNDI not configured for solr (NoIn= itialContextEx) [junit4] 2> 1053947 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.SolrResourceLoader solr home defaulted to 'solr/' (co= uld not find system property or JNDI) [junit4] 2> 1053948 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider [junit4] 2> 1053948 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to = ZooKeeper [junit4] 2> 1053948 INFO (zkCallback-1753-thread-1) [ ] o.a.s.c.c.= ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@e7= 6626 name:ZooKeeperConnection Watcher:127.0.0.1:43126/solr got event Watche= dEvent state:SyncConnected type:None path:null path:null type:None [junit4] 2> 1053948 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper [junit4] 2> 1053949 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider [junit4] 2> 1053949 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (no= t found in ZooKeeper) [junit4] 2> 1053949 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /h= ome/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0= /temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/control-001/solr.xml [junit4] 2> 1053953 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.CorePropertiesLocator Config-defined core root direct= ory: /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/= test/J0/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-maste= r-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4= FA437E1D5-001/control-001/cores [junit4] 2> 1053953 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.CoreContainer New CoreContainer 26143849 [junit4] 2> 1053953 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.CoreContainer Loading cores into CoreContainer [insta= nceDir=3D/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-c= ore/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/control-001= ] [junit4] 2> 1053953 WARN (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.CoreContainer Couldn't add files from /home/jenkins/w= orkspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cl= oud.RecoveryZkTest_FF7B6D4FA437E1D5-001/control-001/lib to classpath: /home= /jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/te= mp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/control-001/lib [junit4] 2> 1053953 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.h.c.HttpShardHandlerFactory created with socketTimeout = : 90000,urlScheme : ,connTimeout : 15000,maxConnectionsPerHost : 20,maxConn= ections : 10000,corePoolSize : 0,maximumPoolSize : 2147483647,maxThreadIdle= Time : 5,sizeOfQueue : -1,fairnessPolicy : false, [junit4] 2> 1053955 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.u.UpdateShardHandler Created UpdateShardHandler HTTP cl= ient with params: socketTimeout=3D340000&connTimeout=3D45000&maxConnections= =3D100000&maxConnectionsPerHost=3D100000 [junit4] 2> 1053955 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.l.LogWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFa= ctory [junit4] 2> 1053955 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.l.LogWatcher Registering Log Listener [Log4j (org.slf4j= .impl.Log4jLoggerFactory)] [junit4] 2> 1053955 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.ZkContainer Zookeeper client=3D127.0.0.1:43126/solr [junit4] 2> 1053955 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.ZkController zkHost includes chroot [junit4] 2> 1053955 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider [junit4] 2> 1053956 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to = ZooKeeper [junit4] 2> 1053956 INFO (zkCallback-1756-thread-1) [ ] o.a.s.c.c.= ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@16= 542b5 name:ZooKeeperConnection Watcher:127.0.0.1:43126 got event WatchedEve= nt state:SyncConnected type:None path:null path:null type:None [junit4] 2> 1053956 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper [junit4] 2> 1053956 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider [junit4] 2> 1053957 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.ZkController Added new OnRecon= nect listener org.apache.solr.cloud.ZkController$$Lambda$87/13543940@57476d [junit4] 2> 1053957 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ConnectionManager Waiting fo= r client to connect to ZooKeeper [junit4] 2> 1053958 INFO (zkCallback-1757-thread-1-processing-n:127.0= .0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ConnectionManager= Watcher org.apache.solr.common.cloud.ConnectionManager@bfd7fa name:ZooKeep= erConnection Watcher:127.0.0.1:43126/solr got event WatchedEvent state:Sync= Connected type:None path:null path:null type:None [junit4] 2> 1053958 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ConnectionManager Client is = connected to ZooKeeper [junit4] 2> 1053958 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /over= seer/queue [junit4] 2> 1053960 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /over= seer/collection-queue-work [junit4] 2> 1053960 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /over= seer/collection-map-running [junit4] 2> 1053961 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /over= seer/collection-map-completed [junit4] 2> 1053961 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /over= seer/collection-map-failure [junit4] 2> 1053962 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /live= _nodes [junit4] 2> 1053962 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /alia= ses.json [junit4] 2> 1053963 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /clus= terstate.json [junit4] 2> 1053963 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /secu= rity.json [junit4] 2> 1053963 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ZkStateReader Updating clust= er state from ZooKeeper...=20 [junit4] 2> 1053963 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ZkStateReader Loaded cluster= properties: {urlScheme=3Dhttps} [junit4] 2> 1053963 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ZkStateReader Updated live n= odes from ZooKeeper... (0) -> (0) [junit4] 2> 1053964 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /over= seer_elect [junit4] 2> 1053964 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /over= seer_elect/election [junit4] 2> 1053965 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.Overseer Overseer (id=3Dnull) = closing [junit4] 2> 1053965 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.LeaderElector Joined leadershi= p election with path: /overseer_elect/election/96420930657910789-127.0.0.1:= 38523_z%2Fk-n_0000000000 [junit4] 2> 1053965 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.OverseerElectionContext I am g= oing to be the leader 127.0.0.1:38523_z%2Fk [junit4] 2> 1053965 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /over= seer_elect/leader [junit4] 2> 1053965 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.Overseer Overseer (id=3D964209= 30657910789-127.0.0.1:38523_z%2Fk-n_0000000000) starting [junit4] 2> 1053966 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /over= seer/queue-work [junit4] 2> 1053967 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.OverseerAutoReplicaFailoverThr= ead Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopD= elay=3D10000 autoReplicaFailoverWaitAfterExpiration=3D10000 autoReplicaFail= overBadNodeExpiration=3D60000 [junit4] 2> 1053967 INFO (OverseerCollectionConfigSetProcessor-964209= 30657910789-127.0.0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk = ] o.a.s.c.OverseerTaskProcessor Process current queue of overseer operatio= ns [junit4] 2> 1053967 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.Overse= er Starting to work on the main queue [junit4] 2> 1053967 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.ZkController Register node as = live in ZooKeeper:/live_nodes/127.0.0.1:38523_z%2Fk [junit4] 2> 1053968 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /live= _nodes/127.0.0.1:38523_z%2Fk [junit4] 2> 1053968 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ZkSt= ateReader Updated live nodes from ZooKeeper... (0) -> (0) [junit4] 2> 1053968 INFO (zkCallback-1757-thread-1-processing-n:127.0= .0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ZkStateReader A l= ive node change: [WatchedEvent state:SyncConnected type:NodeChildrenChanged= path:/live_nodes], has occurred - updating... (live nodes size: [0]) [junit4] 2> 1053968 INFO (zkCallback-1757-thread-1-processing-n:127.0= .0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ZkStateReader Upd= ated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 1053980 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.CoreContainer Security conf do= esn't exist. Skipping setup for authorization module. [junit4] 2> 1053980 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.CoreContainer No authenticatio= n plugin used. [junit4] 2> 1053981 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.CorePropertiesLocator Looking = for core definitions underneath /home/jenkins/workspace/Lucene-Solr-master-= Linux/solr/build/solr-core/test/J0/../../../../../../../../../home/jenkins/= workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.c= loud.RecoveryZkTest_FF7B6D4FA437E1D5-001/control-001/cores [junit4] 2> 1053981 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.CoreDescriptor Created CoreDes= criptor: {name=3Dcollection1, config=3Dsolrconfig.xml, transient=3Dfalse, s= chema=3Dschema.xml, loadOnStartup=3Dtrue, configSetProperties=3Dconfigsetpr= ops.json, collection=3Dcontrol_collection, coreNodeName=3D, dataDir=3Ddata/= , shard=3D} [junit4] 2> 1053982 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.CorePropertiesLocator Found co= re collection1 in /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/bui= ld/solr-core/test/J0/../../../../../../../../../home/jenkins/workspace/Luce= ne-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.RecoveryZ= kTest_FF7B6D4FA437E1D5-001/control-001/cores/collection1 [junit4] 2> 1053982 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.CorePropertiesLocator Found 1 = core definitions [junit4] 2> 1053982 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.ZkController publishing state=3Ddown [junit4] 2> 1053982 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.ZkController numShards not found on descriptor - readin= g it from system property [junit4] 2> 1053982 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.s.SolrDispatchFilter user.dir=3D= /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/= J0 [junit4] 2> 1053982 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:38523_z%2Fk ] o.a.s.s.SolrDispatchFilter SolrDispatc= hFilter.init() done [junit4] 2> 1053982 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.ZkController Collection control_collection not visible = yet, but flagging it so a watch is registered when it becomes visible [junit4] 2> 1053982 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.Overse= er processMessage: queueSize: 1, message =3D { [junit4] 2> "core":"collection1", [junit4] 2> "roles":null, [junit4] 2> "base_url":"https://127.0.0.1:38523/z/k", [junit4] 2> "node_name":"127.0.0.1:38523_z%2Fk", [junit4] 2> "numShards":"1", [junit4] 2> "state":"down", [junit4] 2> "shard":null, [junit4] 2> "collection":"control_collection", [junit4] 2> "operation":"state"} current state version: 0 [junit4] 2> 1053983 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.o.Repl= icaMutator Update state numShards=3D1 message=3D{ [junit4] 2> "core":"collection1", [junit4] 2> "roles":null, [junit4] 2> "base_url":"https://127.0.0.1:38523/z/k", [junit4] 2> "node_name":"127.0.0.1:38523_z%2Fk", [junit4] 2> "numShards":"1", [junit4] 2> "state":"down", [junit4] 2> "shard":null, [junit4] 2> "collection":"control_collection", [junit4] 2> "operation":"state"} [junit4] 2> 1053983 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.c.ZkStateReader Deleting data for [control_collection] [junit4] 2> 1053983 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.o.Clus= terStateMutator building a new cName: control_collection [junit4] 2> 1053983 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.o.Repl= icaMutator Assigning new node to shard shard=3Dshard1 [junit4] 2> 1053984 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.ZkController look for our core node name [junit4] 2> 1053984 INFO (zkCallback-1757-thread-1-processing-n:127.0= .0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ZkStateReader A c= luster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged= path:/clusterstate.json], has occurred - updating... (live nodes size: [1]= ) [junit4] 2> 1054984 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.ZkController waiting to find shard id in clusterstate f= or collection1 [junit4] 2> 1054984 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.ZkController Check for collection zkNode:control_collec= tion [junit4] 2> 1054984 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.ZkController Collection zkNode exists [junit4] 2> 1054984 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.c.ZkStateReader Load collection config from: [/collecti= ons/control_collection] [junit4] 2> 1054985 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.c.ZkStateReader path=3D[/collections/control_collection= ] [configName]=3D[conf1] specified config exists in ZooKeeper [junit4] 2> 1054985 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.SolrResourceLoader new SolrResourceLoader for directory= : '/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/te= st/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/control-001/cores= /collection1' [junit4] 2> 1054985 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.SolrResourceLoader JNDI not configured for solr (NoInit= ialContextEx) [junit4] 2> 1054985 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.SolrResourceLoader solr home defaulted to 'solr/' (coul= d not find system property or JNDI) [junit4] 2> 1054986 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.Config loaded config solrconfig.xml with version 0=20 [junit4] 2> 1054989 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.SolrConfig current version of requestparams : -1 [junit4] 2> 1054991 WARN (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.Config Beginning with Solr 5.5, is deprec= ated, use instead. [junit4] 2> 1054992 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0 [junit4] 2> 1054998 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.SolrConfig Loaded SolrConfig: solrconfig.xml [junit4] 2> 1055001 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.s.IndexSchema [collection1] Schema name=3Dtest [junit4] 2> 1055054 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.s.IndexSchema default search field in schema is text [junit4] 2> 1055054 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.s.IndexSchema unique key field: id [junit4] 2> 1055055 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.s.FileExchangeRateProvider Reloading exchange rates from = file currency.xml [junit4] 2> 1055056 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.s.FileExchangeRateProvider Reloading exchange rates from = file currency.xml [junit4] 2> 1055062 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.ConfigSetProperties Did not find ConfigSet properties, = assuming default properties: Can't find resource 'configsetprops.json' in c= lasspath or '/configs/conf1', cwd=3D/home/jenkins/workspace/Lucene-Solr-mas= ter-Linux/solr/build/solr-core/test/J0 [junit4] 2> 1055062 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection x:c= ollection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using con= figuration from collection control_collection [junit4] 2> 1055062 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.SolrCore org.apache.solr.core.MockD= irectoryFactory [junit4] 2> 1055062 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening n= ew SolrCore at [/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build= /solr-core/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/cont= rol-001/cores/collection1], dataDir=3D[/home/jenkins/workspace/Lucene-Solr-= master-Linux/solr/build/solr-core/test/J0/../../../../../../../../../home/j= enkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp= /solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/control-001/cores/collectio= n1/data/] [junit4] 2> 1055062 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is e= nabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanS= erver@16fc28e [junit4] 2> 1055063 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.CachingDirectoryFactory return new = directory for /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/s= olr-core/test/J0/../../../../../../../../../home/jenkins/workspace/Lucene-S= olr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.RecoveryZkTes= t_FF7B6D4FA437E1D5-001/control-001/cores/collection1/data/snapshot_metadata [junit4] 2> 1055063 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.s.SolrSnapshotMetaDataManager Loadi= ng from snapshot metadata file... [junit4] 2> 1055063 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.CachingDirectoryFactory return new = directory for /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/s= olr-core/test/J0/../../../../../../../../../home/jenkins/workspace/Lucene-S= olr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.RecoveryZkTes= t_FF7B6D4FA437E1D5-001/control-001/cores/collection1/data [junit4] 2> 1055063 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.SolrCore New index directory detect= ed: old=3Dnull new=3D/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/= build/solr-core/test/J0/../../../../../../../../../home/jenkins/workspace/L= ucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.Recove= ryZkTest_FF7B6D4FA437E1D5-001/control-001/cores/collection1/data/index/ [junit4] 2> 1055063 WARN (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.SolrCore [collection1] Solr index d= irectory '/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-= core/test/J0/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-= master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.RecoveryZkTest_FF= 7B6D4FA437E1D5-001/control-001/cores/collection1/data/index' doesn't exist.= Creating new index... [junit4] 2> 1055064 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.CachingDirectoryFactory return new = directory for /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/s= olr-core/test/J0/../../../../../../../../../home/jenkins/workspace/Lucene-S= olr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.RecoveryZkTes= t_FF7B6D4FA437E1D5-001/control-001/cores/collection1/data/index [junit4] 2> 1055064 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy= wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePoli= cy: minMergeSize=3D1000, mergeFactor=3D25, maxMergeSize=3D92233720368547758= 07, maxMergeSizeForForcedMerge=3D9223372036854775807, calibrateSizeByDelete= s=3Dfalse, maxMergeDocs=3D2147483647, maxCFSSegmentSizeMB=3D8.7960930222079= 99E12, noCFSRatio=3D0.5284436844598078] [junit4] 2> 1055064 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.SolrDeletionPolicy SolrDeletionPoli= cy.onCommit: commits: num=3D1 [junit4] 2> =09commit{dir=3DMockDirectoryWrapper(RAMDirectory@2631a3 l= ockFactory=3Dorg.apache.lucene.store.SingleInstanceLockFactory@1ef4da7),seg= FN=3Dsegments_1,generation=3D1} [junit4] 2> 1055064 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.SolrDeletionPolicy newest commit ge= neration =3D 1 [junit4] 2> 1055065 INFO (OldIndexDirectoryCleanupThreadForCore-colle= ction1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1= x:collection1] o.a.s.c.SolrCore Looking for old index directories to clean= up for core collection1 in /home/jenkins/workspace/Lucene-Solr-master-Linux= /solr/build/solr-core/test/J0/../../../../../../../../../home/jenkins/works= pace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.= RecoveryZkTest_FF7B6D4FA437E1D5-001/control-001/cores/collection1/data/ [junit4] 2> 1055065 WARN (OldIndexDirectoryCleanupThreadForCore-colle= ction1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1= x:collection1] o.a.s.c.DirectoryFactory /home/jenkins/workspace/Lucene-Sol= r-master-Linux/solr/build/solr-core/test/J0/../../../../../../../../../home= /jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/te= mp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/control-001/cores/collect= ion1/data/ does not point to a valid data directory; skipping clean-up of o= ld index directories. [junit4] 2> 1055067 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creat= ing updateRequestProcessorChain "nodistrib" [junit4] 2> 1055067 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creat= ing updateRequestProcessorChain "dedupe" [junit4] 2> 1055067 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inser= ting DistributedUpdateProcessorFactory into updateRequestProcessorChain "de= dupe" [junit4] 2> 1055067 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creat= ing updateRequestProcessorChain "stored_sig" [junit4] 2> 1055067 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inser= ting DistributedUpdateProcessorFactory into updateRequestProcessorChain "st= ored_sig" [junit4] 2> 1055067 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creat= ing updateRequestProcessorChain "distrib-dup-test-chain-explicit" [junit4] 2> 1055067 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creat= ing updateRequestProcessorChain "distrib-dup-test-chain-implicit" [junit4] 2> 1055067 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inser= ting DistributedUpdateProcessorFactory into updateRequestProcessorChain "di= strib-dup-test-chain-implicit" [junit4] 2> 1055067 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.SolrCore no updateRequestProcessorC= hain defined as default, creating implicit default [junit4] 2> 1055067 WARN (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.RequestHandlers INVALID paramSet a = in requestHandler {type =3D requestHandler,name =3D /dump,class =3D DumpReq= uestHandler,args =3D {defaults=3D{a=3DA,b=3DB}}} [junit4] 2> 1055068 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.h.l.XMLLoader xsltCacheLifetimeSecond= s=3D60 [junit4] 2> 1055069 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.h.l.XMLLoader xsltCacheLifetimeSecond= s=3D60 [junit4] 2> 1055069 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.h.l.XMLLoader xsltCacheLifetimeSecond= s=3D60 [junit4] 2> 1055070 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.h.l.XMLLoader xsltCacheLifetimeSecond= s=3D60 [junit4] 2> 1055072 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.RequestHandlers Registered paths: /= admin/mbeans,standard,/update/json/docs,/admin/luke,/export,/get,/admin/pro= perties,/update/json,/admin/threads,/dump,/update/csv,/sql,/graph,/admin/se= gments,/admin/system,/replication,/config,/stream,/schema,/admin/plugins,/a= dmin/logging,/admin/ping,/update,/admin/file,/terms [junit4] 2> 1055072 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.SolrCore Using default statsCache c= ache: org.apache.solr.search.stats.LocalStatsCache [junit4] 2> 1055072 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog imple= mentation: org.apache.solr.update.UpdateLog [junit4] 2> 1055072 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: d= ataDir=3D defaultSyncLevel=3DFLUSH numRecordsToKeep=3D100 maxNumLogsToKeep= =3D10 numVersionBuckets=3D65536 [junit4] 2> 1055073 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disa= bled [junit4] 2> 1055073 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disa= bled [junit4] 2> 1055073 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy= wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePoli= cy: minMergeSize=3D1000, mergeFactor=3D26, maxMergeSize=3D92233720368547758= 07, maxMergeSizeForForcedMerge=3D9223372036854775807, calibrateSizeByDelete= s=3Dtrue, maxMergeDocs=3D2147483647, maxCFSSegmentSizeMB=3D8.79609302220799= 9E12, noCFSRatio=3D1.0] [junit4] 2> 1055073 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.SolrDeletionPolicy SolrDeletionPoli= cy.onInit: commits: num=3D1 [junit4] 2> =09commit{dir=3DMockDirectoryWrapper(RAMDirectory@2631a3 l= ockFactory=3Dorg.apache.lucene.store.SingleInstanceLockFactory@1ef4da7),seg= FN=3Dsegments_1,generation=3D1} [junit4] 2> 1055073 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.SolrDeletionPolicy newest commit ge= neration =3D 1 [junit4] 2> 1055074 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher= @678080[collection1] main] [junit4] 2> 1055074 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.c.ZkStateReader Load collection con= fig from: [/collections/control_collection] [junit4] 2> 1055074 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.c.ZkStateReader path=3D[/collection= s/control_collection] [configName]=3D[conf1] specified config exists in Zoo= Keeper [junit4] 2> 1055074 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Setting up Z= ooKeeper-based storage for the RestManager with znodeBase: /configs/conf1 [junit4] 2> 1055074 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Configured Z= ooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 1055074 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.r.RestManager Initializing RestManage= r with initArgs: {} [junit4] 2> 1055074 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Reading _res= t_managed.json using ZooKeeperStorageIO:path=3D/configs/conf1 [junit4] 2> 1055074 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage No data foun= d for znode /configs/conf1/_rest_managed.json [junit4] 2> 1055074 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null = at path _rest_managed.json using ZooKeeperStorageIO:path=3D/configs/conf1 [junit4] 2> 1055074 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.r.RestManager Initializing 0 register= ed ManagedResources [junit4] 2> 1055075 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.h.ReplicationHandler Commits will be = reserved for 10000 [junit4] 2> 1055075 INFO (searcherExecutor-4549-thread-1-processing-n= :127.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_n= ode1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x= :collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Search= er@678080[collection1] main{ExitableDirectoryReader(UninvertingDirectoryRea= der())} [junit4] 2> 1055075 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Looking up max value of v= ersion field to seed version buckets [junit4] 2> 1055076 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.VersionInfo Refreshing highest valu= e of _version_ for 65536 version buckets from index [junit4] 2> 1055076 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.VersionInfo No terms found for _ver= sion_, cannot seed version bucket highest value from index [junit4] 2> 1055076 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Could not find max versio= n in index or recent updates, using new clock 1542734891896012800 [junit4] 2> 1055077 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Took 1.0ms to seed versio= n buckets with highest version 1542734891896012800 [junit4] 2> 1055077 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.ZkController watch zkdir /configs/c= onf1 [junit4] 2> 1055078 INFO (coreLoadExecutor-4548-thread-1-processing-n= :127.0.0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk c:control_collection s:sha= rd1 r:core_node1 x:collection1] o.a.s.c.CoreContainer registering core: col= lection1 [junit4] 2> 1055078 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.ZkController Register replica - core:collection1 addres= s:https://127.0.0.1:38523/z/k collection:control_collection shard:shard1 [junit4] 2> 1055078 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.c.SolrZkClient makePath: /collections/control_collectio= n/leader_elect/shard1/election [junit4] 2> 1055079 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.LeaderElector Joined leadership election with path: /co= llections/control_collection/leader_elect/shard1/election/96420930657910789= -core_node1-n_0000000000 [junit4] 2> 1055079 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.ShardLeaderElectionContext Running the leader process f= or shard=3Dshard1 and weAreReplacement=3Dfalse and leaderVoteWait=3D10000 [junit4] 2> 1055080 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to con= tinue. [junit4] 2> 1055080 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - tr= y and sync [junit4] 2> 1055080 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:38523/z= /k/collection1/ [junit4] 2> 1055080 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.Overse= er processMessage: queueSize: 1, message =3D { [junit4] 2> "operation":"leader", [junit4] 2> "shard":"shard1", [junit4] 2> "collection":"control_collection"} current state version= : 1 [junit4] 2> 1055080 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 1055080 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.SyncStrategy https://127.0.0.1:38523/z/k/collection1/ h= as no replicas [junit4] 2> 1055080 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.c.SolrZkClient makePath: /collections/control_collectio= n/leaders/shard1 [junit4] 2> 1055081 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.ShardLeaderElectionContextBase Creating leader registra= tion node /collections/control_collection/leaders/shard1/leader after winni= ng as /collections/control_collection/leader_elect/shard1/election/96420930= 657910789-core_node1-n_0000000000 [junit4] 2> 1055082 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.ShardLeaderElectionContext I am the new leader: https:/= /127.0.0.1:38523/z/k/collection1/ shard1 [junit4] 2> 1055082 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.Overse= er processMessage: queueSize: 1, message =3D { [junit4] 2> "operation":"leader", [junit4] 2> "shard":"shard1", [junit4] 2> "collection":"control_collection", [junit4] 2> "base_url":"https://127.0.0.1:38523/z/k", [junit4] 2> "core":"collection1", [junit4] 2> "state":"active"} current state version: 1 [junit4] 2> 1055183 INFO (zkCallback-1757-thread-1-processing-n:127.0= .0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ZkStateReader A c= luster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged= path:/clusterstate.json], has occurred - updating... (live nodes size: [1]= ) [junit4] 2> 1055232 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.ZkController We are https://127.0.0.1:38523/z/k/collect= ion1/ and leader is https://127.0.0.1:38523/z/k/collection1/ [junit4] 2> 1055232 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.ZkController No LogReplay needed for core=3Dcollection1= baseURL=3Dhttps://127.0.0.1:38523/z/k [junit4] 2> 1055232 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 1055232 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.ZkController publishing state=3Dactive [junit4] 2> 1055232 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.ZkController numShards not found on descriptor - readin= g it from system property [junit4] 2> 1055233 INFO (coreZkRegister-4541-thread-1-processing-n:1= 27.0.0.1:38523_z%2Fk x:collection1 s:shard1 c:control_collection r:core_nod= e1) [n:127.0.0.1:38523_z%2Fk c:control_collection s:shard1 r:core_node1 x:c= ollection1] o.a.s.c.c.ZkStateReader Checking legacy cluster state for colle= ction control_collection [junit4] 2> 1055233 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.Overse= er processMessage: queueSize: 1, message =3D { [junit4] 2> "core":"collection1", [junit4] 2> "core_node_name":"core_node1", [junit4] 2> "roles":null, [junit4] 2> "base_url":"https://127.0.0.1:38523/z/k", [junit4] 2> "node_name":"127.0.0.1:38523_z%2Fk", [junit4] 2> "numShards":"1", [junit4] 2> "state":"active", [junit4] 2> "shard":"shard1", [junit4] 2> "collection":"control_collection", [junit4] 2> "operation":"state"} current state version: 2 [junit4] 2> 1055233 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.o.Repl= icaMutator Update state numShards=3D1 message=3D{ [junit4] 2> "core":"collection1", [junit4] 2> "core_node_name":"core_node1", [junit4] 2> "roles":null, [junit4] 2> "base_url":"https://127.0.0.1:38523/z/k", [junit4] 2> "node_name":"127.0.0.1:38523_z%2Fk", [junit4] 2> "numShards":"1", [junit4] 2> "state":"active", [junit4] 2> "shard":"shard1", [junit4] 2> "collection":"control_collection", [junit4] 2> "operation":"state"} [junit4] 2> 1055334 INFO (zkCallback-1757-thread-1-processing-n:127.0= .0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ZkStateReader A c= luster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged= path:/clusterstate.json], has occurred - updating... (live nodes size: [1]= ) [junit4] 2> 1055485 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider [junit4] 2> 1055485 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to = ZooKeeper [junit4] 2> 1055486 INFO (zkCallback-1761-thread-1) [ ] o.a.s.c.c.= ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@11= 90092 name:ZooKeeperConnection Watcher:127.0.0.1:43126/solr got event Watch= edEvent state:SyncConnected type:None path:null path:null type:None [junit4] 2> 1055486 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper [junit4] 2> 1055486 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider [junit4] 2> 1055486 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper= ...=20 [junit4] 2> 1055486 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ZkStateReader Loaded cluster properties: {urlScheme= =3Dhttps} [junit4] 2> 1055486 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... = (0) -> (1) [junit4] 2> 1055487 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.ChaosMonkey monkey: init - expire sessions:false caus= e connection loss:false [junit4] 2> 1055547 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/je= nkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/= solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-1-001/cores/collection= 1 [junit4] 2> 1055547 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 1 in direc= tory /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/= test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-1-001 [junit4] 2> 1055549 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314 [junit4] 2> 1055549 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandle= r@1914d80{/z/k,null,AVAILABLE} [junit4] 2> 1055550 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.e.j.s.ServerConnector Started ServerConnector@1346d2{SSL,[s= sl, http/1.1]}{127.0.0.1:32866} [junit4] 2> 1055550 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.e.j.s.Server Started @1057477ms [junit4] 2> 1055551 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir= =3D/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/te= st/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/tempDir-001/jetty= 1, solrconfig=3Dsolrconfig.xml, hostContext=3D/z/k, hostPort=3D32866, coreR= ootDirectory=3D/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/= solr-core/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard= -1-001/cores} [junit4] 2> 1055551 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.s.SolrDispatchFilter SolrDispatchFilter.init(): sun.mis= c.Launcher$AppClassLoader@1d16e93 [junit4] 2> 1055551 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.SolrResourceLoader new SolrResourceLoader for directo= ry: '/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/= test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-1-001' [junit4] 2> 1055551 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.SolrResourceLoader JNDI not configured for solr (NoIn= itialContextEx) [junit4] 2> 1055551 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.SolrResourceLoader solr home defaulted to 'solr/' (co= uld not find system property or JNDI) [junit4] 2> 1055551 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider [junit4] 2> 1055551 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to = ZooKeeper [junit4] 2> 1055552 INFO (zkCallback-1762-thread-1) [ ] o.a.s.c.c.= ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@45= 8081 name:ZooKeeperConnection Watcher:127.0.0.1:43126/solr got event Watche= dEvent state:SyncConnected type:None path:null path:null type:None [junit4] 2> 1055552 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper [junit4] 2> 1055552 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider [junit4] 2> 1055553 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (no= t found in ZooKeeper) [junit4] 2> 1055553 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /h= ome/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0= /temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-1-001/solr.xml [junit4] 2> 1055556 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.CorePropertiesLocator Config-defined core root direct= ory: /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/= test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-1-001/cor= es [junit4] 2> 1055557 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.CoreContainer New CoreContainer 11632674 [junit4] 2> 1055557 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.CoreContainer Loading cores into CoreContainer [insta= nceDir=3D/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-c= ore/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-1-001= ] [junit4] 2> 1055557 WARN (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.CoreContainer Couldn't add files from /home/jenkins/w= orkspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cl= oud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-1-001/lib to classpath: /home= /jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/te= mp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-1-001/lib [junit4] 2> 1055557 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.h.c.HttpShardHandlerFactory created with socketTimeout = : 90000,urlScheme : ,connTimeout : 15000,maxConnectionsPerHost : 20,maxConn= ections : 10000,corePoolSize : 0,maximumPoolSize : 2147483647,maxThreadIdle= Time : 5,sizeOfQueue : -1,fairnessPolicy : false, [junit4] 2> 1055558 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.u.UpdateShardHandler Created UpdateShardHandler HTTP cl= ient with params: socketTimeout=3D340000&connTimeout=3D45000&maxConnections= =3D100000&maxConnectionsPerHost=3D100000 [junit4] 2> 1055558 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.l.LogWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFa= ctory [junit4] 2> 1055558 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.l.LogWatcher Registering Log Listener [Log4j (org.slf4j= .impl.Log4jLoggerFactory)] [junit4] 2> 1055558 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.ZkContainer Zookeeper client=3D127.0.0.1:43126/solr [junit4] 2> 1055559 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.ZkController zkHost includes chroot [junit4] 2> 1055559 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider [junit4] 2> 1055559 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to = ZooKeeper [junit4] 2> 1055559 INFO (zkCallback-1765-thread-1) [ ] o.a.s.c.c.= ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@1a= 81106 name:ZooKeeperConnection Watcher:127.0.0.1:43126 got event WatchedEve= nt state:SyncConnected type:None path:null path:null type:None [junit4] 2> 1055559 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper [junit4] 2> 1055560 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider [junit4] 2> 1055560 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.ZkController Added new OnRecon= nect listener org.apache.solr.cloud.ZkController$$Lambda$87/13543940@1574dc= c [junit4] 2> 1055560 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.c.ConnectionManager Waiting fo= r client to connect to ZooKeeper [junit4] 2> 1055561 INFO (zkCallback-1766-thread-1-processing-n:127.0= .0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.c.ConnectionManager= Watcher org.apache.solr.common.cloud.ConnectionManager@920d46 name:ZooKeep= erConnection Watcher:127.0.0.1:43126/solr got event WatchedEvent state:Sync= Connected type:None path:null path:null type:None [junit4] 2> 1055561 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.c.ConnectionManager Client is = connected to ZooKeeper [junit4] 2> 1055562 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.c.ZkStateReader Updating clust= er state from ZooKeeper...=20 [junit4] 2> 1055563 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.c.ZkStateReader Loaded cluster= properties: {urlScheme=3Dhttps} [junit4] 2> 1055563 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.c.ZkStateReader Updated live n= odes from ZooKeeper... (0) -> (1) [junit4] 2> 1055564 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.Overseer Overseer (id=3Dnull) = closing [junit4] 2> 1055564 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.LeaderElector Joined leadershi= p election with path: /overseer_elect/election/96420930657910793-127.0.0.1:= 32866_z%2Fk-n_0000000001 [junit4] 2> 1055564 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.LeaderElector Watching path /o= verseer_elect/election/96420930657910789-127.0.0.1:38523_z%2Fk-n_0000000000= to know if I could be the leader [junit4] 2> 1055564 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.ZkController Publish node=3D12= 7.0.0.1:32866_z%2Fk as DOWN [junit4] 2> 1055564 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.ZkController Register node as = live in ZooKeeper:/live_nodes/127.0.0.1:32866_z%2Fk [junit4] 2> 1055565 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.c.SolrZkClient makePath: /live= _nodes/127.0.0.1:32866_z%2Fk [junit4] 2> 1055565 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.Overse= er processMessage: queueSize: 1, message =3D { [junit4] 2> "operation":"downnode", [junit4] 2> "node_name":"127.0.0.1:32866_z%2Fk"} current state versi= on: 3 [junit4] 2> 1055565 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.o.Node= Mutator DownNode state invoked for node: 127.0.0.1:32866_z%2Fk [junit4] 2> 1055565 INFO (zkCallback-1757-thread-2-processing-n:127.0= .0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ZkStateReader A l= ive node change: [WatchedEvent state:SyncConnected type:NodeChildrenChanged= path:/live_nodes], has occurred - updating... (live nodes size: [1]) [junit4] 2> 1055565 INFO (zkCallback-1761-thread-1) [ ] o.a.s.c.c.= ZkStateReader A live node change: [WatchedEvent state:SyncConnected type:No= deChildrenChanged path:/live_nodes], has occurred - updating... (live nodes= size: [1]) [junit4] 2> 1055565 INFO (zkCallback-1766-thread-1-processing-n:127.0= .0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.c.ZkStateReader A l= ive node change: [WatchedEvent state:SyncConnected type:NodeChildrenChanged= path:/live_nodes], has occurred - updating... (live nodes size: [1]) [junit4] 2> 1055565 INFO (zkCallback-1757-thread-2-processing-n:127.0= .0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ZkStateReader Upd= ated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 1055565 INFO (zkCallback-1761-thread-1) [ ] o.a.s.c.c.= ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 1055565 INFO (zkCallback-1766-thread-1-processing-n:127.0= .0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.c.ZkStateReader Upd= ated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 1055580 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.CoreContainer Security conf do= esn't exist. Skipping setup for authorization module. [junit4] 2> 1055580 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.CoreContainer No authenticatio= n plugin used. [junit4] 2> 1055580 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.CorePropertiesLocator Looking = for core definitions underneath /home/jenkins/workspace/Lucene-Solr-master-= Linux/solr/build/solr-core/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA= 437E1D5-001/shard-1-001/cores [junit4] 2> 1055581 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.CoreDescriptor Created CoreDes= criptor: {name=3Dcollection1, config=3Dsolrconfig.xml, transient=3Dfalse, s= chema=3Dschema.xml, loadOnStartup=3Dtrue, configSetProperties=3Dconfigsetpr= ops.json, collection=3Dcollection1, coreNodeName=3D, dataDir=3Ddata/, shard= =3D} [junit4] 2> 1055581 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.CorePropertiesLocator Found co= re collection1 in /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/bui= ld/solr-core/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/sh= ard-1-001/cores/collection1 [junit4] 2> 1055581 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.CorePropertiesLocator Found 1 = core definitions [junit4] 2> 1055581 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.ZkController publishing state=3Ddown [junit4] 2> 1055581 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.s.SolrDispatchFilter user.dir=3D= /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/= J0 [junit4] 2> 1055581 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [n:127.0.0.1:32866_z%2Fk ] o.a.s.s.SolrDispatchFilter SolrDispatc= hFilter.init() done [junit4] 2> 1055581 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.ZkController numShards not found on descriptor - reading it fr= om system property [junit4] 2> 1055582 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.ZkController Collection collection1 not visible yet, but flagg= ing it so a watch is registered when it becomes visible [junit4] 2> 1055582 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.Overse= er processMessage: queueSize: 1, message =3D { [junit4] 2> "core":"collection1", [junit4] 2> "roles":null, [junit4] 2> "base_url":"https://127.0.0.1:32866/z/k", [junit4] 2> "node_name":"127.0.0.1:32866_z%2Fk", [junit4] 2> "numShards":"1", [junit4] 2> "state":"down", [junit4] 2> "shard":null, [junit4] 2> "collection":"collection1", [junit4] 2> "operation":"state"} current state version: 3 [junit4] 2> 1055582 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.o.Repl= icaMutator Update state numShards=3D1 message=3D{ [junit4] 2> "core":"collection1", [junit4] 2> "roles":null, [junit4] 2> "base_url":"https://127.0.0.1:32866/z/k", [junit4] 2> "node_name":"127.0.0.1:32866_z%2Fk", [junit4] 2> "numShards":"1", [junit4] 2> "state":"down", [junit4] 2> "shard":null, [junit4] 2> "collection":"collection1", [junit4] 2> "operation":"state"} [junit4] 2> 1055582 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.c.ZkStateReader Deleting data for [collection1] [junit4] 2> 1055582 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.o.Clus= terStateMutator building a new cName: collection1 [junit4] 2> 1055582 INFO (OverseerStateUpdate-96420930657910789-127.0= .0.1:38523_z%2Fk-n_0000000000) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.o.Repl= icaMutator Assigning new node to shard shard=3Dshard1 [junit4] 2> 1055582 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.ZkController look for our core node name [junit4] 2> 1055683 INFO (zkCallback-1761-thread-1) [ ] o.a.s.c.c.= ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected typ= e:NodeDataChanged path:/clusterstate.json], has occurred - updating... (liv= e nodes size: [2]) [junit4] 2> 1055683 INFO (zkCallback-1757-thread-2-processing-n:127.0= .0.1:38523_z%2Fk) [n:127.0.0.1:38523_z%2Fk ] o.a.s.c.c.ZkStateReader A c= luster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged= path:/clusterstate.json], has occurred - updating... (live nodes size: [2]= ) [junit4] 2> 1055684 INFO (zkCallback-1766-thread-1-processing-n:127.0= .0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk ] o.a.s.c.c.ZkStateReader A c= luster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged= path:/clusterstate.json], has occurred - updating... (live nodes size: [2]= ) [junit4] 2> 1056583 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.ZkController waiting to find shard id in clusterstate for coll= ection1 [junit4] 2> 1056583 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.ZkController Check for collection zkNode:collection1 [junit4] 2> 1056583 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.ZkController Collection zkNode exists [junit4] 2> 1056583 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.c.ZkStateReader Load collection config from: [/collections/col= lection1] [junit4] 2> 1056584 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.c.ZkStateReader path=3D[/collections/collection1] [configName]= =3D[conf1] specified config exists in ZooKeeper [junit4] 2> 1056584 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.SolrResourceLoader new SolrResourceLoader for directory: '/hom= e/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/t= emp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-1-001/cores/collec= tion1' [junit4] 2> 1056584 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.SolrResourceLoader JNDI not configured for solr (NoInitialCont= extEx) [junit4] 2> 1056584 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.SolrResourceLoader solr home defaulted to 'solr/' (could not f= ind system property or JNDI) [junit4] 2> 1056585 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.Config loaded config solrconfig.xml with version 0=20 [junit4] 2> 1056588 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.SolrConfig current version of requestparams : -1 [junit4] 2> 1056590 WARN (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.Config Beginning with Solr 5.5, is deprecated, u= se instead. [junit4] 2> 1056590 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0 [junit4] 2> 1056597 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.SolrConfig Loaded SolrConfig: solrconfig.xml [junit4] 2> 1056600 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.s.IndexSchema [collection1] Schema name=3Dtest [junit4] 2> 1056680 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.s.IndexSchema default search field in schema is text [junit4] 2> 1056682 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.s.IndexSchema unique key field: id [junit4] 2> 1056682 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.s.FileExchangeRateProvider Reloading exchange rates from file cu= rrency.xml [junit4] 2> 1056684 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.s.FileExchangeRateProvider Reloading exchange rates from file cu= rrency.xml [junit4] 2> 1056690 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.ConfigSetProperties Did not find ConfigSet properties, assumin= g default properties: Can't find resource 'configsetprops.json' in classpat= h or '/configs/conf1', cwd=3D/home/jenkins/workspace/Lucene-Solr-master-Lin= ux/solr/build/solr-core/test/J0 [junit4] 2> 1056690 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 x:collecti= on1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configurat= ion from collection collection1 [junit4] 2> 1056690 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 s:shard1 r:c= ore_node1 x:collection1] o.a.s.c.SolrCore org.apache.solr.core.MockDirector= yFactory [junit4] 2> 1056690 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 s:shard1 r:c= ore_node1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new Solr= Core at [/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-c= ore/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-1-001= /cores/collection1], dataDir=3D[/home/jenkins/workspace/Lucene-Solr-master-= Linux/solr/build/solr-core/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA= 437E1D5-001/shard-1-001/cores/collection1/data/] [junit4] 2> 1056690 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 s:shard1 r:c= ore_node1 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled.= Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1= 6fc28e [junit4] 2> 1056691 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 s:shard1 r:c= ore_node1 x:collection1] o.a.s.c.CachingDirectoryFactory return new directo= ry for /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-cor= e/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-1-001/c= ores/collection1/data/snapshot_metadata [junit4] 2> 1056691 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 s:shard1 r:c= ore_node1 x:collection1] o.a.s.c.s.SolrSnapshotMetaDataManager Loading from= snapshot metadata file... [junit4] 2> 1056691 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 s:shard1 r:c= ore_node1 x:collection1] o.a.s.c.CachingDirectoryFactory return new directo= ry for /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-cor= e/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-1-001/c= ores/collection1/data [junit4] 2> 1056691 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 s:shard1 r:c= ore_node1 x:collection1] o.a.s.c.SolrCore New index directory detected: old= =3Dnull new=3D/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/s= olr-core/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-= 1-001/cores/collection1/data/index/ [junit4] 2> 1056691 WARN (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 s:shard1 r:c= ore_node1 x:collection1] o.a.s.c.SolrCore [collection1] Solr index director= y '/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/te= st/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-1-001/cores= /collection1/data/index' doesn't exist. Creating new index... [junit4] 2> 1056691 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 s:shard1 r:c= ore_node1 x:collection1] o.a.s.c.CachingDirectoryFactory return new directo= ry for /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-cor= e/test/J0/temp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-1-001/c= ores/collection1/data/index [junit4] 2> 1056691 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 s:shard1 r:c= ore_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrappi= ng class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: min= MergeSize=3D1000, mergeFactor=3D25, maxMergeSize=3D9223372036854775807, max= MergeSizeForForcedMerge=3D9223372036854775807, calibrateSizeByDeletes=3Dfal= se, maxMergeDocs=3D2147483647, maxCFSSegmentSizeMB=3D8.796093022207999E12, = noCFSRatio=3D0.5284436844598078] [junit4] 2> 1056692 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 s:shard1 r:c= ore_node1 x:collection1] o.a.s.c.SolrDeletionPolicy SolrDeletionPolicy.onCo= mmit: commits: num=3D1 [junit4] 2> =09commit{dir=3DMockDirectoryWrapper(RAMDirectory@19970a2 = lockFactory=3Dorg.apache.lucene.store.SingleInstanceLockFactory@168b5ca),se= gFN=3Dsegments_1,generation=3D1} [junit4] 2> 1056692 INFO (coreLoadExecutor-4559-thread-1-processing-n= :127.0.0.1:32866_z%2Fk) [n:127.0.0.1:32866_z%2Fk c:collection1 s:shard1 r:c= ore_node1 x:collection1] o.a.s.c.SolrDeletionPolicy newest commit generatio= n =3D 1 [junit4] 2> 1056692 INFO (OldI [...truncated too long message...] [n:127.0.0.1:32925_z%2Fk c:collection1 s:shard1 r:core_node2 x:collection1]= o.a.s.c.CachingDirectoryFactory Closing directory, CoreContainer#isShutdow= n=3Dtrue [junit4] 2> 1090529 INFO (zkCallback-1779-thread-1-processing-n:127.0= .0.1:32925_z%2Fk) [n:127.0.0.1:32925_z%2Fk c:collection1 s:shard1 r:core_no= de2 x:collection1] o.a.s.c.CachingDirectoryFactory Closing directory: /home= /jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/te= mp/solr.cloud.RecoveryZkTest_FF7B6D4FA437E1D5-001/shard-2-001/cores/collect= ion1/data/snapshot_metadata [junit4] 2> 1090529 INFO (zkCallback-1779-thread-1-processing-n:127.0= .0.1:32925_z%2Fk) [n:127.0.0.1:32925_z%2Fk c:collection1 s:shard1 r:core_no= de2 x:collection1] o.a.s.c.ElectionContext Canceling election /collections/= collection1/leader_elect/shard1/election/96420930657910799-core_node2-n_000= 0000002 [junit4] 2> 1090529 WARN (zkCallback-1779-thread-1-processing-n:127.0= .0.1:32925_z%2Fk) [n:127.0.0.1:32925_z%2Fk c:collection1 s:shard1 r:core_no= de2 x:collection1] o.a.s.c.LeaderElector=20 [junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredExcepti= on: KeeperErrorCode =3D Session expired for /collections/collection1/leader= _elect/shard1/election/96420930657910799-core_node2-n_0000000002 [junit4] 2> =09at org.apache.zookeeper.KeeperException.create(KeeperEx= ception.java:127) [junit4] 2> =09at org.apache.zookeeper.KeeperException.create(KeeperEx= ception.java:51) [junit4] 2> =09at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java= :873) [junit4] 2> =09at org.apache.solr.common.cloud.SolrZkClient$2.execute(= SolrZkClient.java:244) [junit4] 2> =09at org.apache.solr.common.cloud.SolrZkClient$2.execute(= SolrZkClient.java:241) [junit4] 2> =09at org.apache.solr.common.cloud.ZkCmdExecutor.retryOper= ation(ZkCmdExecutor.java:60) [junit4] 2> =09at org.apache.solr.common.cloud.SolrZkClient.delete(Sol= rZkClient.java:241) [junit4] 2> =09at org.apache.solr.cloud.ElectionContext.cancelElection= (ElectionContext.java:85) [junit4] 2> =09at org.apache.solr.cloud.ShardLeaderElectionContextBase= .cancelElection(ElectionContext.java:142) [junit4] 2> =09at org.apache.solr.cloud.ShardLeaderElectionContext.can= celElection(ElectionContext.java:274) [junit4] 2> =09at org.apache.solr.cloud.ShardLeaderElectionContext.run= LeaderProcess(ElectionContext.java:450) [junit4] 2> =09at org.apache.solr.cloud.LeaderElector.runIamLeaderProc= ess(LeaderElector.java:170) [junit4] 2> =09at org.apache.solr.cloud.LeaderElector.checkIfIamLeader= (LeaderElector.java:135) [junit4] 2> =09at org.apache.solr.cloud.LeaderElector.access$200(Leade= rElector.java:56) [junit4] 2> =09at org.apache.solr.cloud.LeaderElector$ElectionWatcher.= process(LeaderElector.java:348) [junit4] 2> =09at org.apache.solr.common.cloud.SolrZkClient$3.lambda$p= rocess$0(SolrZkClient.java:266) [junit4] 2> =09at java.util.concurrent.Executors$RunnableAdapter.call(= Executors.java:511) [junit4] 2> =09at java.util.concurrent.FutureTask.run(FutureTask.java:= 266) [junit4] 2> =09at org.apache.solr.common.util.ExecutorUtil$MDCAwareThr= eadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229) [junit4] 2> =09at java.util.concurrent.ThreadPoolExecutor.runWorker(Th= readPoolExecutor.java:1142) [junit4] 2> =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(T= hreadPoolExecutor.java:617) [junit4] 2> =09at java.lang.Thread.run(Thread.java:745) [junit4] 2> 1090531 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.e.j.s.ServerConnector Stopped ServerConnector@1f84a80{SSL,[= ssl, http/1.1]}{127.0.0.1:32925} [junit4] 2> 1090531 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandle= r@3a6c0d{/z/k,null,UNAVAILABLE} [junit4] 2> 1090532 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.ChaosMonkey monkey: stop shard! 38523 [junit4] 2> 1090532 INFO (TEST-RecoveryZkTest.test-seed#[FF7B6D4FA437= E1D5]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:43126 43126 [junit4] 2> 1090686 INFO (Thread-2124) [ ] o.a.s.c.ZkTestServer co= nnecting to 127.0.0.1:43126 43126 [junit4] 2> 1090686 WARN (Thread-2124) [ ] o.a.s.c.ZkTestServer Wa= tch limit violations:=20 [junit4] 2> Maximum concurrent create/delete watches above limit: [junit4] 2>=20 [junit4] 2> =095=09/solr/aliases.json [junit4] 2> =094=09/solr/security.json [junit4] 2> =094=09/solr/configs/conf1 [junit4] 2> =093=09/solr/collections/collection1/state.json [junit4] 2>=20 [junit4] 2> Maximum concurrent data watches above limit: [junit4] 2>=20 [junit4] 2> =095=09/solr/clusterstate.json [junit4] 2> =095=09/solr/clusterprops.json [junit4] 2> =092=09/solr/collections/collection1/leader_elect/shard1/e= lection/96420930657910793-core_node1-n_0000000000 [junit4] 2> =092=09/solr/overseer_elect/election/96420930657910793-127= .0.0.1:32866_z%2Fk-n_0000000001 [junit4] 2>=20 [junit4] 2> Maximum concurrent children watches above limit: [junit4] 2>=20 [junit4] 2> =0965=09/solr/overseer/queue [junit4] 2> =0936=09/solr/overseer/collection-queue-work [junit4] 2> =095=09/solr/collections [junit4] 2> =094=09/solr/live_nodes [junit4] 2> =094=09/solr/overseer/queue-work [junit4] 2>=20 [junit4] 2> NOTE: reproduce with: ant test -Dtestcase=3DRecoveryZkTes= t -Dtests.method=3Dtest -Dtests.seed=3DFF7B6D4FA437E1D5 -Dtests.multiplier= =3D3 -Dtests.slow=3Dtrue -Dtests.locale=3Dhr-HR -Dtests.timezone=3DAtlantic= /Bermuda -Dtests.asserts=3Dtrue -Dtests.file.encoding=3DUS-ASCII [junit4] ERROR 36.9s J0 | RecoveryZkTest.test <<< [junit4] > Throwable #1: com.carrotsearch.randomizedtesting.UncaughtE= xceptionError: Captured an uncaught exception in thread: Thread[id=3D9352, = name=3DupdateExecutor-1763-thread-3, state=3DRUNNABLE, group=3DTGRP-Recover= yZkTest] [junit4] > =09at __randomizedtesting.SeedInfo.seed([FF7B6D4FA437E1D5:= 772F52950ACB8C2D]:0) [junit4] > Caused by: org.apache.solr.common.SolrException: Replica: = https://127.0.0.1:32925/z/k/collection1/ should have been marked under lead= er initiated recovery in ZkController but wasn't. [junit4] > =09at __randomizedtesting.SeedInfo.seed([FF7B6D4FA437E1D5]= :0) [junit4] > =09at org.apache.solr.cloud.LeaderInitiatedRecoveryThread.= run(LeaderInitiatedRecoveryThread.java:88) [junit4] > =09at org.apache.solr.common.util.ExecutorUtil$MDCAwareThr= eadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229) [junit4] > =09at java.util.concurrent.ThreadPoolExecutor.runWorker(Th= readPoolExecutor.java:1142) [junit4] > =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(T= hreadPoolExecutor.java:617) [junit4] > =09at java.lang.Thread.run(Thread.java:745) [junit4] 2> 1090689 INFO (SUITE-RecoveryZkTest-seed#[FF7B6D4FA437E1D5= ]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore [junit4] 2> NOTE: test params are: codec=3DAsserting(Lucene62): {rnd_b= =3DLucene50(blocksize=3D128), _version_=3DPostingsFormat(name=3DMockRandom)= , a_t=3DPostingsFormat(name=3DMemory doPackFST=3D false), a_i=3DLucene50(bl= ocksize=3D128), id=3DLucene50(blocksize=3D128)}, docValues:{}, maxPointsInL= eafNode=3D676, maxMBSortInHeap=3D5.325752622021825, sim=3DRandomSimilarity(= queryNorm=3Dtrue): {}, locale=3Dhr-HR, timezone=3DAtlantic/Bermuda [junit4] 2> NOTE: Linux 4.4.0-31-generic i386/Oracle Corporation 1.8.0= _102 (32-bit)/cpus=3D12,threads=3D1,free=3D288726920,total=3D518979584 [junit4] 2> NOTE: All tests run in this JVM: [TestJsonFacets, TestColl= ectionAPI, TestFieldCacheSanityChecker, DataDrivenBlockJoinTest, StandardRe= questHandlerTest, TestDocSet, TestRangeQuery, TestSolrConfigHandler, DisMax= RequestHandlerTest, HLLUtilTest, SyncSliceTest, TestRandomFlRTGCloud, Secur= ityConfHandlerTest, CachingDirectoryFactoryTest, HdfsChaosMonkeyNothingIsSa= feTest, TestFastOutputStream, TestRemoteStreaming, TestSSLRandomization, Te= stRandomFaceting, TestHighFrequencyDictionaryFactory, TestManagedResourceSt= orage, BigEndianAscendingWordDeserializerTest, TestReqParamsAPI, IndexSchem= aRuntimeFieldTest, TestSolrCloudWithDelegationTokens, DateFieldTest, CdcrRe= questHandlerTest, TestFieldCacheVsDocValues, TestBadConfig, CursorPagingTes= t, TestCloudInspectUtil, DefaultValueUpdateProcessorTest, OverseerTaskQueue= Test, CollectionStateFormat2Test, TestDistributedSearch, CheckHdfsIndexTest= , CloudMLTQParserTest, HighlighterMaxOffsetTest, TestHighlightDedupGrouping= , RequiredFieldsTest, TestSolr4Spatial, TestReplicaProperties, TestSortByMi= nMaxFunction, SolrXmlInZkTest, RAMDirectoryFactoryTest, AlternateDirectoryT= est, TestLazyCores, OutputWriterTest, TestNRTOpen, SolrRequestParserTest, T= estFieldResource, TestSchemaNameResource, JSONWriterTest, DocExpirationUpda= teProcessorFactoryTest, DeleteInactiveReplicaTest, BasicZkTest, TestLMDiric= hletSimilarityFactory, UUIDFieldTest, EchoParamsTest, TestReplicationHandle= r, TestAddFieldRealTimeGet, HdfsTlogReplayBufferedWhileIndexingTest, SolrCo= reTest, ExplicitHLLTest, DistributedExpandComponentTest, TestConfigSetsAPIZ= kFailure, TestLuceneMatchVersion, IndexSchemaTest, ZkNodePropsTest, TestNoO= pRegenerator, TestOmitPositions, TestAnalyzedSuggestions, StressHdfsTest, T= estStressLucene, FacetPivotSmallTest, CacheHeaderTest, ConnectionManagerTes= t, TestFoldingMultitermQuery, ZkStateWriterTest, TestImplicitCoreProperties= , ResponseLogComponentTest, AtomicUpdatesTest, TestSimpleQParserPlugin, Tes= tRandomCollapseQParserPlugin, TestSolrCoreSnapshots, CdcrBootstrapTest, Tes= tSchemaVersionResource, TestCrossCoreJoin, DistribCursorPagingTest, TestRTG= Base, TestBlendedInfixSuggestions, TestSolrConfigHandlerCloud, TestCloudMan= agedSchema, TestLRUCache, TestRandomDVFaceting, TestPhraseSuggestions, Test= ConfigSetProperties, TestArbitraryIndexDir, DocumentAnalysisRequestHandlerT= est, TestPseudoReturnFields, FileBasedSpellCheckerTest, TestManagedSynonymF= ilterFactory, OverseerTest, LeaderElectionIntegrationTest, ShardRoutingTest= , RecoveryZkTest] [junit4] Completed [272/629 (1!)] on J0 in 37.01s, 1 test, 1 error <<< F= AILURES! [...truncated 53556 lines...] ------=_Part_176_222535611.1471268259476 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_176_222535611.1471268259476--