Build: https://builds.apache.org/job/Lucene-Solr-repro/1225/
[...truncated 28 lines...] [repro] Jenkins log URL: https://builds.apache.org/job/Lucene-Solr-BadApples-NightlyTests-7.x/22/consoleText [repro] Revision: 31220bab3a4d46458487d35526d7673d931e7de9 [repro] Ant options: -Dtests.multiplier=2 -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt [repro] Repro line: ant test -Dtestcase=CdcrBidirectionalTest -Dtests.method=testBiDir -Dtests.seed=27E82EF2F5B126B -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=es-GT -Dtests.timezone=America/Costa_Rica -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testReplicationStartStop -Dtests.seed=27E82EF2F5B126B -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=es-PE -Dtests.timezone=Asia/Vladivostok -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testBatchBoundaries -Dtests.seed=27E82EF2F5B126B -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=es-PE -Dtests.timezone=Asia/Vladivostok -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testUpdateLogSynchronisation -Dtests.seed=27E82EF2F5B126B -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=es-PE -Dtests.timezone=Asia/Vladivostok -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testReplicationAfterLeaderChange -Dtests.seed=27E82EF2F5B126B -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=es-PE -Dtests.timezone=Asia/Vladivostok -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testBatchAddsWithDelete -Dtests.seed=27E82EF2F5B126B -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=es-PE -Dtests.timezone=Asia/Vladivostok -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testBufferOnNonLeader -Dtests.seed=27E82EF2F5B126B -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=es-PE -Dtests.timezone=Asia/Vladivostok -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testReplicationAfterRestart -Dtests.seed=27E82EF2F5B126B -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=es-PE -Dtests.timezone=Asia/Vladivostok -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testResilienceWithDeleteByQueryOnTarget -Dtests.seed=27E82EF2F5B126B -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=es-PE -Dtests.timezone=Asia/Vladivostok -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testOps -Dtests.seed=27E82EF2F5B126B -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=es-PE -Dtests.timezone=Asia/Vladivostok -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [repro] Repro line: ant test -Dtestcase=RestartWhileUpdatingTest -Dtests.method=test -Dtests.seed=27E82EF2F5B126B -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=tr -Dtests.timezone=America/Port-au-Prince -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [repro] Repro line: ant test -Dtestcase=RestartWhileUpdatingTest -Dtests.seed=27E82EF2F5B126B -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=tr -Dtests.timezone=America/Port-au-Prince -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [repro] git rev-parse --abbrev-ref HEAD [repro] git rev-parse HEAD [repro] Initial local git branch/revision: 0d89ff2e6135a079e246e32af9f0deecb60c85d9 [repro] git fetch [repro] git checkout 31220bab3a4d46458487d35526d7673d931e7de9 [...truncated 2 lines...] [repro] git merge --ff-only [...truncated 1 lines...] [repro] ant clean [...truncated 6 lines...] [repro] Test suites by module: [repro] solr/core [repro] RestartWhileUpdatingTest [repro] CdcrBidirectionalTest [repro] CdcrReplicationDistributedZkTest [repro] ant compile-test [...truncated 3408 lines...] [repro] ant test-nocompile -Dtests.dups=5 -Dtests.maxfailures=15 -Dtests.class="*.RestartWhileUpdatingTest|*.CdcrBidirectionalTest|*.CdcrReplicationDistributedZkTest" -Dtests.showOutput=onerror -Dtests.multiplier=2 -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.seed=27E82EF2F5B126B -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=tr -Dtests.timezone=America/Port-au-Prince -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [...truncated 18541 lines...] [junit4] 2> 218716 ERROR (Finalizer) [ ] o.a.s.c.SolrCore REFCOUNT ERROR: unreferenced org.apache.solr.core.SolrCore@2226aa21 (collection1_shard1_replica_n25) has a reference count of -1 [junit4] 2> 218717 ERROR (Finalizer) [ ] o.a.s.c.SolrCore REFCOUNT ERROR: unreferenced org.apache.solr.core.SolrCore@3855a647 (collection1_shard1_replica_n23) has a reference count of -1 [junit4] 2> 218717 ERROR (Finalizer) [ ] o.a.s.c.SolrCore REFCOUNT ERROR: unreferenced org.apache.solr.core.SolrCore@460a5dd4 (collection1_shard1_replica_n21) has a reference count of -1 [junit4] 2> 218717 ERROR (Finalizer) [ ] o.a.s.c.SolrCore REFCOUNT ERROR: unreferenced org.apache.solr.core.SolrCore@3de55ea8 (collection1_shard1_replica_n25) has a reference count of -1 [junit4] 2> 218717 ERROR (Finalizer) [ ] o.a.s.c.SolrCore REFCOUNT ERROR: unreferenced org.apache.solr.core.SolrCore@6affc98f (collection1_shard1_replica_n23) has a reference count of -1 [junit4] 2> 218717 ERROR (Finalizer) [ ] o.a.s.c.SolrCore REFCOUNT ERROR: unreferenced org.apache.solr.core.SolrCore@123794c9 (collection1_shard1_replica_n21) has a reference count of -1 [junit4] 2> 218717 ERROR (Finalizer) [ ] o.a.s.c.SolrCore REFCOUNT ERROR: unreferenced org.apache.solr.core.SolrCore@63a04fb0 (control_collection_shard1_replica_n1) has a reference count of -1 [junit4] 2> 218871 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.e.j.s.Server jetty-9.4.11.v20180605; built: 2018-06-05T18:24:03.829Z; git: d5fc0523cfa96bfebfbda19606cad384d772f04c; jvm 1.8.0_172-b11 [junit4] 2> 218872 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0 [junit4] 2> 218872 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.e.j.s.session No SessionScavenger set, using defaults [junit4] 2> 218872 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.e.j.s.session node0 Scavenging every 660000ms [junit4] 2> 218872 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@699017ff{/,null,AVAILABLE} [junit4] 2> 218873 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@62f69926{HTTP/1.1,[http/1.1]}{127.0.0.1:37839} [junit4] 2> 218873 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.e.j.s.Server Started @218922ms [junit4] 2> 218873 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {shards=shard3, hostContext=/, hostPort=37839, coreRootDirectory=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.cdcr.CdcrReplicationDistributedZkTest_27E82EF2F5B126B-001/jetty-011/cores} [junit4] 2> 218874 ERROR (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 218874 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory [junit4] 2> 218875 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.5.0 [junit4] 2> 218875 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 218875 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 218875 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-08-14T22:34:16.649Z [junit4] 2> 218877 INFO (zkConnectionManagerCallback-432-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 218878 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper) [junit4] 2> 218878 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.cdcr.CdcrReplicationDistributedZkTest_27E82EF2F5B126B-001/jetty-011/solr.xml [junit4] 2> 218883 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored [junit4] 2> 218883 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored [junit4] 2> 218885 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@207a421f, but no JMX reporters were configured - adding default JMX reporter. [junit4] 2> 219152 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:43669/solr [junit4] 2> 219154 INFO (zkConnectionManagerCallback-436-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 219157 INFO (zkConnectionManagerCallback-438-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 219164 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2) [junit4] 2> 219169 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores [junit4] 2> 219169 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37839_ [junit4] 2> 219170 INFO (zkCallback-421-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 219171 INFO (zkCallback-412-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 219171 INFO (zkCallback-405-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 219172 INFO (zkCallback-428-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 219173 INFO (zkCallback-437-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3) [junit4] 2> 219190 INFO (zkConnectionManagerCallback-445-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 219191 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3) [junit4] 2> 219192 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:43669/solr ready [junit4] 2> 219192 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory. [junit4] 2> 219208 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@207a421f [junit4] 2> 219221 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@207a421f [junit4] 2> 219221 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@207a421f [junit4] 2> 219224 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.cdcr.CdcrReplicationDistributedZkTest_27E82EF2F5B126B-001/jetty-011/cores [junit4] 2> 219364 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.e.j.s.Server jetty-9.4.11.v20180605; built: 2018-06-05T18:24:03.829Z; git: d5fc0523cfa96bfebfbda19606cad384d772f04c; jvm 1.8.0_172-b11 [junit4] 2> 219365 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0 [junit4] 2> 219365 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.e.j.s.session No SessionScavenger set, using defaults [junit4] 2> 219365 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.e.j.s.session node0 Scavenging every 600000ms [junit4] 2> 219366 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@b8e1b1b{/,null,AVAILABLE} [junit4] 2> 219366 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@22466212{HTTP/1.1,[http/1.1]}{127.0.0.1:44711} [junit4] 2> 219367 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.e.j.s.Server Started @219415ms [junit4] 2> 219367 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {shards=shard4, hostContext=/, hostPort=44711, coreRootDirectory=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.cdcr.CdcrReplicationDistributedZkTest_27E82EF2F5B126B-001/jetty-012/cores} [junit4] 2> 219367 ERROR (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 219367 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory [junit4] 2> 219367 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.5.0 [junit4] 2> 219367 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 219367 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 219367 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-08-14T22:34:17.141Z [junit4] 2> 219369 INFO (zkConnectionManagerCallback-448-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 219371 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper) [junit4] 2> 219371 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.cdcr.CdcrReplicationDistributedZkTest_27E82EF2F5B126B-001/jetty-012/solr.xml [junit4] 2> 219376 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored [junit4] 2> 219376 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored [junit4] 2> 219377 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@207a421f, but no JMX reporters were configured - adding default JMX reporter. [junit4] 2> 219505 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:43669/solr [junit4] 2> 219507 INFO (zkConnectionManagerCallback-452-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 219511 INFO (zkConnectionManagerCallback-454-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 219517 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3) [junit4] 2> 219521 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores [junit4] 2> 219521 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44711_ [junit4] 2> 219522 INFO (zkCallback-421-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 219522 INFO (zkCallback-412-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 219522 INFO (zkCallback-437-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 219522 INFO (zkCallback-428-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 219522 INFO (zkCallback-405-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 219524 INFO (zkCallback-453-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 219525 INFO (zkCallback-444-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 219541 INFO (zkConnectionManagerCallback-461-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 219542 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 219543 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:43669/solr ready [junit4] 2> 219544 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory. [junit4] 2> 219560 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@207a421f [junit4] 2> 219569 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@207a421f [junit4] 2> 219569 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@207a421f [junit4] 2> 219571 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.cdcr.CdcrReplicationDistributedZkTest_27E82EF2F5B126B-001/jetty-012/cores [junit4] 2> 219612 INFO (zkConnectionManagerCallback-467-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 219612 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 219614 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:43669/solr ready [junit4] 2> 219615 INFO (qtp1861356375-1864) [n:127.0.0.1:44711_ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params collection.configName=conf1&name=tmp_collection&nrtReplicas=1&action=CREATE&numShards=2&createNodeSet=&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 219618 INFO (OverseerThreadFactory-372-thread-1) [ ] o.a.s.c.a.c.CreateCollectionCmd Create collection tmp_collection [junit4] 2> 219724 WARN (OverseerThreadFactory-372-thread-1) [ ] o.a.s.c.a.c.CreateCollectionCmd It is unusual to create a collection (tmp_collection) without cores. [junit4] 2> 219726 INFO (qtp1861356375-1864) [n:127.0.0.1:44711_ ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas [junit4] 2> 219727 INFO (qtp1861356375-1864) [n:127.0.0.1:44711_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={collection.configName=conf1&name=tmp_collection&nrtReplicas=1&action=CREATE&numShards=2&createNodeSet=&wt=javabin&version=2} status=0 QTime=111 [junit4] 2> 219727 INFO (qtp1861356375-1861) [n:127.0.0.1:44711_ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :addreplica with params node=127.0.0.1:39839_&action=ADDREPLICA&collection=tmp_collection&shard=shard1&type=NRT&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 219731 INFO (OverseerCollectionConfigSetProcessor-72160801340850180-127.0.0.1:39839_-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000000 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 219732 INFO (OverseerThreadFactory-372-thread-2) [ c:tmp_collection s:shard1 ] o.a.s.c.a.c.AddReplicaCmd Node Identified 127.0.0.1:39839_ for creating new replica of shard shard1 [junit4] 2> 219737 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ x:tmp_collection_shard1_replica_n41] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&name=tmp_collection_shard1_replica_n41&action=CREATE&collection=tmp_collection&shard=shard1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 219737 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ x:tmp_collection_shard1_replica_n41] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores [junit4] 2> 220762 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.5.0 [junit4] 2> 220771 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.s.IndexSchema [tmp_collection_shard1_replica_n41] Schema name=test [junit4] 2> 220837 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id [junit4] 2> 220854 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.c.CoreContainer Creating SolrCore 'tmp_collection_shard1_replica_n41' using configuration from collection tmp_collection, trusted=true [junit4] 2> 220854 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.tmp_collection.shard1.replica_n41' (registry 'solr.core.tmp_collection.shard1.replica_n41') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@207a421f [junit4] 2> 220854 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 220854 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.c.SolrCore [[tmp_collection_shard1_replica_n41] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.cdcr.CdcrReplicationDistributedZkTest_27E82EF2F5B126B-001/jetty-009/cores/tmp_collection_shard1_replica_n41], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.cdcr.CdcrReplicationDistributedZkTest_27E82EF2F5B126B-001/jetty-009/cores/tmp_collection_shard1_replica_n41/data/] [junit4] 2> 220858 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.MockRandomMergePolicy: org.apache.lucene.index.MockRandomMergePolicy@5e0c0ac [junit4] 2> 220899 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.CdcrUpdateLog [junit4] 2> 220899 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 220900 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 220900 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 220901 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=47, maxMergeAtOnceExplicit=45, maxMergedSegmentMB=0.9853515625, floorSegmentMB=1.267578125, forceMergeDeletesPctAllowed=0.612340156204586, segmentsPerTier=15.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0, deletesPctAllowed=37.04522294109195 [junit4] 2> 220902 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.s.SolrIndexSearcher Opening [Searcher@208fbc6b[tmp_collection_shard1_replica_n41] main] [junit4] 2> 220903 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 220903 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 220904 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 220906 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.h.CdcrBufferStateManager Created znode /collections/tmp_collection/cdcr/state/buffer [junit4] 2> 220907 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.h.CdcrProcessStateManager Created znode /collections/tmp_collection/cdcr/state/process [junit4] 2> 220908 INFO (searcherExecutor-404-thread-1-processing-n:127.0.0.1:39839_ x:tmp_collection_shard1_replica_n41 c:tmp_collection s:shard1) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.c.SolrCore [tmp_collection_shard1_replica_n41] Registered new searcher Searcher@208fbc6b[tmp_collection_shard1_replica_n41] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 220909 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1608815538269585408 [junit4] 2> 220914 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.c.ZkShardTerms Successful update of terms at /collections/tmp_collection/terms/shard1 to Terms{values={core_node42=0}, version=0} [junit4] 2> 220917 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 220917 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 220917 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:39839/tmp_collection_shard1_replica_n41/ [junit4] 2> 220917 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 220917 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.c.SyncStrategy http://127.0.0.1:39839/tmp_collection_shard1_replica_n41/ has no replicas [junit4] 2> 220917 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 220922 INFO (zkCallback-405-thread-1) [ ] o.a.s.h.CdcrLeaderStateManager Received new leader state @ tmp_collection:shard1 [junit4] 2> 220926 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:39839/tmp_collection_shard1_replica_n41/ shard1 [junit4] 2> 221029 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 221031 INFO (qtp962526414-1766) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n41] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&name=tmp_collection_shard1_replica_n41&action=CREATE&collection=tmp_collection&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1294 [junit4] 2> 221033 INFO (qtp1861356375-1861) [n:127.0.0.1:44711_ c:tmp_collection ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={node=127.0.0.1:39839_&action=ADDREPLICA&collection=tmp_collection&shard=shard1&type=NRT&wt=javabin&version=2} status=0 QTime=1305 [junit4] 2> 221034 INFO (qtp1861356375-1863) [n:127.0.0.1:44711_ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :addreplica with params node=127.0.0.1:41715_&action=ADDREPLICA&collection=tmp_collection&shard=shard2&type=NRT&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 221036 INFO (OverseerCollectionConfigSetProcessor-72160801340850180-127.0.0.1:39839_-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000002 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 221038 INFO (OverseerThreadFactory-372-thread-3) [ c:tmp_collection s:shard2 ] o.a.s.c.a.c.AddReplicaCmd Node Identified 127.0.0.1:41715_ for creating new replica of shard shard2 [junit4] 2> 221041 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ x:tmp_collection_shard2_replica_n43] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&name=tmp_collection_shard2_replica_n43&action=CREATE&collection=tmp_collection&shard=shard2&wt=javabin&version=2&replicaType=NRT [junit4] 2> 221145 INFO (zkCallback-405-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 222057 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.5.0 [junit4] 2> 222067 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.s.IndexSchema [tmp_collection_shard2_replica_n43] Schema name=test [junit4] 2> 222132 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id [junit4] 2> 222149 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.c.CoreContainer Creating SolrCore 'tmp_collection_shard2_replica_n43' using configuration from collection tmp_collection, trusted=true [junit4] 2> 222150 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.tmp_collection.shard2.replica_n43' (registry 'solr.core.tmp_collection.shard2.replica_n43') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@207a421f [junit4] 2> 222150 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 222150 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.c.SolrCore [[tmp_collection_shard2_replica_n43] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.cdcr.CdcrReplicationDistributedZkTest_27E82EF2F5B126B-001/jetty-010/cores/tmp_collection_shard2_replica_n43], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.cdcr.CdcrReplicationDistributedZkTest_27E82EF2F5B126B-001/jetty-010/cores/tmp_collection_shard2_replica_n43/data/] [junit4] 2> 222155 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.MockRandomMergePolicy: org.apache.lucene.index.MockRandomMergePolicy@6cd4cb71 [junit4] 2> 222196 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.CdcrUpdateLog [junit4] 2> 222196 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 222197 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 222197 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 222199 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=47, maxMergeAtOnceExplicit=45, maxMergedSegmentMB=0.9853515625, floorSegmentMB=1.267578125, forceMergeDeletesPctAllowed=0.612340156204586, segmentsPerTier=15.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0, deletesPctAllowed=37.04522294109195 [junit4] 2> 222199 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.s.SolrIndexSearcher Opening [Searcher@7bcdedec[tmp_collection_shard2_replica_n43] main] [junit4] 2> 222201 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 222201 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 222202 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 222205 INFO (searcherExecutor-410-thread-1-processing-n:127.0.0.1:41715_ x:tmp_collection_shard2_replica_n43 c:tmp_collection s:shard2) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.c.SolrCore [tmp_collection_shard2_replica_n43] Registered new searcher Searcher@7bcdedec[tmp_collection_shard2_replica_n43] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 222205 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1608815539628539904 [junit4] 2> 222211 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.c.ZkShardTerms Successful update of terms at /collections/tmp_collection/terms/shard2 to Terms{values={core_node44=0}, version=0} [junit4] 2> 222214 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 222214 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 222214 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:41715/tmp_collection_shard2_replica_n43/ [junit4] 2> 222214 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 222214 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.c.SyncStrategy http://127.0.0.1:41715/tmp_collection_shard2_replica_n43/ has no replicas [junit4] 2> 222214 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 222216 INFO (zkCallback-421-thread-1) [ ] o.a.s.h.CdcrLeaderStateManager Received new leader state @ tmp_collection:shard2 [junit4] 2> 222218 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:41715/tmp_collection_shard2_replica_n43/ shard2 [junit4] 2> 222321 INFO (zkCallback-405-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 222322 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 222325 INFO (qtp1199135375-1804) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n43] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&name=tmp_collection_shard2_replica_n43&action=CREATE&collection=tmp_collection&shard=shard2&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1283 [junit4] 2> 222327 INFO (qtp1861356375-1863) [n:127.0.0.1:44711_ c:tmp_collection ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={node=127.0.0.1:41715_&action=ADDREPLICA&collection=tmp_collection&shard=shard2&type=NRT&wt=javabin&version=2} status=0 QTime=1293 [junit4] 2> 222328 INFO (qtp1861356375-1866) [n:127.0.0.1:44711_ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :addreplica with params node=127.0.0.1:37839_&action=ADDREPLICA&collection=tmp_collection&shard=shard1&type=NRT&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 222330 INFO (OverseerCollectionConfigSetProcessor-72160801340850180-127.0.0.1:39839_-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000004 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 222331 INFO (OverseerThreadFactory-372-thread-4) [ c:tmp_collection s:shard1 ] o.a.s.c.a.c.AddReplicaCmd Node Identified 127.0.0.1:37839_ for creating new replica of shard shard1 [junit4] 2> 222335 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&name=tmp_collection_shard1_replica_n45&action=CREATE&collection=tmp_collection&shard=shard1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 222441 INFO (zkCallback-421-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 222441 INFO (zkCallback-405-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 223352 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.5.0 [junit4] 2> 223362 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.s.IndexSchema [tmp_collection_shard1_replica_n45] Schema name=test [junit4] 2> 223430 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id [junit4] 2> 223447 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.c.CoreContainer Creating SolrCore 'tmp_collection_shard1_replica_n45' using configuration from collection tmp_collection, trusted=true [junit4] 2> 223448 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.tmp_collection.shard1.replica_n45' (registry 'solr.core.tmp_collection.shard1.replica_n45') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@207a421f [junit4] 2> 223448 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 223448 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.c.SolrCore [[tmp_collection_shard1_replica_n45] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.cdcr.CdcrReplicationDistributedZkTest_27E82EF2F5B126B-001/jetty-011/cores/tmp_collection_shard1_replica_n45], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.cdcr.CdcrReplicationDistributedZkTest_27E82EF2F5B126B-001/jetty-011/cores/tmp_collection_shard1_replica_n45/data/] [junit4] 2> 223452 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.MockRandomMergePolicy: org.apache.lucene.index.MockRandomMergePolicy@5bca373e [junit4] 2> 223494 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.CdcrUpdateLog [junit4] 2> 223494 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 223495 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 223495 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 223496 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=47, maxMergeAtOnceExplicit=45, maxMergedSegmentMB=0.9853515625, floorSegmentMB=1.267578125, forceMergeDeletesPctAllowed=0.612340156204586, segmentsPerTier=15.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0, deletesPctAllowed=37.04522294109195 [junit4] 2> 223496 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.s.SolrIndexSearcher Opening [Searcher@1fe1d24c[tmp_collection_shard1_replica_n45] main] [junit4] 2> 223498 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 223498 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 223499 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 223500 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1608815540986445824 [junit4] 2> 223509 INFO (searcherExecutor-416-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.c.SolrCore [tmp_collection_shard1_replica_n45] Registered new searcher Searcher@1fe1d24c[tmp_collection_shard1_replica_n45] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 223509 INFO (qtp962526414-1761) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 r:core_node42 x:tmp_collection_shard1_replica_n41] o.a.s.c.S.Request [tmp_collection_shard1_replica_n41] webapp= path=/cdcr params={action=LASTPROCESSEDVERSION&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 223513 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.c.ZkShardTerms Successful update of terms at /collections/tmp_collection/terms/shard1 to Terms{values={core_node42=0, core_node46=0}, version=1} [junit4] 2> 223514 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.c.ZkController Core needs to recover:tmp_collection_shard1_replica_n45 [junit4] 2> 223515 INFO (updateExecutor-433-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.u.DefaultSolrCoreState Running recovery [junit4] 2> 223515 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.RecoveryStrategy Starting recovery process. recoveringAfterStartup=true [junit4] 2> 223516 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.RecoveryStrategy ###### startupVersions=[[]] [junit4] 2> 223517 INFO (qtp1319590639-1834) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 x:tmp_collection_shard1_replica_n45] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&name=tmp_collection_shard1_replica_n45&action=CREATE&collection=tmp_collection&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1181 [junit4] 2> 223519 INFO (qtp1861356375-1866) [n:127.0.0.1:44711_ c:tmp_collection ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={node=127.0.0.1:37839_&action=ADDREPLICA&collection=tmp_collection&shard=shard1&type=NRT&wt=javabin&version=2} status=0 QTime=1191 [junit4] 2> 223520 INFO (qtp1861356375-1863) [n:127.0.0.1:44711_ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :addreplica with params node=127.0.0.1:44711_&action=ADDREPLICA&collection=tmp_collection&shard=shard2&type=NRT&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 223520 INFO (qtp962526414-1762) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 r:core_node42 x:tmp_collection_shard1_replica_n41] o.a.s.c.S.Request [tmp_collection_shard1_replica_n41] webapp= path=/admin/ping params={wt=javabin&version=2} hits=0 status=0 QTime=0 [junit4] 2> 223520 INFO (qtp962526414-1762) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 r:core_node42 x:tmp_collection_shard1_replica_n41] o.a.s.c.S.Request [tmp_collection_shard1_replica_n41] webapp= path=/admin/ping params={wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 223522 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[tmp_collection_shard1_replica_n45] [junit4] 2> 223522 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null} [junit4] 2> 223522 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.RecoveryStrategy Publishing state of core [tmp_collection_shard1_replica_n45] as recovering, leader is [http://127.0.0.1:39839/tmp_collection_shard1_replica_n41/] and I am [http://127.0.0.1:37839/tmp_collection_shard1_replica_n45/] [junit4] 2> 223528 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.ZkShardTerms Successful update of terms at /collections/tmp_collection/terms/shard1 to Terms{values={core_node42=0, core_node46=0, core_node46_recovering=0}, version=2} [junit4] 2> 223530 INFO (OverseerCollectionConfigSetProcessor-72160801340850180-127.0.0.1:39839_-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000006 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 223530 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://127.0.0.1:39839]; [WaitForState: action=PREPRECOVERY&core=tmp_collection_shard1_replica_n41&nodeName=127.0.0.1:37839_&coreNodeName=core_node46&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true] [junit4] 2> 223531 INFO (qtp962526414-1768) [n:127.0.0.1:39839_ x:tmp_collection_shard1_replica_n41] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node46, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true, maxTime: 183 s [junit4] 2> 223532 INFO (qtp962526414-1768) [n:127.0.0.1:39839_ x:tmp_collection_shard1_replica_n41] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=tmp_collection, shard=shard1, thisCore=tmp_collection_shard1_replica_n41, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=down, localState=active, nodeName=127.0.0.1:37839_, coreNodeName=core_node46, onlyIfActiveCheckResult=false, nodeProps: core_node46:{"core":"tmp_collection_shard1_replica_n45","base_url":"http://127.0.0.1:37839","node_name":"127.0.0.1:37839_","state":"down","type":"NRT"} [junit4] 2> 223533 INFO (OverseerThreadFactory-372-thread-5) [ c:tmp_collection s:shard2 ] o.a.s.c.a.c.AddReplicaCmd Node Identified 127.0.0.1:44711_ for creating new replica of shard shard2 [junit4] 2> 223538 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ x:tmp_collection_shard2_replica_n47] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&name=tmp_collection_shard2_replica_n47&action=CREATE&collection=tmp_collection&shard=shard2&wt=javabin&version=2&replicaType=NRT [junit4] 2> 223642 INFO (zkCallback-421-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 223642 INFO (zkCallback-405-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 223642 INFO (zkCallback-437-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 223642 INFO (zkCallback-437-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 224512 INFO (qtp962526414-1765) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 r:core_node42 x:tmp_collection_shard1_replica_n41] o.a.s.c.S.Request [tmp_collection_shard1_replica_n41] webapp= path=/cdcr params={action=LASTPROCESSEDVERSION&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 224532 INFO (qtp962526414-1768) [n:127.0.0.1:39839_ x:tmp_collection_shard1_replica_n41] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=tmp_collection, shard=shard1, thisCore=tmp_collection_shard1_replica_n41, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=recovering, localState=active, nodeName=127.0.0.1:37839_, coreNodeName=core_node46, onlyIfActiveCheckResult=false, nodeProps: core_node46:{"core":"tmp_collection_shard1_replica_n45","base_url":"http://127.0.0.1:37839","node_name":"127.0.0.1:37839_","state":"recovering","type":"NRT"} [junit4] 2> 224532 INFO (qtp962526414-1768) [n:127.0.0.1:39839_ x:tmp_collection_shard1_replica_n41] o.a.s.h.a.PrepRecoveryOp Waited coreNodeName: core_node46, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds. [junit4] 2> 224532 INFO (qtp962526414-1768) [n:127.0.0.1:39839_ x:tmp_collection_shard1_replica_n41] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={nodeName=127.0.0.1:37839_&onlyIfLeaderActive=true&core=tmp_collection_shard1_replica_n41&coreNodeName=core_node46&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=0 QTime=1001 [junit4] 2> 224557 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.5.0 [junit4] 2> 224567 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.s.IndexSchema [tmp_collection_shard2_replica_n47] Schema name=test [junit4] 2> 224640 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id [junit4] 2> 224656 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.c.CoreContainer Creating SolrCore 'tmp_collection_shard2_replica_n47' using configuration from collection tmp_collection, trusted=true [junit4] 2> 224656 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.tmp_collection.shard2.replica_n47' (registry 'solr.core.tmp_collection.shard2.replica_n47') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@207a421f [junit4] 2> 224656 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 224656 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.c.SolrCore [[tmp_collection_shard2_replica_n47] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.cdcr.CdcrReplicationDistributedZkTest_27E82EF2F5B126B-001/jetty-012/cores/tmp_collection_shard2_replica_n47], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.cdcr.CdcrReplicationDistributedZkTest_27E82EF2F5B126B-001/jetty-012/cores/tmp_collection_shard2_replica_n47/data/] [junit4] 2> 224661 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.MockRandomMergePolicy: org.apache.lucene.index.MockRandomMergePolicy@4bb66a87 [junit4] 2> 224702 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.CdcrUpdateLog [junit4] 2> 224702 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 224703 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 224703 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 224704 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=47, maxMergeAtOnceExplicit=45, maxMergedSegmentMB=0.9853515625, floorSegmentMB=1.267578125, forceMergeDeletesPctAllowed=0.612340156204586, segmentsPerTier=15.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0, deletesPctAllowed=37.04522294109195 [junit4] 2> 224705 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.s.SolrIndexSearcher Opening [Searcher@4bd59345[tmp_collection_shard2_replica_n47] main] [junit4] 2> 224706 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 224706 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 224707 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 224708 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1608815542253125632 [junit4] 2> 224710 INFO (searcherExecutor-422-thread-1-processing-n:127.0.0.1:44711_ x:tmp_collection_shard2_replica_n47 c:tmp_collection s:shard2) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.c.SolrCore [tmp_collection_shard2_replica_n47] Registered new searcher Searcher@4bd59345[tmp_collection_shard2_replica_n47] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 224715 INFO (qtp1199135375-1799) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 r:core_node44 x:tmp_collection_shard2_replica_n43] o.a.s.c.S.Request [tmp_collection_shard2_replica_n43] webapp= path=/cdcr params={action=LASTPROCESSEDVERSION&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 224718 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.c.ZkShardTerms Successful update of terms at /collections/tmp_collection/terms/shard2 to Terms{values={core_node44=0, core_node48=0}, version=1} [junit4] 2> 224719 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.c.ZkController Core needs to recover:tmp_collection_shard2_replica_n47 [junit4] 2> 224725 INFO (updateExecutor-449-thread-1-processing-n:127.0.0.1:44711_ x:tmp_collection_shard2_replica_n47 c:tmp_collection s:shard2) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 r:core_node48 x:tmp_collection_shard2_replica_n47] o.a.s.u.DefaultSolrCoreState Running recovery [junit4] 2> 224725 INFO (recoveryExecutor-450-thread-1-processing-n:127.0.0.1:44711_ x:tmp_collection_shard2_replica_n47 c:tmp_collection s:shard2 r:core_node48) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 r:core_node48 x:tmp_collection_shard2_replica_n47] o.a.s.c.RecoveryStrategy Starting recovery process. recoveringAfterStartup=true [junit4] 2> 224726 INFO (recoveryExecutor-450-thread-1-processing-n:127.0.0.1:44711_ x:tmp_collection_shard2_replica_n47 c:tmp_collection s:shard2 r:core_node48) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 r:core_node48 x:tmp_collection_shard2_replica_n47] o.a.s.c.RecoveryStrategy ###### startupVersions=[[]] [junit4] 2> 224727 INFO (qtp1861356375-1860) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 x:tmp_collection_shard2_replica_n47] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&name=tmp_collection_shard2_replica_n47&action=CREATE&collection=tmp_collection&shard=shard2&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1190 [junit4] 2> 224729 INFO (qtp1199135375-1800) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 r:core_node44 x:tmp_collection_shard2_replica_n43] o.a.s.c.S.Request [tmp_collection_shard2_replica_n43] webapp= path=/admin/ping params={wt=javabin&version=2} hits=0 status=0 QTime=0 [junit4] 2> 224729 INFO (qtp1199135375-1800) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 r:core_node44 x:tmp_collection_shard2_replica_n43] o.a.s.c.S.Request [tmp_collection_shard2_replica_n43] webapp= path=/admin/ping params={wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 224735 INFO (recoveryExecutor-450-thread-1-processing-n:127.0.0.1:44711_ x:tmp_collection_shard2_replica_n47 c:tmp_collection s:shard2 r:core_node48) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 r:core_node48 x:tmp_collection_shard2_replica_n47] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[tmp_collection_shard2_replica_n47] [junit4] 2> 224735 INFO (recoveryExecutor-450-thread-1-processing-n:127.0.0.1:44711_ x:tmp_collection_shard2_replica_n47 c:tmp_collection s:shard2 r:core_node48) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 r:core_node48 x:tmp_collection_shard2_replica_n47] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null} [junit4] 2> 224735 INFO (recoveryExecutor-450-thread-1-processing-n:127.0.0.1:44711_ x:tmp_collection_shard2_replica_n47 c:tmp_collection s:shard2 r:core_node48) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 r:core_node48 x:tmp_collection_shard2_replica_n47] o.a.s.c.RecoveryStrategy Publishing state of core [tmp_collection_shard2_replica_n47] as recovering, leader is [http://127.0.0.1:41715/tmp_collection_shard2_replica_n43/] and I am [http://127.0.0.1:44711/tmp_collection_shard2_replica_n47/] [junit4] 2> 224737 INFO (qtp1861356375-1863) [n:127.0.0.1:44711_ c:tmp_collection ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={node=127.0.0.1:44711_&action=ADDREPLICA&collection=tmp_collection&shard=shard2&type=NRT&wt=javabin&version=2} status=0 QTime=1217 [junit4] 2> 224745 INFO (recoveryExecutor-450-thread-1-processing-n:127.0.0.1:44711_ x:tmp_collection_shard2_replica_n47 c:tmp_collection s:shard2 r:core_node48) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 r:core_node48 x:tmp_collection_shard2_replica_n47] o.a.s.c.ZkShardTerms Successful update of terms at /collections/tmp_collection/terms/shard2 to Terms{values={core_node48_recovering=0, core_node44=0, core_node48=0}, version=2} [junit4] 2> 224745 INFO (TEST-CdcrReplicationDistributedZkTest.testReplicationStartStop-seed#[27E82EF2F5B126B]) [ ] o.a.s.c.AbstractDistribZkTestBase Wait for recoveries to finish - collection: tmp_collection failOnTimeout:true timeout (sec):330 [junit4] 1> - [junit4] 1> replica:core_node42 rstate:active live:true [junit4] 1> replica:core_node46 rstate:recovering live:true [junit4] 1> replica:core_node44 rstate:active live:true [junit4] 1> replica:core_node48 rstate:down live:true [junit4] 2> 224746 INFO (recoveryExecutor-450-thread-1-processing-n:127.0.0.1:44711_ x:tmp_collection_shard2_replica_n47 c:tmp_collection s:shard2 r:core_node48) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 r:core_node48 x:tmp_collection_shard2_replica_n47] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://127.0.0.1:41715]; [WaitForState: action=PREPRECOVERY&core=tmp_collection_shard2_replica_n43&nodeName=127.0.0.1:44711_&coreNodeName=core_node48&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true] [junit4] 2> 224747 INFO (qtp1199135375-1806) [n:127.0.0.1:41715_ x:tmp_collection_shard2_replica_n43] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node48, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true, maxTime: 183 s [junit4] 2> 224748 INFO (qtp1199135375-1806) [n:127.0.0.1:41715_ x:tmp_collection_shard2_replica_n43] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=tmp_collection, shard=shard2, thisCore=tmp_collection_shard2_replica_n43, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=down, localState=active, nodeName=127.0.0.1:44711_, coreNodeName=core_node48, onlyIfActiveCheckResult=false, nodeProps: core_node48:{"core":"tmp_collection_shard2_replica_n47","base_url":"http://127.0.0.1:44711","node_name":"127.0.0.1:44711_","state":"down","type":"NRT"} [junit4] 2> 224847 INFO (zkCallback-421-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 224847 INFO (zkCallback-437-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 224847 INFO (zkCallback-405-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 224847 INFO (zkCallback-437-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 224847 INFO (zkCallback-453-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 224847 INFO (zkCallback-453-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 225033 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.RecoveryStrategy Attempting to PeerSync from [http://127.0.0.1:39839/tmp_collection_shard1_replica_n41/] - recoveringAfterStartup=[true] [junit4] 2> 225033 WARN (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.u.PeerSyncWithLeader no frame of reference to tell if we've missed updates [junit4] 2> 225034 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.RecoveryStrategy PeerSync Recovery was not successful - trying replication. [junit4] 2> 225034 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.RecoveryStrategy Starting Replication Recovery. [junit4] 2> 225034 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.RecoveryStrategy Attempting to replicate from [http://127.0.0.1:39839/tmp_collection_shard1_replica_n41/]. [junit4] 2> 225037 INFO (qtp962526414-1768) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 r:core_node42 x:tmp_collection_shard1_replica_n41] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1608815542598107136,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 225038 INFO (qtp962526414-1768) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 r:core_node42 x:tmp_collection_shard1_replica_n41] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit. [junit4] 2> 225040 INFO (qtp962526414-1768) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 r:core_node42 x:tmp_collection_shard1_replica_n41] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 225040 INFO (qtp962526414-1768) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 r:core_node42 x:tmp_collection_shard1_replica_n41] o.a.s.c.S.Request [tmp_collection_shard1_replica_n41] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&softCommit=false&commit_end_point=true&wt=javabin&version=2} status=0 QTime=3 [junit4] 2> 225042 INFO (qtp962526414-1765) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 r:core_node42 x:tmp_collection_shard1_replica_n41] o.a.s.c.S.Request [tmp_collection_shard1_replica_n41] webapp= path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0 [junit4] 2> 225042 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.h.IndexFetcher Master's generation: 1 [junit4] 2> 225043 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.h.IndexFetcher Master's version: 0 [junit4] 2> 225043 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.h.IndexFetcher Slave's generation: 1 [junit4] 2> 225043 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.h.IndexFetcher Slave's version: 0 [junit4] 2> 225043 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.h.IndexFetcher New index in Master. Deleting mine... [junit4] 2> 225045 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.s.SolrIndexSearcher Opening [Searcher@6d4a8122[tmp_collection_shard1_replica_n45] main] [junit4] 2> 225046 INFO (searcherExecutor-416-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.SolrCore [tmp_collection_shard1_replica_n45] Registered new searcher Searcher@6d4a8122[tmp_collection_shard1_replica_n45] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 225047 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.RecoveryStrategy No replay needed. [junit4] 2> 225047 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.RecoveryStrategy Replication Recovery was successful. [junit4] 2> 225047 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.RecoveryStrategy Registering as Active after recovery. [junit4] 2> 225048 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.ZkShardTerms Successful update of terms at /collections/tmp_collection/terms/shard1 to Terms{values={core_node42=0, core_node46=0}, version=3} [junit4] 2> 225048 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.RecoveryStrategy Updating version bucket highest from index after successful recovery. [junit4] 2> 225048 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1608815542609641472 [junit4] 2> 225050 INFO (recoveryExecutor-434-thread-1-processing-n:127.0.0.1:37839_ x:tmp_collection_shard1_replica_n45 c:tmp_collection s:shard1 r:core_node46) [n:127.0.0.1:37839_ c:tmp_collection s:shard1 r:core_node46 x:tmp_collection_shard1_replica_n45] o.a.s.c.RecoveryStrategy Finished recovery process, successful=[true] [junit4] 2> 225150 INFO (zkCallback-405-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 225150 INFO (zkCallback-421-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 225150 INFO (zkCallback-437-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 225150 INFO (zkCallback-453-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 225150 INFO (zkCallback-453-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 225150 INFO (zkCallback-437-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tmp_collection/state.json] for collection [tmp_collection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 225514 INFO (qtp962526414-1764) [n:127.0.0.1:39839_ c:tmp_collection s:shard1 r:core_node42 x:tmp_collection_shard1_replica_n41] o.a.s.c.S.Request [tmp_collection_shard1_replica_n41] webapp= path=/cdcr params={action=LASTPROCESSEDVERSION&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 225539 INFO (OverseerCollectionConfigSetProcessor-72160801340850180-127.0.0.1:39839_-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000008 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 225719 INFO (qtp1199135375-1800) [n:127.0.0.1:41715_ c:tmp_collection s:shard2 r:core_node44 x:tmp_collection_shard2_replica_n43] o.a.s.c.S.Request [tmp_collection_shard2_replica_n43] webapp= path=/cdcr params={action=LASTPROCESSEDVERSION&wt=javabin&version=2} status=0 QTime=0 [junit4] 1> - [junit4] 1> replica:core_node42 rstate:active live:true [junit4] 1> replica:core_node46 rstate:active live:true [junit4] 1> replica:core_node44 rstate:active live:true [junit4] 1> replica:core_node48 rstate:recovering live:true [junit4] 2> 225748 INFO (qtp1199135375-1806) [n:127.0.0.1:41715_ x:tmp_collection_shard2_replica_n43] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=tmp_collection, shard=shard2, thisCore=tmp_collection_shard2_replica_n43, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=recovering, localState=active, nodeName=127.0.0.1:44711_, coreNodeName=core_node48, onlyIfActiveCheckResult=false, nodeProps: core_node48:{"core":"tmp_collection_shard2_replica_n47","base_url":"http://127.0.0.1:44711","node_name":"127.0.0.1:44711_","state":"recovering","type":"NRT"} [junit4] 2> 225748 INFO (qtp1199135375-1806) [n:127.0.0.1:41715_ x:tmp_collection_shard2_replica_n43] o.a.s.h.a.PrepRecoveryOp Waited coreNodeName: core_node48, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds. [junit4] 2> 225749 INFO (qtp1199135375-1806) [n:127.0.0.1:41715_ x:tmp_collection_shard2_replica_n43] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={nodeName=127.0.0.1:44711_&onlyIfLeaderActive=true&core=tmp_collection_shard2_replica_n43&coreNodeName=core_node48&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=0 QTime=1001 [junit4] 2> 226249 INFO (recoveryExecutor-450-thread-1-processing-n:127.0.0.1:44711_ x:tmp_collection_shard2_replica_n47 c:tmp_collection s:shard2 r:core_node48) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 r:core_node48 x:tmp_collection_shard2_replica_n47] o.a.s.c.RecoveryStrategy Attempting to PeerSync from [http://127.0.0.1:41715/tmp_collection_shard2_replica_n43/] - recoveringAfterStartup=[true] [junit4] 2> 226250 WARN (recoveryExecutor-450-thread-1-processing-n:127.0.0.1:44711_ x:tmp_collection_shard2_replica_n47 c:tmp_collection s:shard2 r:core_node48) [n:127.0.0.1:44711_ c:tmp_collection s:shard2 r:core_node48 x:tmp_collection_shard2_replica_n47] o.a.s.u.Pee [...truncated too long message...] rent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) [junit4] > at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) [junit4] > at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) [junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) [junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] > at java.lang.Thread.run(Thread.java:748) [junit4] > at __randomizedtesting.SeedInfo.seed([27E82EF2F5B126B]:0)Throwable #2: com.carrotsearch.randomizedtesting.ThreadLeakError: There are still zombie threads that couldn't be terminated: [junit4] > 1) Thread[id=15105, name=searcherExecutor-2983-thread-1, state=WAITING, group=TGRP-RestartWhileUpdatingTest] [junit4] > at sun.misc.Unsafe.park(Native Method) [junit4] > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) [junit4] > at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) [junit4] > at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) [junit4] > at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) [junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) [junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] > at java.lang.Thread.run(Thread.java:748) [junit4] > 2) Thread[id=15059, name=searcherExecutor-2969-thread-1, state=WAITING, group=TGRP-RestartWhileUpdatingTest] [junit4] > at sun.misc.Unsafe.park(Native Method) [junit4] > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) [junit4] > at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) [junit4] > at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) [junit4] > at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) [junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) [junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] > at java.lang.Thread.run(Thread.java:748) [junit4] > 3) Thread[id=14978, name=searcherExecutor-2941-thread-1, state=WAITING, group=TGRP-RestartWhileUpdatingTest] [junit4] > at sun.misc.Unsafe.park(Native Method) [junit4] > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) [junit4] > at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) [junit4] > at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) [junit4] > at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) [junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) [junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] > at java.lang.Thread.run(Thread.java:748) [junit4] > 4) Thread[id=15426, name=searcherExecutor-3003-thread-1, state=WAITING, group=TGRP-RestartWhileUpdatingTest] [junit4] > at sun.misc.Unsafe.park(Native Method) [junit4] > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) [junit4] > at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) [junit4] > at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) [junit4] > at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) [junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) [junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] > at java.lang.Thread.run(Thread.java:748) [junit4] > 5) Thread[id=15021, name=searcherExecutor-2955-thread-1, state=WAITING, group=TGRP-RestartWhileUpdatingTest] [junit4] > at sun.misc.Unsafe.park(Native Method) [junit4] > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) [junit4] > at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) [junit4] > at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) [junit4] > at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) [junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) [junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] > at java.lang.Thread.run(Thread.java:748) [junit4] > 6) Thread[id=15498, name=searcherExecutor-3031-thread-1, state=WAITING, group=TGRP-RestartWhileUpdatingTest] [junit4] > at sun.misc.Unsafe.park(Native Method) [junit4] > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) [junit4] > at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) [junit4] > at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) [junit4] > at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) [junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) [junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] > at java.lang.Thread.run(Thread.java:748) [junit4] > 7) Thread[id=15462, name=searcherExecutor-3017-thread-1, state=WAITING, group=TGRP-RestartWhileUpdatingTest] [junit4] > at sun.misc.Unsafe.park(Native Method) [junit4] > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) [junit4] > at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) [junit4] > at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) [junit4] > at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) [junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) [junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] > at java.lang.Thread.run(Thread.java:748) [junit4] > at __randomizedtesting.SeedInfo.seed([27E82EF2F5B126B]:0) [junit4] Completed [15/15 (4!)] on J1 in 470.19s, 1 test, 1 failure, 2 errors <<< FAILURES! [junit4] [junit4] [junit4] Tests with failures [seed: 27E82EF2F5B126B] (first 10 out of 23): [junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testReplicationStartStop [junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testReplicationStartStop [junit4] - org.apache.solr.cloud.RestartWhileUpdatingTest.test [junit4] - org.apache.solr.cloud.RestartWhileUpdatingTest (suite) [junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testBatchBoundaries [junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testBatchBoundaries [junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testUpdateLogSynchronisation [junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testUpdateLogSynchronisation [junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testReplicationAfterLeaderChange [junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testBatchAddsWithDelete [junit4] [junit4] [junit4] JVM J0: 0.71 .. 491.53 = 490.83s [junit4] JVM J1: 0.71 .. 2123.39 = 2122.67s [junit4] JVM J2: 0.71 .. 1666.28 = 1665.57s [junit4] Execution time total: 35 minutes 23 seconds [junit4] Tests summary: 15 suites, 65 tests, 6 suite-level errors, 18 errors, 2 failures, 39 ignored BUILD FAILED /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/lucene/common-build.xml:1568: The following error occurred while executing this line: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/lucene/common-build.xml:1092: There were test failures: 15 suites, 65 tests, 6 suite-level errors, 18 errors, 2 failures, 39 ignored [seed: 27E82EF2F5B126B] Total time: 35 minutes 25 seconds [repro] Setting last failure code to 256 [repro] Failures: [repro] 0/5 failed: org.apache.solr.cloud.cdcr.CdcrBidirectionalTest [repro] 2/5 failed: org.apache.solr.cloud.RestartWhileUpdatingTest [repro] 2/5 failed: org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest [repro] git checkout 0d89ff2e6135a079e246e32af9f0deecb60c85d9 Previous HEAD position was 31220ba... SOLR-12660: Fix TestLang HEAD is now at 0d89ff2... SOLR-12664: Fix Download Solr button in index.adoc so it looks like it did before button style changes [repro] Exiting with code 256 Archiving artifacts Recording test results Build step 'Publish JUnit test result report' changed build result to UNSTABLE Email was triggered for: Unstable (Test Failures) Sending email for trigger: Unstable (Test Failures)
--------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
