From dev-return-327540-archive-asf-public=cust-asf.ponee.io@lucene.apache.org Thu Jul 5 23:21:10 2018 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by mx-eu-01.ponee.io (Postfix) with SMTP id 721AC180657 for ; Thu, 5 Jul 2018 23:21:08 +0200 (CEST) Received: (qmail 28873 invoked by uid 500); 5 Jul 2018 21:21:07 -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 28857 invoked by uid 99); 5 Jul 2018 21:21:06 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd2-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 05 Jul 2018 21:21:06 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd2-us-west.apache.org (ASF Mail Server at spamd2-us-west.apache.org) with ESMTP id 0A60C1A3DAE for ; Thu, 5 Jul 2018 21:21:06 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd2-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -0.3 X-Spam-Level: X-Spam-Status: No, score=-0.3 tagged_above=-999 required=6.31 tests=[KAM_BADIPHTTP=2, RCVD_IN_DNSWL_MED=-2.3, SPF_PASS=-0.001, WEIRD_PORT=0.001] autolearn=disabled Received: from mx1-lw-eu.apache.org ([10.40.0.8]) by localhost (spamd2-us-west.apache.org [10.40.0.9]) (amavisd-new, port 10024) with ESMTP id Qgg_trQmWum3 for ; Thu, 5 Jul 2018 21:20:53 +0000 (UTC) Received: from serv1.sd-datasolutions.de (serv1.sd-datasolutions.de [88.99.242.108]) by mx1-lw-eu.apache.org (ASF Mail Server at mx1-lw-eu.apache.org) with ESMTP id DD63C5F430 for ; Thu, 5 Jul 2018 21:20:52 +0000 (UTC) Received: from serv1 (ip6-localhost [IPv6:::1]) by serv1.sd-datasolutions.de (Postfix) with ESMTP id 9D52010805C6; Thu, 5 Jul 2018 21:20:52 +0000 (UTC) Date: Thu, 5 Jul 2018 21:19:29 +0000 (UTC) From: Policeman Jenkins Server To: sarowe@apache.org, dev@lucene.apache.org Message-ID: <1707127767.41.1530825652645.JavaMail.jenkins@serv1.sd-datasolutions.de> In-Reply-To: <1259044464.37.1530813935524.JavaMail.jenkins@serv1.sd-datasolutions.de> References: <1259044464.37.1530813935524.JavaMail.jenkins@serv1.sd-datasolutions.de> Subject: [JENKINS] Lucene-Solr-7.x-Linux (32bit/jdk1.8.0_172) - Build # 2267 - Still Unstable! MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----=_Part_40_975153955.1530825652591" X-Jenkins-Job: Lucene-Solr-7.x-Linux X-Jenkins-Result: UNSTABLE ------=_Part_40_975153955.1530825652591 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Build: https://jenkins.thetaphi.de/job/Lucene-Solr-7.x-Linux/2267/ Java: 32bit/jdk1.8.0_172 -client -XX:+UseSerialGC 2 tests failed. FAILED: org.apache.solr.cloud.cdcr.CdcrBidirectionalTest.testBiDir Error Message: Captured an uncaught exception in thread: Thread[id=3D224, name=3Dcdcr-repl= icator-61-thread-1, state=3DRUNNABLE, group=3DTGRP-CdcrBidirectionalTest] Stack Trace: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an unca= ught exception in thread: Thread[id=3D224, name=3Dcdcr-replicator-61-thread= -1, state=3DRUNNABLE, group=3DTGRP-CdcrBidirectionalTest] =09at __randomizedtesting.SeedInfo.seed([51D0AC1134D69078:140B5CF32CF8DC3A]= :0) Caused by: java.lang.AssertionError: 1605186670842347520 !=3D 1605186670636= 826624 =09at __randomizedtesting.SeedInfo.seed([51D0AC1134D69078]:0) =09at org.apache.solr.update.CdcrUpdateLog$CdcrLogReader.forwardSeek(CdcrUp= dateLog.java:611) =09at org.apache.solr.handler.CdcrReplicator.run(CdcrReplicator.java:125) =09at org.apache.solr.handler.CdcrReplicatorScheduler.lambda$null$0(CdcrRep= licatorScheduler.java:81) =09at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.l= ambda$execute$0(ExecutorUtil.java:209) =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.= java:1149) =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor= .java:624) =09at java.lang.Thread.run(Thread.java:748) FAILED: org.apache.solr.cloud.cdcr.CdcrBidirectionalTest.testBiDir Error Message: Captured an uncaught exception in thread: Thread[id=3D3022, name=3Dcdcr-rep= licator-798-thread-1, state=3DRUNNABLE, group=3DTGRP-CdcrBidirectionalTest] Stack Trace: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an unca= ught exception in thread: Thread[id=3D3022, name=3Dcdcr-replicator-798-thre= ad-1, state=3DRUNNABLE, group=3DTGRP-CdcrBidirectionalTest] Caused by: java.lang.AssertionError: 1605183060818526208 !=3D 1605183060816= 429056 =09at __randomizedtesting.SeedInfo.seed([51D0AC1134D69078]:0) =09at org.apache.solr.update.CdcrUpdateLog$CdcrLogReader.forwardSeek(CdcrUp= dateLog.java:611) =09at org.apache.solr.handler.CdcrReplicator.run(CdcrReplicator.java:125) =09at org.apache.solr.handler.CdcrReplicatorScheduler.lambda$null$0(CdcrRep= licatorScheduler.java:81) =09at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.l= ambda$execute$0(ExecutorUtil.java:209) =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.= java:1149) =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor= .java:624) =09at java.lang.Thread.run(Thread.java:748) Build Log: [...truncated 12620 lines...] [junit4] Suite: org.apache.solr.cloud.cdcr.CdcrBidirectionalTest [junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-7.x-= Linux/solr/build/solr-core/test/J0/temp/solr.cloud.cdcr.CdcrBidirectionalTe= st_51D0AC1134D69078-001/init-core-data-001 [junit4] 2> 229096 WARN (SUITE-CdcrBidirectionalTest-seed#[51D0AC1134= D69078]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpen= s=3D7 numCloses=3D7 [junit4] 2> 229096 INFO (SUITE-CdcrBidirectionalTest-seed#[51D0AC1134= D69078]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POIN= TS_SYSPROP=3Dtrue) w/NUMERIC_DOCVALUES_SYSPROP=3Dfalse [junit4] 2> 229098 INFO (SUITE-CdcrBidirectionalTest-seed#[51D0AC1134= D69078]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clien= tAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=3D, ssl=3DNaN,= value=3DNaN, clientAuth=3DNaN) [junit4] 2> 229098 INFO (SUITE-CdcrBidirectionalTest-seed#[51D0AC1134= D69078]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: tes= t.solr.allowed.securerandom=3Dnull & java.security.egd=3Dfile:/dev/./urando= m [junit4] 2> 229107 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testBiDir [junit4] 2> 229107 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 1= servers in /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-c= ore/test/J0/temp/solr.cloud.cdcr.CdcrBidirectionalTest_51D0AC1134D69078-001= /cdcr-cluster2-001 [junit4] 2> 229107 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER [junit4] 2> 229108 INFO (Thread-435) [ ] o.a.s.c.ZkTestServer clie= nt port:0.0.0.0/0.0.0.0:0 [junit4] 2> 229108 INFO (Thread-435) [ ] o.a.s.c.ZkTestServer Star= ting server [junit4] 2> 229111 ERROR (Thread-435) [ ] o.a.z.s.ZooKeeperServer Z= KShutdownHandler is not registered, so ZooKeeper server won't take any acti= on on ERROR or SHUTDOWN server state changes [junit4] 2> 229208 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.c.ZkTestServer start zk server on port:44649 [junit4] 2> 229224 INFO (zkConnectionManagerCallback-433-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 229259 INFO (jetty-launcher-430-thread-1) [ ] o.e.j.s.= Server jetty-9.4.11.v20180605; built: 2018-06-05T18:24:03.829Z; git: d5fc05= 23cfa96bfebfbda19606cad384d772f04c; jvm 1.8.0_172-b11 [junit4] 2> 229260 INFO (jetty-launcher-430-thread-1) [ ] o.e.j.s.= session DefaultSessionIdManager workerName=3Dnode0 [junit4] 2> 229260 INFO (jetty-launcher-430-thread-1) [ ] o.e.j.s.= session No SessionScavenger set, using defaults [junit4] 2> 229260 INFO (jetty-launcher-430-thread-1) [ ] o.e.j.s.= session node0 Scavenging every 660000ms [junit4] 2> 229261 INFO (jetty-launcher-430-thread-1) [ ] o.e.j.s.= h.ContextHandler Started o.e.j.s.ServletContextHandler@1804f8f{/solr,null,A= VAILABLE} [junit4] 2> 229266 INFO (jetty-launcher-430-thread-1) [ ] o.e.j.s.= AbstractConnector Started ServerConnector@124453d{SSL,[ssl, http/1.1]}{127.= 0.0.1:39865} [junit4] 2> 229266 INFO (jetty-launcher-430-thread-1) [ ] o.e.j.s.= Server Started @229291ms [junit4] 2> 229267 INFO (jetty-launcher-430-thread-1) [ ] o.a.s.c.= s.e.JettySolrRunner Jetty properties: {hostContext=3D/solr, hostPort=3D3986= 5} [junit4] 2> 229267 ERROR (jetty-launcher-430-thread-1) [ ] o.a.s.u.= StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missin= g or incomplete. [junit4] 2> 229267 INFO (jetty-launcher-430-thread-1) [ ] o.a.s.s.= SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLogge= rFactory [junit4] 2> 229267 INFO (jetty-launcher-430-thread-1) [ ] o.a.s.s.= SolrDispatchFilter ___ _ Welcome to Apache Solr=E2=84=A2 versio= n 7.5.0 [junit4] 2> 229267 INFO (jetty-launcher-430-thread-1) [ ] o.a.s.s.= SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 229267 INFO (jetty-launcher-430-thread-1) [ ] o.a.s.s.= SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 229267 INFO (jetty-launcher-430-thread-1) [ ] o.a.s.s.= SolrDispatchFilter |___/\___/_|_| Start time: 2018-07-05T20:17:17.507Z [junit4] 2> 229270 INFO (zkConnectionManagerCallback-435-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 229270 INFO (jetty-launcher-430-thread-1) [ ] o.a.s.s.= SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 229773 INFO (jetty-launcher-430-thread-1) [ ] o.a.s.c.= ZkContainer Zookeeper client=3D127.0.0.1:44649/solr [junit4] 2> 229774 INFO (zkConnectionManagerCallback-439-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 229776 INFO (zkConnectionManagerCallback-441-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 229825 INFO (jetty-launcher-430-thread-1) [n:127.0.0.1:39= 865_solr ] o.a.s.c.Overseer Overseer (id=3Dnull) closing [junit4] 2> 229826 INFO (jetty-launcher-430-thread-1) [n:127.0.0.1:39= 865_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 1= 27.0.0.1:39865_solr [junit4] 2> 229826 INFO (jetty-launcher-430-thread-1) [n:127.0.0.1:39= 865_solr ] o.a.s.c.Overseer Overseer (id=3D72076665943949315-127.0.0.1:3= 9865_solr-n_0000000000) starting [junit4] 2> 229831 INFO (zkConnectionManagerCallback-448-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 229833 INFO (jetty-launcher-430-thread-1) [n:127.0.0.1:39= 865_solr ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1= :44649/solr ready [junit4] 2> 229833 INFO (jetty-launcher-430-thread-1) [n:127.0.0.1:39= 865_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live= _nodes/127.0.0.1:39865_solr [junit4] 2> 229835 INFO (OverseerStateUpdate-72076665943949315-127.0.= 0.1:39865_solr-n_0000000000) [ ] o.a.s.c.c.ZkStateReader Updated live no= des from ZooKeeper... (0) -> (1) [junit4] 2> 229838 INFO (zkCallback-447-thread-1) [ ] o.a.s.c.c.Zk= StateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 229865 INFO (jetty-launcher-430-thread-1) [n:127.0.0.1:39= 865_solr ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keepin= g metrics history in memory. [junit4] 2> 229888 INFO (jetty-launcher-430-thread-1) [n:127.0.0.1:39= 865_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_39865.solr= .node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.Jm= xMBeanServer@18f6f32 [junit4] 2> 229895 INFO (jetty-launcher-430-thread-1) [n:127.0.0.1:39= 865_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_39865.solr= .jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxM= BeanServer@18f6f32 [junit4] 2> 229895 INFO (jetty-launcher-430-thread-1) [n:127.0.0.1:39= 865_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_39865.solr= .jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.= JmxMBeanServer@18f6f32 [junit4] 2> 229896 INFO (jetty-launcher-430-thread-1) [n:127.0.0.1:39= 865_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions undern= eath /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/tes= t/J0/temp/solr.cloud.cdcr.CdcrBidirectionalTest_51D0AC1134D69078-001/cdcr-c= luster2-001/node1/. [junit4] 2> 229910 INFO (zkConnectionManagerCallback-451-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 229914 INFO (zkConnectionManagerCallback-454-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 229915 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 1= servers in /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-c= ore/test/J0/temp/solr.cloud.cdcr.CdcrBidirectionalTest_51D0AC1134D69078-001= /cdcr-cluster1-001 [junit4] 2> 229915 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER [junit4] 2> 229915 INFO (Thread-445) [ ] o.a.s.c.ZkTestServer clie= nt port:0.0.0.0/0.0.0.0:0 [junit4] 2> 229915 INFO (Thread-445) [ ] o.a.s.c.ZkTestServer Star= ting server [junit4] 2> 229918 ERROR (Thread-445) [ ] o.a.z.s.ZooKeeperServer Z= KShutdownHandler is not registered, so ZooKeeper server won't take any acti= on on ERROR or SHUTDOWN server state changes [junit4] 2> 230015 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.c.ZkTestServer start zk server on port:33897 [junit4] 2> 230019 INFO (zkConnectionManagerCallback-458-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 230028 INFO (jetty-launcher-455-thread-1) [ ] o.e.j.s.= Server jetty-9.4.11.v20180605; built: 2018-06-05T18:24:03.829Z; git: d5fc05= 23cfa96bfebfbda19606cad384d772f04c; jvm 1.8.0_172-b11 [junit4] 2> 230028 INFO (jetty-launcher-455-thread-1) [ ] o.e.j.s.= session DefaultSessionIdManager workerName=3Dnode0 [junit4] 2> 230028 INFO (jetty-launcher-455-thread-1) [ ] o.e.j.s.= session No SessionScavenger set, using defaults [junit4] 2> 230029 INFO (jetty-launcher-455-thread-1) [ ] o.e.j.s.= session node0 Scavenging every 600000ms [junit4] 2> 230029 INFO (jetty-launcher-455-thread-1) [ ] o.e.j.s.= h.ContextHandler Started o.e.j.s.ServletContextHandler@f5ab0d{/solr,null,AV= AILABLE} [junit4] 2> 230029 INFO (jetty-launcher-455-thread-1) [ ] o.e.j.s.= AbstractConnector Started ServerConnector@fef35d{SSL,[ssl, http/1.1]}{127.0= .0.1:37317} [junit4] 2> 230029 INFO (jetty-launcher-455-thread-1) [ ] o.e.j.s.= Server Started @230055ms [junit4] 2> 230030 INFO (jetty-launcher-455-thread-1) [ ] o.a.s.c.= s.e.JettySolrRunner Jetty properties: {hostContext=3D/solr, hostPort=3D3731= 7} [junit4] 2> 230030 ERROR (jetty-launcher-455-thread-1) [ ] o.a.s.u.= StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missin= g or incomplete. [junit4] 2> 230031 INFO (jetty-launcher-455-thread-1) [ ] o.a.s.s.= SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLogge= rFactory [junit4] 2> 230031 INFO (jetty-launcher-455-thread-1) [ ] o.a.s.s.= SolrDispatchFilter ___ _ Welcome to Apache Solr=E2=84=A2 versio= n 7.5.0 [junit4] 2> 230031 INFO (jetty-launcher-455-thread-1) [ ] o.a.s.s.= SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 230031 INFO (jetty-launcher-455-thread-1) [ ] o.a.s.s.= SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 230031 INFO (jetty-launcher-455-thread-1) [ ] o.a.s.s.= SolrDispatchFilter |___/\___/_|_| Start time: 2018-07-05T20:17:18.271Z [junit4] 2> 230033 INFO (zkConnectionManagerCallback-460-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 230033 INFO (jetty-launcher-455-thread-1) [ ] o.a.s.s.= SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 231221 INFO (jetty-launcher-455-thread-1) [ ] o.a.s.c.= ZkContainer Zookeeper client=3D127.0.0.1:33897/solr [junit4] 2> 231223 INFO (zkConnectionManagerCallback-464-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 231225 INFO (zkConnectionManagerCallback-466-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 231274 INFO (jetty-launcher-455-thread-1) [n:127.0.0.1:37= 317_solr ] o.a.s.c.Overseer Overseer (id=3Dnull) closing [junit4] 2> 231275 INFO (jetty-launcher-455-thread-1) [n:127.0.0.1:37= 317_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 1= 27.0.0.1:37317_solr [junit4] 2> 231275 INFO (jetty-launcher-455-thread-1) [n:127.0.0.1:37= 317_solr ] o.a.s.c.Overseer Overseer (id=3D72076665996836867-127.0.0.1:3= 7317_solr-n_0000000000) starting [junit4] 2> 231280 INFO (zkConnectionManagerCallback-473-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 231282 INFO (jetty-launcher-455-thread-1) [n:127.0.0.1:37= 317_solr ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1= :33897/solr ready [junit4] 2> 231283 INFO (jetty-launcher-455-thread-1) [n:127.0.0.1:37= 317_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live= _nodes/127.0.0.1:37317_solr [junit4] 2> 231284 INFO (OverseerStateUpdate-72076665996836867-127.0.= 0.1:37317_solr-n_0000000000) [ ] o.a.s.c.c.ZkStateReader Updated live no= des from ZooKeeper... (0) -> (1) [junit4] 2> 231293 INFO (zkCallback-472-thread-1) [ ] o.a.s.c.c.Zk= StateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 231301 INFO (jetty-launcher-455-thread-1) [n:127.0.0.1:37= 317_solr ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keepin= g metrics history in memory. [junit4] 2> 231329 INFO (jetty-launcher-455-thread-1) [n:127.0.0.1:37= 317_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_37317.solr= .node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.Jm= xMBeanServer@18f6f32 [junit4] 2> 231336 INFO (jetty-launcher-455-thread-1) [n:127.0.0.1:37= 317_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_37317.solr= .jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxM= BeanServer@18f6f32 [junit4] 2> 231336 INFO (jetty-launcher-455-thread-1) [n:127.0.0.1:37= 317_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_37317.solr= .jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.= JmxMBeanServer@18f6f32 [junit4] 2> 231337 INFO (jetty-launcher-455-thread-1) [n:127.0.0.1:37= 317_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions undern= eath /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/tes= t/J0/temp/solr.cloud.cdcr.CdcrBidirectionalTest_51D0AC1134D69078-001/cdcr-c= luster1-001/node1/. [junit4] 2> 231358 INFO (zkConnectionManagerCallback-476-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 231362 INFO (zkConnectionManagerCallback-479-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 231363 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.c.c.CdcrBidirectionalTest cluster2 zkHost = =3D 127.0.0.1:44649/solr [junit4] 2> 231363 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.c.c.CdcrBidirectionalTest cluster1 zkHost = =3D 127.0.0.1:33897/solr [junit4] 2> 231364 INFO (zkConnectionManagerCallback-481-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 231367 INFO (zkConnectionManagerCallback-485-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 231368 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from Zo= oKeeper... (0) -> (1) [junit4] 2> 231369 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster a= t 127.0.0.1:33897/solr ready [junit4] 2> 231423 INFO (qtp30020297-2879) [n:127.0.0.1:37317_solr = ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with para= ms collection.configName=3Dcdcr-cluster1&maxShardsPerNode=3D2&name=3Dcdcr-c= luster1&nrtReplicas=3D1&action=3DCREATE&numShards=3D2&property.solr.directo= ryFactory=3Dsolr.StandardDirectoryFactory&wt=3Djavabin&version=3D2 and send= ToOCPQueue=3Dtrue [junit4] 2> 231426 INFO (OverseerThreadFactory-759-thread-1) [ ] o= .a.s.c.a.c.CreateCollectionCmd Create collection cdcr-cluster1 [junit4] 2> 231534 INFO (OverseerStateUpdate-72076665996836867-127.0.= 0.1:37317_solr-n_0000000000) [ ] o.a.s.c.o.SliceMutator createReplica() = { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"cdcr-cluster1", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"cdcr-cluster1_shard1_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:37317/solr", [junit4] 2> "type":"NRT", [junit4] 2> "waitForFinalState":"false"}=20 [junit4] 2> 231535 INFO (OverseerStateUpdate-72076665996836867-127.0.= 0.1:37317_solr-n_0000000000) [ ] o.a.s.c.o.SliceMutator createReplica() = { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"cdcr-cluster1", [junit4] 2> "shard":"shard2", [junit4] 2> "core":"cdcr-cluster1_shard2_replica_n2", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:37317/solr", [junit4] 2> "type":"NRT", [junit4] 2> "waitForFinalState":"false"}=20 [junit4] 2> 231758 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr = x:cdcr-cluster1_shard1_replica_n1] o.a.s.h.a.CoreAdminOperation core creat= e command qt=3D/admin/cores&collection.configName=3Dcdcr-cluster1&newCollec= tion=3Dtrue&collection=3Dcdcr-cluster1&version=3D2&replicaType=3DNRT&coreNo= deName=3Dcore_node3&name=3Dcdcr-cluster1_shard1_replica_n1&action=3DCREATE&= numShards=3D2&shard=3Dshard1&property.solr.directoryFactory=3Dsolr.Standard= DirectoryFactory&wt=3Djavabin [junit4] 2> 231759 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr = x:cdcr-cluster1_shard2_replica_n2] o.a.s.h.a.CoreAdminOperation core creat= e command qt=3D/admin/cores&collection.configName=3Dcdcr-cluster1&newCollec= tion=3Dtrue&collection=3Dcdcr-cluster1&version=3D2&replicaType=3DNRT&coreNo= deName=3Dcore_node4&name=3Dcdcr-cluster1_shard2_replica_n2&action=3DCREATE&= numShards=3D2&shard=3Dshard2&property.solr.directoryFactory=3Dsolr.Standard= DirectoryFactory&wt=3Djavabin [junit4] 2> 231759 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr = x:cdcr-cluster1_shard2_replica_n2] o.a.s.c.TransientSolrCoreCacheDefault A= llocating transient cache for 2147483647 transient cores [junit4] 2> 232782 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.SolrConfig Using Lucene MatchVersion: 7.5.0 [junit4] 2> 232783 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.SolrConfig Using Lucene MatchVersion: 7.5.0 [junit4] 2> 232798 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.s.IndexSchema [cdcr-cluster1_shard1_replica_n1] Schema name=3Dminimal [junit4] 2> 232799 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.s.IndexSchema [cdcr-cluster1_shard2_replica_n2] Schema name=3Dminimal [junit4] 2> 232801 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 232801 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.CoreContainer Creating SolrCore 'cdcr-cluster1_shard1_replica_n1' using= configuration from collection cdcr-cluster1, trusted=3Dtrue [junit4] 2> 232801 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 232801 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.CoreContainer Creating SolrCore 'cdcr-cluster1_shard2_replica_n2' using= configuration from collection cdcr-cluster1, trusted=3Dtrue [junit4] 2> 232801 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.m.r.SolrJmxReporter JMX monitoring for 'solr_37317.solr.core.cdcr-cluster= 1.shard1.replica_n1' (registry 'solr.core.cdcr-cluster1.shard1.replica_n1')= enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@18f6f32 [junit4] 2> 232801 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.m.r.SolrJmxReporter JMX monitoring for 'solr_37317.solr.core.cdcr-cluster= 1.shard2.replica_n2' (registry 'solr.core.cdcr-cluster1.shard2.replica_n2')= enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@18f6f32 [junit4] 2> 232810 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 232810 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 232810 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.SolrCore [[cdcr-cluster1_shard1_replica_n1] ] Opening new SolrCore at [= /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/= temp/solr.cloud.cdcr.CdcrBidirectionalTest_51D0AC1134D69078-001/cdcr-cluste= r1-001/node1/cdcr-cluster1_shard1_replica_n1], dataDir=3D[/home/jenkins/wor= kspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.c= dcr.CdcrBidirectionalTest_51D0AC1134D69078-001/cdcr-cluster1-001/node1/./cd= cr-cluster1_shard1_replica_n1/data/] [junit4] 2> 232810 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.SolrCore [[cdcr-cluster1_shard2_replica_n2] ] Opening new SolrCore at [= /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/= temp/solr.cloud.cdcr.CdcrBidirectionalTest_51D0AC1134D69078-001/cdcr-cluste= r1-001/node1/cdcr-cluster1_shard2_replica_n2], dataDir=3D[/home/jenkins/wor= kspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.c= dcr.CdcrBidirectionalTest_51D0AC1134D69078-001/cdcr-cluster1-001/node1/./cd= cr-cluster1_shard2_replica_n2/data/] [junit4] 2> 232926 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.Cd= crUpdateLog [junit4] 2> 232926 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.u.UpdateLog Initializing UpdateLog: dataDir=3D defaultSyncLevel=3DFLUSH n= umRecordsToKeep=3D100 maxNumLogsToKeep=3D10 numVersionBuckets=3D65536 [junit4] 2> 232927 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.Cd= crUpdateLog [junit4] 2> 232927 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.u.UpdateLog Initializing UpdateLog: dataDir=3D defaultSyncLevel=3DFLUSH n= umRecordsToKeep=3D100 maxNumLogsToKeep=3D10 numVersionBuckets=3D65536 [junit4] 2> 232928 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 232928 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 232928 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 232928 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 232930 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.s.SolrIndexSearcher Opening [Searcher@1a15f45[cdcr-cluster1_shard2_replic= a_n2] main] [junit4] 2> 232932 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /c= onfigs/cdcr-cluster1 [junit4] 2> 232932 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using Zoo= KeeperStorageIO:path=3D/configs/cdcr-cluster1 [junit4] 2> 232932 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.s.SolrIndexSearcher Opening [Searcher@1707526[cdcr-cluster1_shard1_replic= a_n1] main] [junit4] 2> 232932 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at = /configs/cdcr-cluster1/managed-schema [junit4] 2> 232932 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.s.ZkIndexSchemaReader Current schema version 0 is already the latest [junit4] 2> 232933 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /c= onfigs/cdcr-cluster1 [junit4] 2> 232933 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using Zoo= KeeperStorageIO:path=3D/configs/cdcr-cluster1 [junit4] 2> 232933 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at = /configs/cdcr-cluster1/managed-schema [junit4] 2> 232933 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 232933 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.s.ZkIndexSchemaReader Current schema version 0 is already the latest [junit4] 2> 232934 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 232937 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.h.CdcrBufferStateManager Created znode /collections/cdcr-cluster1/cdcr/st= ate/buffer [junit4] 2> 232953 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.h.CdcrProcessStateManager Created znode /collections/cdcr-cluster1/cdcr/s= tate/process [junit4] 2> 232972 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.u.UpdateLog Could not find max version in index or recent updates, using = new clock 1605183042970714112 [junit4] 2> 232972 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.u.UpdateLog Could not find max version in index or recent updates, using = new clock 1605183042970714112 [junit4] 2> 232973 INFO (searcherExecutor-765-thread-1-processing-n:1= 27.0.0.1:37317_solr x:cdcr-cluster1_shard2_replica_n2 c:cdcr-cluster1 s:sha= rd2 r:core_node4) [n:127.0.0.1:37317_solr c:cdcr-cluster1 s:shard2 r:core_n= ode4 x:cdcr-cluster1_shard2_replica_n2] o.a.s.c.SolrCore [cdcr-cluster1_sha= rd2_replica_n2] Registered new searcher Searcher@1a15f45[cdcr-cluster1_shar= d2_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 232973 INFO (searcherExecutor-764-thread-1-processing-n:1= 27.0.0.1:37317_solr x:cdcr-cluster1_shard1_replica_n1 c:cdcr-cluster1 s:sha= rd1 r:core_node3) [n:127.0.0.1:37317_solr c:cdcr-cluster1 s:shard1 r:core_n= ode3 x:cdcr-cluster1_shard1_replica_n1] o.a.s.c.SolrCore [cdcr-cluster1_sha= rd1_replica_n1] Registered new searcher Searcher@1707526[cdcr-cluster1_shar= d1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 232979 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.ZkShardTerms Successful update of terms at /collections/cdcr-cluster1/t= erms/shard2 to Terms{values=3D{core_node4=3D0}, version=3D0} [junit4] 2> 232980 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.ZkShardTerms Successful update of terms at /collections/cdcr-cluster1/t= erms/shard1 to Terms{values=3D{core_node3=3D0}, version=3D0} [junit4] 2> 232983 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 232983 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 232983 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.SyncStrategy Sync replicas to https://127.0.0.1:37317/solr/cdcr-cluster= 1_shard2_replica_n2/ [junit4] 2> 232983 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 232983 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 232983 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 232983 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.SyncStrategy Sync replicas to https://127.0.0.1:37317/solr/cdcr-cluster= 1_shard1_replica_n1/ [junit4] 2> 232983 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.SyncStrategy https://127.0.0.1:37317/solr/cdcr-cluster1_shard2_replica_= n2/ has no replicas [junit4] 2> 232983 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.ShardLeaderElectionContext Found all replicas participating in election= , clear LIR [junit4] 2> 232983 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 232984 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.SyncStrategy https://127.0.0.1:37317/solr/cdcr-cluster1_shard1_replica_= n1/ has no replicas [junit4] 2> 232984 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.ShardLeaderElectionContext Found all replicas participating in election= , clear LIR [junit4] 2> 232985 INFO (zkCallback-465-thread-1) [ ] o.a.s.h.Cdcr= LeaderStateManager Received new leader state @ cdcr-cluster1:shard2 [junit4] 2> 232985 INFO (zkCallback-465-thread-2) [ ] o.a.s.h.Cdcr= LeaderStateManager Received new leader state @ cdcr-cluster1:shard1 [junit4] 2> 232990 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:37317= /solr/cdcr-cluster1_shard2_replica_n2/ shard2 [junit4] 2> 232991 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:37317= /solr/cdcr-cluster1_shard1_replica_n1/ shard1 [junit4] 2> 233093 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 233093 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 233094 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.s.HttpSolrCall [admin] webapp=3Dnull path=3D/admin/cores params=3D{qt=3D/= admin/cores&collection.configName=3Dcdcr-cluster1&newCollection=3Dtrue&coll= ection=3Dcdcr-cluster1&version=3D2&replicaType=3DNRT&coreNodeName=3Dcore_no= de4&name=3Dcdcr-cluster1_shard2_replica_n2&action=3DCREATE&numShards=3D2&sh= ard=3Dshard2&property.solr.directoryFactory=3Dsolr.StandardDirectoryFactory= &wt=3Djavabin} status=3D0 QTime=3D1335 [junit4] 2> 233094 INFO (qtp30020297-2875) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.s.HttpSolrCall [admin] webapp=3Dnull path=3D/admin/cores params=3D{qt=3D/= admin/cores&collection.configName=3Dcdcr-cluster1&newCollection=3Dtrue&coll= ection=3Dcdcr-cluster1&version=3D2&replicaType=3DNRT&coreNodeName=3Dcore_no= de3&name=3Dcdcr-cluster1_shard1_replica_n1&action=3DCREATE&numShards=3D2&sh= ard=3Dshard1&property.solr.directoryFactory=3Dsolr.StandardDirectoryFactory= &wt=3Djavabin} status=3D0 QTime=3D1336 [junit4] 2> 233099 INFO (qtp30020297-2879) [n:127.0.0.1:37317_solr = ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at= most 30 seconds. Check all shard replicas [junit4] 2> 233194 INFO (zkCallback-465-thread-2) [ ] o.a.s.c.c.Zk= StateReader A cluster state change: [WatchedEvent state:SyncConnected type:= NodeDataChanged path:/collections/cdcr-cluster1/state.json] for collection = [cdcr-cluster1] has occurred - updating... (live nodes size: [1]) [junit4] 2> 233428 INFO (OverseerCollectionConfigSetProcessor-7207666= 5996836867-127.0.0.1:37317_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQu= eue Response ZK path: /overseer/collection-queue-work/qnr-0000000000 doesn'= t exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 234100 INFO (qtp30020297-2879) [n:127.0.0.1:37317_solr = ] o.a.s.s.HttpSolrCall [admin] webapp=3Dnull path=3D/admin/collections par= ams=3D{collection.configName=3Dcdcr-cluster1&maxShardsPerNode=3D2&name=3Dcd= cr-cluster1&nrtReplicas=3D1&action=3DCREATE&numShards=3D2&property.solr.dir= ectoryFactory=3Dsolr.StandardDirectoryFactory&wt=3Djavabin&version=3D2} sta= tus=3D0 QTime=3D2676 [junit4] 2> 234102 INFO (zkConnectionManagerCallback-489-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 234105 INFO (zkConnectionManagerCallback-493-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 234106 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from Zo= oKeeper... (0) -> (1) [junit4] 2> 234107 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster a= t 127.0.0.1:44649/solr ready [junit4] 2> 234161 INFO (qtp29385505-2825) [n:127.0.0.1:39865_solr = ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with para= ms collection.configName=3Dcdcr-cluster2&maxShardsPerNode=3D2&name=3Dcdcr-c= luster2&nrtReplicas=3D1&action=3DCREATE&numShards=3D2&property.solr.directo= ryFactory=3Dsolr.StandardDirectoryFactory&wt=3Djavabin&version=3D2 and send= ToOCPQueue=3Dtrue [junit4] 2> 234164 INFO (OverseerThreadFactory-746-thread-1) [ ] o= .a.s.c.a.c.CreateCollectionCmd Create collection cdcr-cluster2 [junit4] 2> 234271 INFO (OverseerStateUpdate-72076665943949315-127.0.= 0.1:39865_solr-n_0000000000) [ ] o.a.s.c.o.SliceMutator createReplica() = { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"cdcr-cluster2", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"cdcr-cluster2_shard1_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:39865/solr", [junit4] 2> "type":"NRT", [junit4] 2> "waitForFinalState":"false"}=20 [junit4] 2> 234272 INFO (OverseerStateUpdate-72076665943949315-127.0.= 0.1:39865_solr-n_0000000000) [ ] o.a.s.c.o.SliceMutator createReplica() = { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"cdcr-cluster2", [junit4] 2> "shard":"shard2", [junit4] 2> "core":"cdcr-cluster2_shard2_replica_n2", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:39865/solr", [junit4] 2> "type":"NRT", [junit4] 2> "waitForFinalState":"false"}=20 [junit4] 2> 234497 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr = x:cdcr-cluster2_shard1_replica_n1] o.a.s.h.a.CoreAdminOperation core creat= e command qt=3D/admin/cores&collection.configName=3Dcdcr-cluster2&newCollec= tion=3Dtrue&collection=3Dcdcr-cluster2&version=3D2&replicaType=3DNRT&coreNo= deName=3Dcore_node3&name=3Dcdcr-cluster2_shard1_replica_n1&action=3DCREATE&= numShards=3D2&shard=3Dshard1&property.solr.directoryFactory=3Dsolr.Standard= DirectoryFactory&wt=3Djavabin [junit4] 2> 234497 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr = x:cdcr-cluster2_shard2_replica_n2] o.a.s.h.a.CoreAdminOperation core creat= e command qt=3D/admin/cores&collection.configName=3Dcdcr-cluster2&newCollec= tion=3Dtrue&collection=3Dcdcr-cluster2&version=3D2&replicaType=3DNRT&coreNo= deName=3Dcore_node4&name=3Dcdcr-cluster2_shard2_replica_n2&action=3DCREATE&= numShards=3D2&shard=3Dshard2&property.solr.directoryFactory=3Dsolr.Standard= DirectoryFactory&wt=3Djavabin [junit4] 2> 234497 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr = x:cdcr-cluster2_shard2_replica_n2] o.a.s.c.TransientSolrCoreCacheDefault A= llocating transient cache for 2147483647 transient cores [junit4] 2> 235511 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.SolrConfig Using Lucene MatchVersion: 7.5.0 [junit4] 2> 235511 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.SolrConfig Using Lucene MatchVersion: 7.5.0 [junit4] 2> 235540 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.s.IndexSchema [cdcr-cluster2_shard1_replica_n1] Schema name=3Dminimal [junit4] 2> 235541 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.s.IndexSchema [cdcr-cluster2_shard2_replica_n2] Schema name=3Dminimal [junit4] 2> 235543 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 235550 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.CoreContainer Creating SolrCore 'cdcr-cluster2_shard1_replica_n1' using= configuration from collection cdcr-cluster2, trusted=3Dtrue [junit4] 2> 235550 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 235551 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.CoreContainer Creating SolrCore 'cdcr-cluster2_shard2_replica_n2' using= configuration from collection cdcr-cluster2, trusted=3Dtrue [junit4] 2> 235551 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.m.r.SolrJmxReporter JMX monitoring for 'solr_39865.solr.core.cdcr-cluster= 2.shard2.replica_n2' (registry 'solr.core.cdcr-cluster2.shard2.replica_n2')= enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@18f6f32 [junit4] 2> 235551 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.m.r.SolrJmxReporter JMX monitoring for 'solr_39865.solr.core.cdcr-cluster= 2.shard1.replica_n1' (registry 'solr.core.cdcr-cluster2.shard1.replica_n1')= enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@18f6f32 [junit4] 2> 235551 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 235551 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 235552 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.SolrCore [[cdcr-cluster2_shard1_replica_n1] ] Opening new SolrCore at [= /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/= temp/solr.cloud.cdcr.CdcrBidirectionalTest_51D0AC1134D69078-001/cdcr-cluste= r2-001/node1/cdcr-cluster2_shard1_replica_n1], dataDir=3D[/home/jenkins/wor= kspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.c= dcr.CdcrBidirectionalTest_51D0AC1134D69078-001/cdcr-cluster2-001/node1/./cd= cr-cluster2_shard1_replica_n1/data/] [junit4] 2> 235552 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.SolrCore [[cdcr-cluster2_shard2_replica_n2] ] Opening new SolrCore at [= /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/= temp/solr.cloud.cdcr.CdcrBidirectionalTest_51D0AC1134D69078-001/cdcr-cluste= r2-001/node1/cdcr-cluster2_shard2_replica_n2], dataDir=3D[/home/jenkins/wor= kspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.c= dcr.CdcrBidirectionalTest_51D0AC1134D69078-001/cdcr-cluster2-001/node1/./cd= cr-cluster2_shard2_replica_n2/data/] [junit4] 2> 235685 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.Cd= crUpdateLog [junit4] 2> 235685 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.u.UpdateLog Initializing UpdateLog: dataDir=3D defaultSyncLevel=3DFLUSH n= umRecordsToKeep=3D100 maxNumLogsToKeep=3D10 numVersionBuckets=3D65536 [junit4] 2> 235686 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 235687 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 235690 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.s.SolrIndexSearcher Opening [Searcher@18748c5[cdcr-cluster2_shard1_replic= a_n1] main] [junit4] 2> 235690 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.Cd= crUpdateLog [junit4] 2> 235690 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.u.UpdateLog Initializing UpdateLog: dataDir=3D defaultSyncLevel=3DFLUSH n= umRecordsToKeep=3D100 maxNumLogsToKeep=3D10 numVersionBuckets=3D65536 [junit4] 2> 235691 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /c= onfigs/cdcr-cluster2 [junit4] 2> 235691 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using Zoo= KeeperStorageIO:path=3D/configs/cdcr-cluster2 [junit4] 2> 235691 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at = /configs/cdcr-cluster2/managed-schema [junit4] 2> 235692 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 235692 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 235692 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.s.ZkIndexSchemaReader Current schema version 0 is already the latest [junit4] 2> 235693 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 235696 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.h.CdcrBufferStateManager Created znode /collections/cdcr-cluster2/cdcr/st= ate/buffer [junit4] 2> 235696 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.s.SolrIndexSearcher Opening [Searcher@42c4f6[cdcr-cluster2_shard2_replica= _n2] main] [junit4] 2> 235697 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.h.CdcrProcessStateManager Created znode /collections/cdcr-cluster2/cdcr/s= tate/process [junit4] 2> 235697 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /c= onfigs/cdcr-cluster2 [junit4] 2> 235697 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using Zoo= KeeperStorageIO:path=3D/configs/cdcr-cluster2 [junit4] 2> 235697 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at = /configs/cdcr-cluster2/managed-schema [junit4] 2> 235698 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.s.ZkIndexSchemaReader Current schema version 0 is already the latest [junit4] 2> 235699 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 235701 INFO (searcherExecutor-776-thread-1-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard1_replica_n1 c:cdcr-cluster2 s:sha= rd1 r:core_node3) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard1 r:core_n= ode3 x:cdcr-cluster2_shard1_replica_n1] o.a.s.c.SolrCore [cdcr-cluster2_sha= rd1_replica_n1] Registered new searcher Searcher@18748c5[cdcr-cluster2_shar= d1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 235701 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.u.UpdateLog Could not find max version in index or recent updates, using = new clock 1605183045832278016 [junit4] 2> 235703 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.u.UpdateLog Could not find max version in index or recent updates, using = new clock 1605183045834375168 [junit4] 2> 235708 INFO (searcherExecutor-777-thread-1-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard2_replica_n2 c:cdcr-cluster2 s:sha= rd2 r:core_node4) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard2 r:core_n= ode4 x:cdcr-cluster2_shard2_replica_n2] o.a.s.c.SolrCore [cdcr-cluster2_sha= rd2_replica_n2] Registered new searcher Searcher@42c4f6[cdcr-cluster2_shard= 2_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 235709 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.ZkShardTerms Successful update of terms at /collections/cdcr-cluster2/t= erms/shard1 to Terms{values=3D{core_node3=3D0}, version=3D0} [junit4] 2> 235711 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.ZkShardTerms Successful update of terms at /collections/cdcr-cluster2/t= erms/shard2 to Terms{values=3D{core_node4=3D0}, version=3D0} [junit4] 2> 235715 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 235715 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 235715 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.SyncStrategy Sync replicas to https://127.0.0.1:39865/solr/cdcr-cluster= 2_shard2_replica_n2/ [junit4] 2> 235715 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 235715 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 235715 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 235715 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.SyncStrategy Sync replicas to https://127.0.0.1:39865/solr/cdcr-cluster= 2_shard1_replica_n1/ [junit4] 2> 235715 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.SyncStrategy https://127.0.0.1:39865/solr/cdcr-cluster2_shard2_replica_= n2/ has no replicas [junit4] 2> 235716 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.ShardLeaderElectionContext Found all replicas participating in election= , clear LIR [junit4] 2> 235716 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 235716 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.SyncStrategy https://127.0.0.1:39865/solr/cdcr-cluster2_shard1_replica_= n1/ has no replicas [junit4] 2> 235716 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.ShardLeaderElectionContext Found all replicas participating in election= , clear LIR [junit4] 2> 235718 INFO (zkCallback-440-thread-1) [ ] o.a.s.h.Cdcr= LeaderStateManager Received new leader state @ cdcr-cluster2:shard1 [junit4] 2> 235722 INFO (zkCallback-440-thread-1) [ ] o.a.s.h.Cdcr= LeaderStateManager Received new leader state @ cdcr-cluster2:shard2 [junit4] 2> 235722 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:39865= /solr/cdcr-cluster2_shard1_replica_n1/ shard1 [junit4] 2> 235726 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:39865= /solr/cdcr-cluster2_shard2_replica_n2/ shard2 [junit4] 2> 235828 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 235830 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.s.HttpSolrCall [admin] webapp=3Dnull path=3D/admin/cores params=3D{qt=3D/= admin/cores&collection.configName=3Dcdcr-cluster2&newCollection=3Dtrue&coll= ection=3Dcdcr-cluster2&version=3D2&replicaType=3DNRT&coreNodeName=3Dcore_no= de4&name=3Dcdcr-cluster2_shard2_replica_n2&action=3DCREATE&numShards=3D2&sh= ard=3Dshard2&property.solr.directoryFactory=3Dsolr.StandardDirectoryFactory= &wt=3Djavabin} status=3D0 QTime=3D1333 [junit4] 2> 235876 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 235878 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.s.HttpSolrCall [admin] webapp=3Dnull path=3D/admin/cores params=3D{qt=3D/= admin/cores&collection.configName=3Dcdcr-cluster2&newCollection=3Dtrue&coll= ection=3Dcdcr-cluster2&version=3D2&replicaType=3DNRT&coreNodeName=3Dcore_no= de3&name=3Dcdcr-cluster2_shard1_replica_n1&action=3DCREATE&numShards=3D2&sh= ard=3Dshard1&property.solr.directoryFactory=3Dsolr.StandardDirectoryFactory= &wt=3Djavabin} status=3D0 QTime=3D1381 [junit4] 2> 235883 INFO (qtp29385505-2825) [n:127.0.0.1:39865_solr = ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at= most 30 seconds. Check all shard replicas [junit4] 2> 235978 INFO (zkCallback-440-thread-1) [ ] o.a.s.c.c.Zk= StateReader A cluster state change: [WatchedEvent state:SyncConnected type:= NodeDataChanged path:/collections/cdcr-cluster2/state.json] for collection = [cdcr-cluster2] has occurred - updating... (live nodes size: [1]) [junit4] 2> 236165 INFO (OverseerCollectionConfigSetProcessor-7207666= 5943949315-127.0.0.1:39865_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQu= eue Response ZK path: /overseer/collection-queue-work/qnr-0000000000 doesn'= t exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 236884 INFO (qtp29385505-2825) [n:127.0.0.1:39865_solr = ] o.a.s.s.HttpSolrCall [admin] webapp=3Dnull path=3D/admin/collections par= ams=3D{collection.configName=3Dcdcr-cluster2&maxShardsPerNode=3D2&name=3Dcd= cr-cluster2&nrtReplicas=3D1&action=3DCREATE&numShards=3D2&property.solr.dir= ectoryFactory=3Dsolr.StandardDirectoryFactory&wt=3Djavabin&version=3D2} sta= tus=3D0 QTime=3D2723 [junit4] 2> 236892 INFO (zkConnectionManagerCallback-500-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 236893 INFO (qtp30020297-2878) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 236893 INFO (qtp30020297-2878) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:44649/solr ready [junit4] 2> 236924 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.h.CdcrRequestHandler Found maxVersionFromRecent 0 maxVersionFromIndex 0 [junit4] 2> 236924 INFO (qtp29385505-2821) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.h.CdcrRequestHandler Found maxVersionFromRecent 0 maxVersionFromIndex 0 [junit4] 2> 236924 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.S.Request [cdcr-cluster2_shard2_replica_n2] webapp=3D/solr path=3D/cdc= r params=3D{action=3DSHARDCHECKPOINT&wt=3Djavabin&version=3D2} status=3D0 Q= Time=3D1 [junit4] 2> 236924 INFO (qtp29385505-2821) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster2_shard1_replica_n1] webapp=3D/solr path=3D/cdc= r params=3D{action=3DSHARDCHECKPOINT&wt=3Djavabin&version=3D2} status=3D0 Q= Time=3D1 [junit4] 2> 236925 INFO (qtp29385505-2825) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.S.Request [cdcr-cluster2_shard2_replica_n2] webapp=3D/solr path=3D/cdc= r params=3D{_stateVer_=3Dcdcr-cluster2:4&action=3DCOLLECTIONCHECKPOINT&wt= =3Djavabin&version=3D2} status=3D0 QTime=3D19 [junit4] 2> 236926 INFO (qtp30020297-2878) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.h.CdcrReplicatorManager Create new update log reader for target cdcr-clus= ter2 with checkpoint -1 @ cdcr-cluster1:shard1 [junit4] 2> 236926 INFO (qtp30020297-2878) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.h.CdcrReplicatorManager Attempting to bootstrap target collection: cdcr-c= luster2, shard: shard1 [junit4] 2> 236928 INFO (qtp30020297-2878) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.h.CdcrReplicatorManager Submitting bootstrap task to executor [junit4] 2> 236929 INFO (cdcr-bootstrap-status-496-thread-1-processin= g-n:127.0.0.1:37317_solr x:cdcr-cluster1_shard1_replica_n1 c:cdcr-cluster1 = s:shard1 r:core_node3) [n:127.0.0.1:37317_solr c:cdcr-cluster1 s:shard1 r:c= ore_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.s.h.CdcrReplicatorManager = Attempting to bootstrap target collection: cdcr-cluster2 shard: shard1 lead= er: https://127.0.0.1:39865/solr/cdcr-cluster2_shard1_replica_n1/ [junit4] 2> 236935 INFO (zkCallback-465-thread-2) [ ] o.a.s.h.Cdcr= ProcessStateManager The CDCR process state has changed: WatchedEvent state:= SyncConnected type:NodeDataChanged path:/collections/cdcr-cluster1/cdcr/sta= te/process @ cdcr-cluster1:shard1 [junit4] 2> 236935 INFO (zkCallback-465-thread-1) [ ] o.a.s.h.Cdcr= ProcessStateManager The CDCR process state has changed: WatchedEvent state:= SyncConnected type:NodeDataChanged path:/collections/cdcr-cluster1/cdcr/sta= te/process @ cdcr-cluster1:shard2 [junit4] 2> 236937 INFO (qtp30020297-2878) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster1_shard1_replica_n1] webapp=3D/solr path=3D/cdc= r params=3D{qt=3D/cdcr&_stateVer_=3Dcdcr-cluster1:4&action=3Dstart&wt=3Djav= abin&version=3D2} status=3D0 QTime=3D48 [junit4] 2> 236937 INFO (zkCallback-465-thread-2) [ ] o.a.s.h.Cdcr= ProcessStateManager Received new CDCR process state from watcher: STARTED @= cdcr-cluster1:shard1 [junit4] 2> 236937 INFO (zkCallback-465-thread-1) [ ] o.a.s.h.Cdcr= ProcessStateManager Received new CDCR process state from watcher: STARTED @= cdcr-cluster1:shard2 [junit4] 2> 236939 INFO (zkConnectionManagerCallback-505-thread-1) [ = ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 236939 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster2_shard1_replica_n1] webapp=3D/solr path=3D/cdc= r params=3D{qt=3D/cdcr&masterUrl=3Dhttps://127.0.0.1:37317/solr/cdcr-cluste= r1_shard1_replica_n1/&action=3DBOOTSTRAP&wt=3Djavabin&version=3D2} status= =3D0 QTime=3D1 [junit4] 2> 236940 INFO (zkCallback-465-thread-1) [ ] o.a.s.c.c.Zk= StateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 236942 INFO (zkCallback-465-thread-1) [ ] o.a.s.c.s.i.= ZkClientClusterStateProvider Cluster at 127.0.0.1:44649/solr ready [junit4] 2> 236942 INFO (recoveryExecutor-437-thread-1-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard1_replica_n1 c:cdcr-cluster2 s:sha= rd1 r:core_node3) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard1 r:core_n= ode3 x:cdcr-cluster2_shard1_replica_n1] o.a.s.u.UpdateLog Starting to buffe= r updates. FSUpdateLog{state=3DACTIVE, tlog=3Dnull} [junit4] 2> 236944 INFO (qtp29385505-2825) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster2_shard1_replica_n1] webapp=3D/solr path=3D/cdc= r params=3D{qt=3D/cdcr&action=3DBOOTSTRAP_STATUS&wt=3Djavabin&version=3D2} = status=3D0 QTime=3D0 [junit4] 2> 236945 INFO (cdcr-bootstrap-status-496-thread-1-processin= g-n:127.0.0.1:37317_solr x:cdcr-cluster1_shard1_replica_n1 c:cdcr-cluster1 = s:shard1 r:core_node3) [n:127.0.0.1:37317_solr c:cdcr-cluster1 s:shard1 r:c= ore_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.s.h.CdcrReplicatorManager = CDCR bootstrap running for 1 seconds, sleeping for 2000 ms [junit4] 2> 236974 INFO (qtp30020297-2878) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.u.DirectUpdateHandler2 start commit{_version_=3D1605183047167115264,optim= ize=3Dfalse,openSearcher=3Dfalse,waitSearcher=3Dtrue,expungeDeletes=3Dfalse= ,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4] 2> 236975 INFO (qtp30020297-2878) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit. [junit4] 2> 236978 INFO (qtp30020297-2878) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 236978 INFO (qtp30020297-2878) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster1_shard1_replica_n1] webapp=3D/solr path=3D/upd= ate params=3D{waitSearcher=3Dtrue&openSearcher=3Dfalse&commit=3Dtrue&softCo= mmit=3Dfalse&commit_end_point=3Dtrue&wt=3Djavabin&version=3D2} status=3D0 Q= Time=3D9 [junit4] 2> 236988 INFO (qtp29385505-2825) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.h.CdcrRequestHandler Found maxVersionFromRecent 0 maxVersionFromIndex 0 [junit4] 2> 236988 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.h.CdcrRequestHandler Found maxVersionFromRecent 0 maxVersionFromIndex 0 [junit4] 2> 236988 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster2_shard1_replica_n1] webapp=3D/solr path=3D/cdc= r params=3D{action=3DSHARDCHECKPOINT&wt=3Djavabin&version=3D2} status=3D0 Q= Time=3D1 [junit4] 2> 236988 INFO (qtp29385505-2825) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.S.Request [cdcr-cluster2_shard2_replica_n2] webapp=3D/solr path=3D/cdc= r params=3D{action=3DSHARDCHECKPOINT&wt=3Djavabin&version=3D2} status=3D0 Q= Time=3D1 [junit4] 2> 236991 INFO (qtp29385505-2824) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster2_shard1_replica_n1] webapp=3D/solr path=3D/cdc= r params=3D{_stateVer_=3Dcdcr-cluster2:4&action=3DCOLLECTIONCHECKPOINT&wt= =3Djavabin&version=3D2} status=3D0 QTime=3D30 [junit4] 2> 236994 INFO (zkCallback-465-thread-1) [ ] o.a.s.h.Cdcr= ReplicatorManager Create new update log reader for target cdcr-cluster2 wit= h checkpoint -1 @ cdcr-cluster1:shard2 [junit4] 2> 236994 INFO (zkCallback-465-thread-1) [ ] o.a.s.h.Cdcr= ReplicatorManager Attempting to bootstrap target collection: cdcr-cluster2,= shard: shard2 [junit4] 2> 236994 INFO (zkCallback-465-thread-1) [ ] o.a.s.h.Cdcr= ReplicatorManager Submitting bootstrap task to executor [junit4] 2> 236995 INFO (cdcr-bootstrap-status-501-thread-1) [ ] o= .a.s.h.CdcrReplicatorManager Attempting to bootstrap target collection: cdc= r-cluster2 shard: shard2 leader: https://127.0.0.1:39865/solr/cdcr-cluster2= _shard2_replica_n2/ [junit4] 2> 237006 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster1_shard1_replica_n1] webapp=3D/solr path=3D/rep= lication params=3D{qt=3D/replication&wt=3Djavabin&version=3D2&command=3Dind= exversion} status=3D0 QTime=3D0 [junit4] 2> 237006 INFO (qtp29385505-2953) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.S.Request [cdcr-cluster2_shard2_replica_n2] webapp=3D/solr path=3D/cdc= r params=3D{qt=3D/cdcr&masterUrl=3Dhttps://127.0.0.1:37317/solr/cdcr-cluste= r1_shard2_replica_n2/&action=3DBOOTSTRAP&wt=3Djavabin&version=3D2} status= =3D0 QTime=3D0 [junit4] 2> 237007 INFO (recoveryExecutor-437-thread-2-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard2_replica_n2 c:cdcr-cluster2 s:sha= rd2 r:core_node4) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard2 r:core_n= ode4 x:cdcr-cluster2_shard2_replica_n2] o.a.s.u.UpdateLog Starting to buffe= r updates. FSUpdateLog{state=3DACTIVE, tlog=3Dnull} [junit4] 2> 237007 INFO (recoveryExecutor-437-thread-1-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard1_replica_n1 c:cdcr-cluster2 s:sha= rd1 r:core_node3) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard1 r:core_n= ode3 x:cdcr-cluster2_shard1_replica_n1] o.a.s.h.IndexFetcher Master's gener= ation: 1 [junit4] 2> 237007 INFO (recoveryExecutor-437-thread-1-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard1_replica_n1 c:cdcr-cluster2 s:sha= rd1 r:core_node3) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard1 r:core_n= ode3 x:cdcr-cluster2_shard1_replica_n1] o.a.s.h.IndexFetcher Master's versi= on: 0 [junit4] 2> 237007 INFO (recoveryExecutor-437-thread-1-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard1_replica_n1 c:cdcr-cluster2 s:sha= rd1 r:core_node3) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard1 r:core_n= ode3 x:cdcr-cluster2_shard1_replica_n1] o.a.s.h.IndexFetcher Slave's genera= tion: 1 [junit4] 2> 237007 INFO (recoveryExecutor-437-thread-1-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard1_replica_n1 c:cdcr-cluster2 s:sha= rd1 r:core_node3) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard1 r:core_n= ode3 x:cdcr-cluster2_shard1_replica_n1] o.a.s.h.IndexFetcher Slave's versio= n: 0 [junit4] 2> 237007 INFO (recoveryExecutor-437-thread-1-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard1_replica_n1 c:cdcr-cluster2 s:sha= rd1 r:core_node3) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard1 r:core_n= ode3 x:cdcr-cluster2_shard1_replica_n1] o.a.s.h.IndexFetcher New index in M= aster. Deleting mine... [junit4] 2> 237009 INFO (recoveryExecutor-437-thread-1-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard1_replica_n1 c:cdcr-cluster2 s:sha= rd1 r:core_node3) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard1 r:core_n= ode3 x:cdcr-cluster2_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [= Searcher@15c59d4[cdcr-cluster2_shard1_replica_n1] main] [junit4] 2> 237010 INFO (qtp29385505-2824) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.S.Request [cdcr-cluster2_shard2_replica_n2] webapp=3D/solr path=3D/cdc= r params=3D{qt=3D/cdcr&action=3DBOOTSTRAP_STATUS&wt=3Djavabin&version=3D2} = status=3D0 QTime=3D0 [junit4] 2> 237010 INFO (cdcr-bootstrap-status-501-thread-1) [ ] o= .a.s.h.CdcrReplicatorManager CDCR bootstrap running for 1 seconds, sleeping= for 2000 ms [junit4] 2> 237015 INFO (searcherExecutor-776-thread-1-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard1_replica_n1 c:cdcr-cluster2 s:sha= rd1 r:core_node3) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard1 r:core_n= ode3 x:cdcr-cluster2_shard1_replica_n1] o.a.s.c.SolrCore [cdcr-cluster2_sha= rd1_replica_n1] Registered new searcher Searcher@15c59d4[cdcr-cluster2_shar= d1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 237019 INFO (recoveryExecutor-437-thread-1-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard1_replica_n1 c:cdcr-cluster2 s:sha= rd1 r:core_node3) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard1 r:core_n= ode3 x:cdcr-cluster2_shard1_replica_n1] o.a.s.h.CdcrRequestHandler No repla= y needed. [junit4] 2> 237022 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.u.DirectUpdateHandler2 start commit{_version_=3D1605183047217446912,optim= ize=3Dfalse,openSearcher=3Dfalse,waitSearcher=3Dtrue,expungeDeletes=3Dfalse= ,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4] 2> 237022 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit. [junit4] 2> 237022 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 237022 INFO (qtp30020297-2880) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.S.Request [cdcr-cluster1_shard2_replica_n2] webapp=3D/solr path=3D/upd= ate params=3D{waitSearcher=3Dtrue&openSearcher=3Dfalse&commit=3Dtrue&softCo= mmit=3Dfalse&commit_end_point=3Dtrue&wt=3Djavabin&version=3D2} status=3D0 Q= Time=3D0 [junit4] 2> 237033 INFO (qtp30020297-2879) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.S.Request [cdcr-cluster1_shard2_replica_n2] webapp=3D/solr path=3D/rep= lication params=3D{qt=3D/replication&wt=3Djavabin&version=3D2&command=3Dind= exversion} status=3D0 QTime=3D0 [junit4] 2> 237033 INFO (recoveryExecutor-437-thread-2-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard2_replica_n2 c:cdcr-cluster2 s:sha= rd2 r:core_node4) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard2 r:core_n= ode4 x:cdcr-cluster2_shard2_replica_n2] o.a.s.h.IndexFetcher Master's gener= ation: 1 [junit4] 2> 237033 INFO (recoveryExecutor-437-thread-2-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard2_replica_n2 c:cdcr-cluster2 s:sha= rd2 r:core_node4) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard2 r:core_n= ode4 x:cdcr-cluster2_shard2_replica_n2] o.a.s.h.IndexFetcher Master's versi= on: 0 [junit4] 2> 237033 INFO (recoveryExecutor-437-thread-2-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard2_replica_n2 c:cdcr-cluster2 s:sha= rd2 r:core_node4) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard2 r:core_n= ode4 x:cdcr-cluster2_shard2_replica_n2] o.a.s.h.IndexFetcher Slave's genera= tion: 1 [junit4] 2> 237033 INFO (recoveryExecutor-437-thread-2-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard2_replica_n2 c:cdcr-cluster2 s:sha= rd2 r:core_node4) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard2 r:core_n= ode4 x:cdcr-cluster2_shard2_replica_n2] o.a.s.h.IndexFetcher Slave's versio= n: 0 [junit4] 2> 237033 INFO (recoveryExecutor-437-thread-2-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard2_replica_n2 c:cdcr-cluster2 s:sha= rd2 r:core_node4) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard2 r:core_n= ode4 x:cdcr-cluster2_shard2_replica_n2] o.a.s.h.IndexFetcher New index in M= aster. Deleting mine... [junit4] 2> 237035 INFO (recoveryExecutor-437-thread-2-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard2_replica_n2 c:cdcr-cluster2 s:sha= rd2 r:core_node4) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard2 r:core_n= ode4 x:cdcr-cluster2_shard2_replica_n2] o.a.s.s.SolrIndexSearcher Opening [= Searcher@1e00ce[cdcr-cluster2_shard2_replica_n2] main] [junit4] 2> 237037 INFO (searcherExecutor-777-thread-1-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard2_replica_n2 c:cdcr-cluster2 s:sha= rd2 r:core_node4) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard2 r:core_n= ode4 x:cdcr-cluster2_shard2_replica_n2] o.a.s.c.SolrCore [cdcr-cluster2_sha= rd2_replica_n2] Registered new searcher Searcher@1e00ce[cdcr-cluster2_shard= 2_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 237038 INFO (recoveryExecutor-437-thread-2-processing-n:1= 27.0.0.1:39865_solr x:cdcr-cluster2_shard2_replica_n2 c:cdcr-cluster2 s:sha= rd2 r:core_node4) [n:127.0.0.1:39865_solr c:cdcr-cluster2 s:shard2 r:core_n= ode4 x:cdcr-cluster2_shard2_replica_n2] o.a.s.h.CdcrRequestHandler No repla= y needed. [junit4] 2> 238939 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.c.c.CdcrBidirectionalTest Adding 10 docs wit= h commit=3Dtrue, numDocs=3D100 [junit4] 2> 238952 INFO (qtp29385505-2826) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster2_shard1_replica_n1] webapp=3D/solr path=3D/cdc= r params=3D{qt=3D/cdcr&action=3DBOOTSTRAP_STATUS&wt=3Djavabin&version=3D2} = status=3D0 QTime=3D0 [junit4] 2> 238952 INFO (cdcr-bootstrap-status-496-thread-1-processin= g-n:127.0.0.1:37317_solr x:cdcr-cluster1_shard1_replica_n1 c:cdcr-cluster1 = s:shard1 r:core_node3) [n:127.0.0.1:37317_solr c:cdcr-cluster1 s:shard1 r:c= ore_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.s.h.CdcrReplicatorManager = CDCR bootstrap successful in 3 seconds [junit4] 2> 238977 INFO (qtp29385505-2954) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.h.CdcrRequestHandler Found maxVersionFromRecent 0 maxVersionFromIndex 0 [junit4] 2> 238977 INFO (qtp29385505-2954) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster2_shard1_replica_n1] webapp=3D/solr path=3D/cdc= r params=3D{action=3DSHARDCHECKPOINT&wt=3Djavabin&version=3D2} status=3D0 Q= Time=3D0 [junit4] 2> 238985 INFO (qtp29385505-2821) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.h.CdcrRequestHandler Found maxVersionFromRecent 0 maxVersionFromIndex 0 [junit4] 2> 238985 INFO (qtp29385505-2821) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.S.Request [cdcr-cluster2_shard2_replica_n2] webapp=3D/solr path=3D/cdc= r params=3D{action=3DSHARDCHECKPOINT&wt=3Djavabin&version=3D2} status=3D0 Q= Time=3D0 [junit4] 2> 238986 INFO (qtp29385505-2824) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster2_shard1_replica_n1] webapp=3D/solr path=3D/cdc= r params=3D{_stateVer_=3Dcdcr-cluster2:4&action=3DCOLLECTIONCHECKPOINT&wt= =3Djavabin&version=3D2} status=3D0 QTime=3D26 [junit4] 2> 238986 INFO (cdcr-bootstrap-status-496-thread-1-processin= g-n:127.0.0.1:37317_solr x:cdcr-cluster1_shard1_replica_n1 c:cdcr-cluster1 = s:shard1 r:core_node3) [n:127.0.0.1:37317_solr c:cdcr-cluster1 s:shard1 r:c= ore_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.s.h.CdcrReplicatorManager = Create new update log reader for target cdcr-cluster2 with checkpoint -1 @ = cdcr-cluster1:shard1 [junit4] 2> 238987 INFO (cdcr-bootstrap-status-496-thread-1-processin= g-n:127.0.0.1:37317_solr x:cdcr-cluster1_shard1_replica_n1 c:cdcr-cluster1 = s:shard1 r:core_node3) [n:127.0.0.1:37317_solr c:cdcr-cluster1 s:shard1 r:c= ore_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.s.h.CdcrReplicatorManager = Bootstrap successful, giving the go-ahead to replicator [junit4] 2> 238989 INFO (qtp30020297-2930) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.ZkShardTerms Successful update of terms at /collections/cdcr-cluster1/t= erms/shard1 to Terms{values=3D{core_node3=3D1}, version=3D1} [junit4] 2> 238990 INFO (qtp30020297-2930) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster1_shard1_replica_n1] webapp=3D/solr path=3D/upd= ate params=3D{_stateVer_=3Dcdcr-cluster1:4&wt=3Djavabin&version=3D2} status= =3D0 QTime=3D41 [junit4] 2> 238992 INFO (qtp30020297-2874) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.ZkShardTerms Successful update of terms at /collections/cdcr-cluster1/t= erms/shard2 to Terms{values=3D{core_node4=3D1}, version=3D1} [junit4] 2> 238992 INFO (qtp30020297-2874) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.S.Request [cdcr-cluster1_shard2_replica_n2] webapp=3D/solr path=3D/upd= ate params=3D{_stateVer_=3Dcdcr-cluster1:4&wt=3Djavabin&version=3D2} status= =3D0 QTime=3D33 [junit4] 2> 239022 INFO (qtp29385505-2821) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.S.Request [cdcr-cluster2_shard2_replica_n2] webapp=3D/solr path=3D/cdc= r params=3D{qt=3D/cdcr&action=3DBOOTSTRAP_STATUS&wt=3Djavabin&version=3D2} = status=3D0 QTime=3D0 [junit4] 2> 239022 INFO (qtp30020297-2930) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.u.DirectUpdateHandler2 start commit{_version_=3D1605183049314598912,optim= ize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,expungeDeletes=3Dfalse,= softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4] 2> 239022 INFO (qtp30020297-2930) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.So= lrIndexWriter@ec70f2 commitCommandVersion:1605183049314598912 [junit4] 2> 239022 INFO (qtp30020297-2876) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.u.DirectUpdateHandler2 start commit{_version_=3D1605183049314598912,optim= ize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,expungeDeletes=3Dfalse,= softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4] 2> 239022 INFO (qtp30020297-2876) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.So= lrIndexWriter@413752 commitCommandVersion:1605183049314598912 [junit4] 2> 239023 INFO (cdcr-bootstrap-status-501-thread-1) [ ] o= .a.s.h.CdcrReplicatorManager CDCR bootstrap successful in 3 seconds [junit4] 2> 239044 INFO (qtp29385505-2953) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.h.CdcrRequestHandler Found maxVersionFromRecent 0 maxVersionFromIndex 0 [junit4] 2> 239044 INFO (qtp29385505-2953) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.S.Request [cdcr-cluster2_shard2_replica_n2] webapp=3D/solr path=3D/cdc= r params=3D{action=3DSHARDCHECKPOINT&wt=3Djavabin&version=3D2} status=3D0 Q= Time=3D5 [junit4] 2> 239044 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.h.CdcrRequestHandler Found maxVersionFromRecent 0 maxVersionFromIndex 0 [junit4] 2> 239044 INFO (qtp29385505-2820) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster2_shard1_replica_n1] webapp=3D/solr path=3D/cdc= r params=3D{action=3DSHARDCHECKPOINT&wt=3Djavabin&version=3D2} status=3D0 Q= Time=3D0 [junit4] 2> 239045 INFO (qtp29385505-2824) [n:127.0.0.1:39865_solr c:= cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_replica_n2] o.a.= s.c.S.Request [cdcr-cluster2_shard2_replica_n2] webapp=3D/solr path=3D/cdc= r params=3D{_stateVer_=3Dcdcr-cluster2:4&action=3DCOLLECTIONCHECKPOINT&wt= =3Djavabin&version=3D2} status=3D0 QTime=3D21 [junit4] 2> 239046 INFO (cdcr-bootstrap-status-501-thread-1) [ ] o= .a.s.h.CdcrReplicatorManager Create new update log reader for target cdcr-c= luster2 with checkpoint -1 @ cdcr-cluster1:shard2 [junit4] 2> 239046 INFO (cdcr-bootstrap-status-501-thread-1) [ ] o= .a.s.h.CdcrReplicatorManager Bootstrap successful, giving the go-ahead to r= eplicator [junit4] 2> 239190 INFO (qtp30020297-2930) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.s.SolrIndexSearcher Opening [Searcher@23b46[cdcr-cluster1_shard1_replica_= n1] main] [junit4] 2> 239191 INFO (qtp30020297-2930) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 239194 INFO (searcherExecutor-764-thread-1-processing-n:1= 27.0.0.1:37317_solr x:cdcr-cluster1_shard1_replica_n1 c:cdcr-cluster1 s:sha= rd1 r:core_node3) [n:127.0.0.1:37317_solr c:cdcr-cluster1 s:shard1 r:core_n= ode3 x:cdcr-cluster1_shard1_replica_n1] o.a.s.c.SolrCore [cdcr-cluster1_sha= rd1_replica_n1] Registered new searcher Searcher@23b46[cdcr-cluster1_shard1= _replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninve= rting(_0(7.5.0):C43)))} [junit4] 2> 239194 INFO (qtp30020297-2930) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster1_shard1_replica_n1] webapp=3D/solr path=3D/upd= ate params=3D{update.distrib=3DFROMLEADER&update.chain=3Dcdcr-processor-cha= in&waitSearcher=3Dtrue&openSearcher=3Dtrue&commit=3Dtrue&softCommit=3Dfalse= &distrib.from=3Dhttps://127.0.0.1:37317/solr/cdcr-cluster1_shard1_replica_n= 1/&commit_end_point=3Dtrue&wt=3Djavabin&version=3D2&expungeDeletes=3Dfalse}= status=3D0 QTime=3D172 [junit4] 2> 239214 INFO (qtp30020297-2876) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.s.SolrIndexSearcher Opening [Searcher@102a838[cdcr-cluster1_shard2_replic= a_n2] main] [junit4] 2> 239214 INFO (qtp30020297-2876) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 239216 INFO (searcherExecutor-765-thread-1-processing-n:1= 27.0.0.1:37317_solr x:cdcr-cluster1_shard2_replica_n2 c:cdcr-cluster1 s:sha= rd2 r:core_node4) [n:127.0.0.1:37317_solr c:cdcr-cluster1 s:shard2 r:core_n= ode4 x:cdcr-cluster1_shard2_replica_n2] o.a.s.c.SolrCore [cdcr-cluster1_sha= rd2_replica_n2] Registered new searcher Searcher@102a838[cdcr-cluster1_shar= d2_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader(Unin= verting(_0(7.5.0):C57)))} [junit4] 2> 239217 INFO (qtp30020297-2876) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.S.Request [cdcr-cluster1_shard2_replica_n2] webapp=3D/solr path=3D/upd= ate params=3D{update.distrib=3DFROMLEADER&update.chain=3Dcdcr-processor-cha= in&waitSearcher=3Dtrue&openSearcher=3Dtrue&commit=3Dtrue&softCommit=3Dfalse= &distrib.from=3Dhttps://127.0.0.1:37317/solr/cdcr-cluster1_shard1_replica_n= 1/&commit_end_point=3Dtrue&wt=3Djavabin&version=3D2&expungeDeletes=3Dfalse}= status=3D0 QTime=3D194 [junit4] 2> 239217 INFO (qtp30020297-2929) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster1_shard1_replica_n1] webapp=3D/solr path=3D/upd= ate params=3D{_stateVer_=3Dcdcr-cluster1:4&waitSearcher=3Dtrue&commit=3Dtru= e&softCommit=3Dfalse&wt=3Djavabin&version=3D2} status=3D0 QTime=3D216 [junit4] 2> 239218 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[5= 1D0AC1134D69078]) [ ] o.a.s.c.c.CdcrBidirectionalTest Adding 10 docs wit= h commit=3Dtrue, numDocs=3D200 [junit4] 2> 239231 INFO (qtp30020297-2878) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.c.S.Request [cdcr-cluster1_shard2_replica_n2] webapp=3D/solr path=3D/upd= ate params=3D{_stateVer_=3Dcdcr-cluster1:4&wt=3Djavabin&version=3D2} status= =3D0 QTime=3D11 [junit4] 2> 239232 INFO (qtp30020297-2874) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.c.S.Request [cdcr-cluster1_shard1_replica_n1] webapp=3D/solr path=3D/upd= ate params=3D{_stateVer_=3Dcdcr-cluster1:4&wt=3Djavabin&version=3D2} status= =3D0 QTime=3D13 [junit4] 2> 239235 INFO (qtp30020297-2876) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.u.DirectUpdateHandler2 start commit{_version_=3D1605183049537945600,optim= ize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,expungeDeletes=3Dfalse,= softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4] 2> 239235 INFO (qtp30020297-2879) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.u.DirectUpdateHandler2 start commit{_version_=3D1605183049537945600,optim= ize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,expungeDeletes=3Dfalse,= softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4] 2> 239238 INFO (qtp30020297-2876) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.So= lrIndexWriter@ec70f2 commitCommandVersion:1605183049537945600 [junit4] 2> 239238 INFO (qtp30020297-2879) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard2 r:core_node4 x:cdcr-cluster1_shard2_replica_n2] o.a.= s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.So= lrIndexWriter@413752 commitCommandVersion:1605183049537945600 [junit4] 2> 239418 INFO (qtp30020297-2876) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.s.SolrIndexSearcher Opening [Searcher@1e2eaf5[cdcr-cluster1_shard1_replic= a_n1] main] [junit4] 2> 239419 INFO (qtp30020297-2876) [n:127.0.0.1:37317_solr c:= cdcr-cluster1 s:shard1 r:core_node3 x:cdcr-cluster1_shard1_replica_n1] o.a.= s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 239422 INFO (searcherExecutor-764-thread-1-processing-n:1= 27.0.0.1:37317_solr x:cdcr-cluster1_shard1_replica_n1 c:cdcr-cluster1 s:sha= rd1 r:core_node3) [n:127.0.0.1:37317_solr c:cdcr-cluster1 s:shard1 r:core_n= ode3 x:cdcr-cluster1_shard1_replica_n1] o.a.s.c.SolrCore [cdcr-cluster1_sha= rd1_replica_n1] Registered ne [...truncated too long message...] 71 INFO (coreCloseExecutor-69-thread-1) [n:127.0.0.1:37737_solr c:cdcr-clu= ster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_replica_n1] o.a.s.c.Solr= Core [cdcr-cluster2_shard1_replica_n1] CLOSING SolrCore org.apache.solr.co= re.SolrCore@18a1e86 [junit4] 2> 42871 INFO (coreCloseExecutor-69-thread-2) [n:127.0.0.1:3= 7737_solr c:cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_repl= ica_n2] o.a.s.c.SolrCore [cdcr-cluster2_shard2_replica_n2] CLOSING SolrCor= e org.apache.solr.core.SolrCore@17b1f49 [junit4] 2> 42871 INFO (coreCloseExecutor-69-thread-1) [n:127.0.0.1:3= 7737_solr c:cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_repl= ica_n1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=3Ds= olr.core.cdcr-cluster2.shard1.replica_n1, tag=3D18a1e86 [junit4] 2> 42871 INFO (zkCallback-11-thread-2) [ ] o.a.s.c.c.ZkSt= ateReader A cluster state change: [WatchedEvent state:SyncConnected type:No= deDataChanged path:/collections/cdcr-cluster2/state.json] for collection [c= dcr-cluster2] has occurred - updating... (live nodes size: [0]) [junit4] 2> 42872 INFO (coreCloseExecutor-69-thread-1) [n:127.0.0.1:3= 7737_solr c:cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_repl= ica_n1] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics= .reporters.SolrJmxReporter@71718: rootName =3D solr_37737, domain =3D solr.= core.cdcr-cluster2.shard1.replica_n1, service url =3D null, agent id =3D nu= ll] for registry solr.core.cdcr-cluster2.shard1.replica_n1 / com.codahale.m= etrics.MetricRegistry@937ac8 [junit4] 2> 42882 INFO (coreCloseExecutor-69-thread-1) [n:127.0.0.1:3= 7737_solr c:cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_repl= ica_n1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=3Ds= olr.collection.cdcr-cluster2.shard1.leader, tag=3D18a1e86 [junit4] 2> 42882 INFO (coreCloseExecutor-69-thread-2) [n:127.0.0.1:3= 7737_solr c:cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_repl= ica_n2] o.a.s.m.SolrMetricManager Closing metric reporters for registry=3Ds= olr.core.cdcr-cluster2.shard2.replica_n2, tag=3D17b1f49 [junit4] 2> 42882 INFO (coreCloseExecutor-69-thread-1) [n:127.0.0.1:3= 7737_solr c:cdcr-cluster2 s:shard1 r:core_node3 x:cdcr-cluster2_shard1_repl= ica_n1] o.a.s.h.CdcrRequestHandler Solr core is being closed - shutting dow= n CDCR handler @ cdcr-cluster2:shard1 [junit4] 2> 42882 INFO (coreCloseExecutor-69-thread-2) [n:127.0.0.1:3= 7737_solr c:cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_repl= ica_n2] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics= .reporters.SolrJmxReporter@101e219: rootName =3D solr_37737, domain =3D sol= r.core.cdcr-cluster2.shard2.replica_n2, service url =3D null, agent id =3D = null] for registry solr.core.cdcr-cluster2.shard2.replica_n2 / com.codahale= .metrics.MetricRegistry@eeb88a [junit4] 2> 42891 INFO (coreCloseExecutor-69-thread-2) [n:127.0.0.1:3= 7737_solr c:cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_repl= ica_n2] o.a.s.m.SolrMetricManager Closing metric reporters for registry=3Ds= olr.collection.cdcr-cluster2.shard2.leader, tag=3D17b1f49 [junit4] 2> 42892 INFO (coreCloseExecutor-69-thread-2) [n:127.0.0.1:3= 7737_solr c:cdcr-cluster2 s:shard2 r:core_node4 x:cdcr-cluster2_shard2_repl= ica_n2] o.a.s.h.CdcrRequestHandler Solr core is being closed - shutting dow= n CDCR handler @ cdcr-cluster2:shard2 [junit4] 2> 42960 INFO (jetty-closer-2-thread-1) [ ] o.a.s.c.Overs= eer Overseer (id=3D72076890473824259-127.0.0.1:37737_solr-n_0000000000) clo= sing [junit4] 2> 42960 INFO (OverseerStateUpdate-72076890473824259-127.0.0= .1:37737_solr-n_0000000000) [ ] o.a.s.c.Overseer Overseer Loop exiting := 127.0.0.1:37737_solr [junit4] 2> 42960 WARN (OverseerAutoScalingTriggerThread-720768904738= 24259-127.0.0.1:37737_solr-n_0000000000) [ ] o.a.s.c.a.OverseerTriggerTh= read OverseerTriggerThread woken up but we are closed, exiting. [junit4] 2> 42962 INFO (jetty-closer-2-thread-1) [ ] o.e.j.s.h.Con= textHandler Stopped o.e.j.s.ServletContextHandler@7dad12{/solr,null,UNAVAIL= ABLE} [junit4] 2> 42962 INFO (jetty-closer-2-thread-1) [ ] o.e.j.s.sessi= on node0 Stopped scavenging [junit4] 2> 42962 ERROR (TEST-CdcrBidirectionalTest.testBiDir-seed#[51= D0AC1134D69078]) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not re= gistered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN se= rver state changes [junit4] 2> 42962 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[51= D0AC1134D69078]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:39579 = 39579 [junit4] 2> 44497 INFO (Thread-1) [ ] o.a.s.c.ZkTestServer connect= ing to 127.0.0.1:39579 39579 [junit4] 2> 44498 WARN (Thread-1) [ ] o.a.s.c.ZkTestServer Watch l= imit violations:=20 [junit4] 2> Maximum concurrent create/delete watches above limit: [junit4] 2>=20 [junit4] 2> =095=09/solr/aliases.json [junit4] 2> =093=09/solr/collections/cdcr-cluster2/terms/shard2 [junit4] 2> =093=09/solr/collections/cdcr-cluster2/terms/shard1 [junit4] 2> =092=09/solr/configs/cdcr-cluster2/managed-schema [junit4] 2>=20 [junit4] 2> Maximum concurrent data watches above limit: [junit4] 2>=20 [junit4] 2> =096=09/solr/collections/cdcr-cluster2/cdcr/state/process [junit4] 2> =095=09/solr/clusterstate.json [junit4] 2> =095=09/solr/clusterprops.json [junit4] 2> =092=09/solr/collections/cdcr-cluster2/cdcr/state/buffer [junit4] 2> =092=09/solr/collections/cdcr-cluster2/state.json [junit4] 2>=20 [junit4] 2> Maximum concurrent children watches above limit: [junit4] 2>=20 [junit4] 2> =095=09/solr/live_nodes [junit4] 2> =095=09/solr/collections [junit4] 2>=20 [junit4] 2> 44501 INFO (TEST-CdcrBidirectionalTest.testBiDir-seed#[51= D0AC1134D69078]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testBiDir [junit4] 2> NOTE: reproduce with: ant test -Dtestcase=3DCdcrBidirecti= onalTest -Dtests.method=3DtestBiDir -Dtests.seed=3D51D0AC1134D69078 -Dtests= .multiplier=3D3 -Dtests.slow=3Dtrue -Dtests.badapples=3Dtrue -Dtests.locale= =3Dcs -Dtests.timezone=3DAfrica/Brazzaville -Dtests.asserts=3Dtrue -Dtests.= file.encoding=3DUTF-8 [junit4] ERROR 42.7s J1 | CdcrBidirectionalTest.testBiDir <<< [junit4] > Throwable #1: com.carrotsearch.randomizedtesting.UncaughtE= xceptionError: Captured an uncaught exception in thread: Thread[id=3D224, n= ame=3Dcdcr-replicator-61-thread-1, state=3DRUNNABLE, group=3DTGRP-CdcrBidir= ectionalTest] [junit4] > =09at __randomizedtesting.SeedInfo.seed([51D0AC1134D69078:= 140B5CF32CF8DC3A]:0) [junit4] > Caused by: java.lang.AssertionError: 1605186670842347520 != =3D 1605186670636826624 [junit4] > =09at __randomizedtesting.SeedInfo.seed([51D0AC1134D69078]= :0) [junit4] > =09at org.apache.solr.update.CdcrUpdateLog$CdcrLogReader.f= orwardSeek(CdcrUpdateLog.java:611) [junit4] > =09at org.apache.solr.handler.CdcrReplicator.run(CdcrRepli= cator.java:125) [junit4] > =09at org.apache.solr.handler.CdcrReplicatorScheduler.lamb= da$null$0(CdcrReplicatorScheduler.java:81) [junit4] > =09at org.apache.solr.common.util.ExecutorUtil$MDCAwareThr= eadPoolExecutor.lambda$execute$0(ExecutorUtil.java:209) [junit4] > =09at java.util.concurrent.ThreadPoolExecutor.runWorker(Th= readPoolExecutor.java:1149) [junit4] > =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(T= hreadPoolExecutor.java:624) [junit4] > =09at java.lang.Thread.run(Thread.java:748) [junit4] 2> 44509 INFO (SUITE-CdcrBidirectionalTest-seed#[51D0AC1134D= 69078]-worker) [ ] o.a.s.SolrTestCaseJ4 --------------------------------= ----------------------- Done waiting for tracked resources to be released [junit4] 2> NOTE: test params are: codec=3DCheapBastard, sim=3DRandomS= imilarity(queryNorm=3Dfalse): {}, locale=3Dcs, timezone=3DAfrica/Brazzavill= e [junit4] 2> NOTE: Linux 4.15.0-24-generic i386/Oracle Corporation 1.8.= 0_172 (32-bit)/cpus=3D8,threads=3D1,free=3D21304872,total=3D64602112 [junit4] 2> NOTE: All tests run in this JVM: [CdcrBidirectionalTest] [junit4] Completed [2/5 (1!)] on J1 in 44.09s, 1 test, 1 error <<< FAILU= RES! [...truncated 24 lines...] BUILD FAILED /home/jenkins/workspace/Lucene-Solr-7.x-Linux/lucene/common-build.xml:1568:= The following error occurred while executing this line: /home/jenkins/workspace/Lucene-Solr-7.x-Linux/lucene/common-build.xml:1092:= There were test failures: 5 suites, 5 tests, 1 error [seed: 51D0AC1134D690= 78] Total time: 1 minute 19 seconds [repro] Setting last failure code to 256 [repro] Failures: [repro] 1/5 failed: org.apache.solr.cloud.cdcr.CdcrBidirectionalTest [repro] Exiting with code 256 + mv lucene/build lucene/build.repro + mv solr/build solr/build.repro + mv lucene/build.orig lucene/build + mv solr/build.orig solr/build Archiving artifacts Setting ANT_1_8_2_HOME=3D/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstall= ation/ANT_1.8.2 [WARNINGS] Parsing warnings in console log with parser Java Compiler (javac= ) Setting ANT_1_8_2_HOME=3D/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstall= ation/ANT_1.8.2 Setting ANT_1_8_2_HOME=3D/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstall= ation/ANT_1.8.2 Using GitBlamer to create author and commit information for al= l warnings. GIT_COMMIT=3Deaf7e32cb4f91728d2266d00c77cfab2ec684ee7, workspa= ce=3D/var/lib/jenkins/workspace/Lucene-Solr-7.x-Linux [WARNINGS] Computing warning deltas based on reference build #2266 Recording test results Setting ANT_1_8_2_HOME=3D/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstall= ation/ANT_1.8.2 Build step 'Publish JUnit test result report' changed build result to UNSTA= BLE Email was triggered for: Unstable (Test Failures) Sending email for trigger: Unstable (Test Failures) Setting ANT_1_8_2_HOME=3D/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstall= ation/ANT_1.8.2 Setting ANT_1_8_2_HOME=3D/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstall= ation/ANT_1.8.2 Setting ANT_1_8_2_HOME=3D/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstall= ation/ANT_1.8.2 Setting ANT_1_8_2_HOME=3D/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstall= ation/ANT_1.8.2 ------=_Part_40_975153955.1530825652591 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_40_975153955.1530825652591--