Build: https://builds.apache.org/job/Lucene-Solr-repro/2603/
[...truncated 28 lines...] [repro] Jenkins log URL: https://builds.apache.org/job/Lucene-Solr-BadApples-NightlyTests-7.x/42/consoleText [repro] Revision: 2ccb505912f5ee1818112e27518154b606b7512e [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=ForceLeaderTest -Dtests.method=testReplicasInLIRNoLeader -Dtests.seed=A3F5576C084DAA87 -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=th-TH-u-nu-thai-x-lvariant-TH -Dtests.timezone=Asia/Aqtau -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [repro] Repro line: ant test -Dtestcase=TestSimTriggerIntegration -Dtests.method=testNodeMarkersRegistration -Dtests.seed=A3F5576C084DAA87 -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=ru-RU -Dtests.timezone=Africa/Asmara -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: 302184dd7ff09f091c0290484743929044789e14 [repro] git fetch [repro] git checkout 2ccb505912f5ee1818112e27518154b606b7512e [...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] TestSimTriggerIntegration [repro] ForceLeaderTest [repro] ant compile-test [...truncated 3605 lines...] [repro] ant test-nocompile -Dtests.dups=5 -Dtests.maxfailures=10 -Dtests.class="*.TestSimTriggerIntegration|*.ForceLeaderTest" -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=A3F5576C084DAA87 -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=ru-RU -Dtests.timezone=Africa/Asmara -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [...truncated 8227 lines...] [junit4] 2> 144559 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.AbstractFullDistribZkTestBase ERROR: org.apache.solr.common.SolrException: Could not find a healthy node to handle the request. ... Sleeping for 1 seconds before re-try ... [junit4] 2> 145560 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.i.CloudSolrClient Request to collection [forceleader_lower_terms_collection] failed due to (510) org.apache.solr.common.SolrException: Could not find a healthy node to handle the request., retry=0 commError=false errorCode=510 [junit4] 2> 145560 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 145560 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.AbstractFullDistribZkTestBase ERROR: org.apache.solr.common.SolrException: Could not find a healthy node to handle the request. ... Sleeping for 1 seconds before re-try ... [junit4] 2> 146579 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.i.CloudSolrClient Request to collection [forceleader_lower_terms_collection] failed due to (510) org.apache.solr.common.SolrException: Could not find a healthy node to handle the request., retry=0 commError=false errorCode=510 [junit4] 2> 146579 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 146579 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.AbstractFullDistribZkTestBase ERROR: org.apache.solr.common.SolrException: Could not find a healthy node to handle the request. ... Sleeping for 1 seconds before re-try ... [junit4] 2> 147580 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.i.CloudSolrClient Request to collection [forceleader_lower_terms_collection] failed due to (510) org.apache.solr.common.SolrException: Could not find a healthy node to handle the request., retry=0 commError=false errorCode=510 [junit4] 2> 147580 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 147580 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.AbstractFullDistribZkTestBase ERROR: org.apache.solr.common.SolrException: Could not find a healthy node to handle the request. ... Sleeping for 1 seconds before re-try ... [junit4] 2> 148580 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.i.CloudSolrClient Request to collection [forceleader_lower_terms_collection] failed due to (510) org.apache.solr.common.SolrException: Could not find a healthy node to handle the request., retry=0 commError=false errorCode=510 [junit4] 2> 148580 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 148580 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.AbstractFullDistribZkTestBase ERROR: org.apache.solr.common.SolrException: Could not find a healthy node to handle the request. ... Sleeping for 1 seconds before re-try ... [junit4] 2> 149589 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.i.CloudSolrClient Request to collection [forceleader_lower_terms_collection] failed due to (510) org.apache.solr.common.SolrException: Could not find a healthy node to handle the request., retry=0 commError=false errorCode=510 [junit4] 2> 149589 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 149589 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.AbstractFullDistribZkTestBase No more retries available! Add batch failed due to: org.apache.solr.common.SolrException: Could not find a healthy node to handle the request. [junit4] 2> 149589 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.ForceLeaderTest Document couldn't be sent, which is expected. [junit4] 2> 149589 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.ForceLeaderTest Do force leader... [junit4] 2> 149670 INFO (zkConnectionManagerCallback-122-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 149711 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3) [junit4] 2> 149712 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:35500/solr ready [junit4] 2> 149713 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=47964,localport=46600], receiveBufferSize:531000 [junit4] 2> 149714 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=33052,localport=46646], receiveBufferSize=530904 [junit4] 2> 149740 INFO (qtp382465680-354) [n:127.0.0.1:46600_ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :forceleader with params action=FORCELEADER&collection=forceleader_lower_terms_collection&shard=shard1&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 149740 INFO (qtp382465680-354) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection ] o.a.s.h.a.CollectionsHandler Force leader invoked, state: znodeVersion: 20 [junit4] 2> live nodes:[127.0.0.1:46600_, 127.0.0.1:37273_, 127.0.0.1:36074_] [junit4] 2> collections:{forceleader_lower_terms_collection=DocCollection(forceleader_lower_terms_collection//clusterstate.json/20)={ [junit4] 2> "pullReplicas":"0", [junit4] 2> "replicationFactor":"3", [junit4] 2> "shards":{"shard1":{ [junit4] 2> "range":"80000000-7fffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{ [junit4] 2> "core_node4":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n1", [junit4] 2> "base_url":"http://127.0.0.1:46600";, [junit4] 2> "node_name":"127.0.0.1:46600_", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}, [junit4] 2> "core_node5":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n2", [junit4] 2> "base_url":"http://127.0.0.1:46600";, [junit4] 2> "node_name":"127.0.0.1:46600_", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}, [junit4] 2> "core_node6":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n3", [junit4] 2> "base_url":"http://127.0.0.1:43067";, [junit4] 2> "node_name":"127.0.0.1:43067_", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}}}}, [junit4] 2> "router":{"name":"compositeId"}, [junit4] 2> "maxShardsPerNode":"1", [junit4] 2> "autoAddReplicas":"false", [junit4] 2> "nrtReplicas":"3", [junit4] 2> "tlogReplicas":"0"}, collection1=DocCollection(collection1//clusterstate.json/20)={ [junit4] 2> "pullReplicas":"0", [junit4] 2> "replicationFactor":"1", [junit4] 2> "shards":{ [junit4] 2> "shard1":{ [junit4] 2> "range":"80000000-ffffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{"core_node3":{ [junit4] 2> "core":"collection1_shard1_replica_n2", [junit4] 2> "base_url":"http://127.0.0.1:43067";, [junit4] 2> "node_name":"127.0.0.1:43067_", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT", [junit4] 2> "leader":"true"}}}, [junit4] 2> "shard2":{ [junit4] 2> "range":"0-7fffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{ [junit4] 2> "core_node4":{ [junit4] 2> "core":"collection1_shard2_replica_n1", [junit4] 2> "base_url":"http://127.0.0.1:36074";, [junit4] 2> "node_name":"127.0.0.1:36074_", [junit4] 2> "state":"active", [junit4] 2> "type":"NRT", [junit4] 2> "leader":"true"}, [junit4] 2> "core_node6":{ [junit4] 2> "core":"collection1_shard2_replica_n5", [junit4] 2> "base_url":"http://127.0.0.1:46600";, [junit4] 2> "node_name":"127.0.0.1:46600_", [junit4] 2> "state":"active", [junit4] 2> "type":"NRT"}}}}, [junit4] 2> "router":{"name":"compositeId"}, [junit4] 2> "maxShardsPerNode":"1", [junit4] 2> "autoAddReplicas":"false", [junit4] 2> "nrtReplicas":"1", [junit4] 2> "tlogReplicas":"0"}, control_collection=LazyCollectionRef(control_collection)} [junit4] 2> 149751 INFO (qtp382465680-354) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection ] o.a.s.c.ZkShardTerms Successful update of terms at /collections/forceleader_lower_terms_collection/terms/shard1 to Terms{values={core_node6=2, core_node4=2, core_node5=1}, version=5} [junit4] 2> 149751 INFO (qtp382465680-354) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection ] o.a.s.c.ZkShardTerms Successful update of terms at /collections/forceleader_lower_terms_collection/terms/shard1 to Terms{values={core_node6=2, core_node4=2, core_node5=2}, version=6} [junit4] 2> 154265 INFO (ScheduledTrigger-82-thread-1) [ ] o.a.s.c.a.SystemLogListener Collection .system does not exist, disabling logging. [junit4] 2> 154281 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=47994,localport=46600], receiveBufferSize:531000 [junit4] 2> 154282 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=33052,localport=46676], receiveBufferSize=530904 [junit4] 2> 154285 INFO (qtp382465680-352) [n:127.0.0.1:46600_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard2.replica_n5:INDEX.sizeInBytes&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:INDEX.sizeInBytes&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n1:INDEX.sizeInBytes} status=0 QTime=3 [junit4] 2> 154297 INFO (qtp382465680-355) [n:127.0.0.1:46600_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard2.replica_n5:INDEX.sizeInBytes&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:INDEX.sizeInBytes&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n1:INDEX.sizeInBytes} status=0 QTime=9 [junit4] 2> 154301 INFO (qtp382465680-535) [n:127.0.0.1:46600_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard2.replica_n5:INDEX.sizeInBytes&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:INDEX.sizeInBytes&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n1:INDEX.sizeInBytes} status=0 QTime=0 [junit4] 2> 154322 INFO (qtp382465680-536) [n:127.0.0.1:46600_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=1 [junit4] 2> 154324 INFO (qtp382465680-353) [n:127.0.0.1:46600_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=0 [junit4] 2> 154326 INFO (qtp382465680-534) [n:127.0.0.1:46600_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=1 [junit4] 2> 154328 INFO (qtp382465680-537) [n:127.0.0.1:46600_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=0 [junit4] 2> 154346 INFO (qtp382465680-351) [n:127.0.0.1:46600_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=0 [junit4] 2> 154349 INFO (qtp231464846-283) [n:127.0.0.1:37273_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.control_collection.shard1.replica_n1:INDEX.sizeInBytes} status=0 QTime=0 [junit4] 2> 154350 INFO (qtp231464846-282) [n:127.0.0.1:37273_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.control_collection.shard1.replica_n1:INDEX.sizeInBytes} status=0 QTime=0 [junit4] 2> 154352 INFO (qtp231464846-284) [n:127.0.0.1:37273_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.control_collection.shard1.replica_n1:INDEX.sizeInBytes} status=0 QTime=0 [junit4] 2> 154366 INFO (qtp231464846-285) [n:127.0.0.1:37273_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=0 [junit4] 2> 154368 INFO (qtp231464846-281) [n:127.0.0.1:37273_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=0 [junit4] 2> 154377 INFO (qtp231464846-283) [n:127.0.0.1:37273_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=8 [junit4] 2> 154386 INFO (qtp231464846-282) [n:127.0.0.1:37273_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=0 [junit4] 2> 154388 INFO (qtp231464846-284) [n:127.0.0.1:37273_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=0 [junit4] 2> 154390 INFO (qtp1871829840-399) [n:127.0.0.1:36074_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard2.replica_n1:INDEX.sizeInBytes} status=0 QTime=0 [junit4] 2> 154392 INFO (qtp1871829840-401) [n:127.0.0.1:36074_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard2.replica_n1:INDEX.sizeInBytes} status=0 QTime=0 [junit4] 2> 154414 INFO (qtp1871829840-400) [n:127.0.0.1:36074_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard2.replica_n1:INDEX.sizeInBytes} status=0 QTime=21 [junit4] 2> 154416 INFO (qtp1871829840-398) [n:127.0.0.1:36074_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=0 [junit4] 2> 154418 INFO (qtp1871829840-402) [n:127.0.0.1:36074_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=0 [junit4] 2> 154420 INFO (qtp1871829840-399) [n:127.0.0.1:36074_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=0 [junit4] 2> 154421 INFO (qtp1871829840-401) [n:127.0.0.1:36074_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=0 [junit4] 2> 154443 INFO (qtp1871829840-400) [n:127.0.0.1:36074_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CORE.coreName&wt=javabin&version=2&group=solr.node,solr.core} status=0 QTime=0 [junit4] 2> 154459 INFO (AutoscalingActionExecutor-83-thread-1) [ ] o.a.s.c.a.ExecutePlanAction No operations to execute for event: { [junit4] 2> "id":"663af888aa6adcT4z0qdmb3qh1di0hhaygzea0i5", [junit4] 2> "source":".auto_add_replicas", [junit4] 2> "eventTime":28775286743657180, [junit4] 2> "eventType":"NODELOST", [junit4] 2> "properties":{ [junit4] 2> "eventTimes":[28775286743657180], [junit4] 2> "preferredOperation":"movereplica", [junit4] 2> "_enqueue_time_":28775296769603606, [junit4] 2> "nodeNames":["127.0.0.1:43067_"]}} [junit4] 2> 154751 WARN (qtp382465680-354) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection ] o.a.s.h.a.CollectionsHandler Force leader attempt 1. Waiting 5 secs for an active leader. State of the slice: shard1:{ [junit4] 2> "range":"80000000-7fffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{ [junit4] 2> "core_node4":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n1", [junit4] 2> "base_url":"http://127.0.0.1:46600";, [junit4] 2> "node_name":"127.0.0.1:46600_", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}, [junit4] 2> "core_node5":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n2", [junit4] 2> "base_url":"http://127.0.0.1:46600";, [junit4] 2> "node_name":"127.0.0.1:46600_", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}, [junit4] 2> "core_node6":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n3", [junit4] 2> "base_url":"http://127.0.0.1:43067";, [junit4] 2> "node_name":"127.0.0.1:43067_", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}}} [junit4] 2> 158683 INFO (zkCallback-70-thread-2) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 158683 WARN (zkCallback-70-thread-2) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.RecoveryStrategy Stopping recovery for core=[forceleader_lower_terms_collection_shard1_replica_n2] coreNodeName=[core_node5] [junit4] 2> 158778 INFO (qtp382465680-352) [n:127.0.0.1:46600_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard2.replica_n5:QUERY./select.requests&key=solr.core.collection1.shard2.replica_n5:UPDATE./update.requests&key=solr.core.collection1.shard2.replica_n5:INDEX.sizeInBytes&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n1:UPDATE./update.requests&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:UPDATE./update.requests&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n1:QUERY./select.requests&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:INDEX.sizeInBytes&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:QUERY./select.requests&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n1:INDEX.sizeInBytes} status=0 QTime=0 [junit4] 2> 158806 INFO (qtp382465680-355) [n:127.0.0.1:46600_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard2.replica_n5:QUERY./select.requests&key=solr.core.collection1.shard2.replica_n5:UPDATE./update.requests&key=solr.core.collection1.shard2.replica_n5:INDEX.sizeInBytes&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n1:UPDATE./update.requests&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:UPDATE./update.requests&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n1:QUERY./select.requests&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:INDEX.sizeInBytes&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:QUERY./select.requests&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n1:INDEX.sizeInBytes} status=0 QTime=15 [junit4] 2> 158826 INFO (qtp382465680-355) [n:127.0.0.1:46600_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard2.replica_n5:QUERY./select.requests&key=solr.core.collection1.shard2.replica_n5:UPDATE./update.requests&key=solr.core.collection1.shard2.replica_n5:INDEX.sizeInBytes&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n1:UPDATE./update.requests&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:UPDATE./update.requests&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n1:QUERY./select.requests&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:INDEX.sizeInBytes&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:QUERY./select.requests&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n1:INDEX.sizeInBytes} status=0 QTime=18 [junit4] 2> 158835 INFO (qtp382465680-355) [n:127.0.0.1:46600_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.jvm:os.processCpuLoad&key=solr.node:CONTAINER.fs.coreRoot.usableSpace&key=solr.jvm:os.systemLoadAverage&key=solr.jvm:memory.heap.used} status=0 QTime=7 [junit4] 2> 158843 INFO (qtp382465680-535) [n:127.0.0.1:46600_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.jvm:os.processCpuLoad&key=solr.node:CONTAINER.fs.coreRoot.usableSpace&key=solr.jvm:os.systemLoadAverage&key=solr.jvm:memory.heap.used} status=0 QTime=0 [junit4] 2> 158879 INFO (qtp382465680-536) [n:127.0.0.1:46600_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.jvm:os.processCpuLoad&key=solr.node:CONTAINER.fs.coreRoot.usableSpace&key=solr.jvm:os.systemLoadAverage&key=solr.jvm:memory.heap.used} status=0 QTime=34 [junit4] 2> 158888 INFO (qtp231464846-285) [n:127.0.0.1:37273_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.control_collection.shard1.replica_n1:QUERY./select.requests&key=solr.core.control_collection.shard1.replica_n1:INDEX.sizeInBytes&key=solr.core.control_collection.shard1.replica_n1:UPDATE./update.requests} status=0 QTime=1 [junit4] 2> 158906 INFO (qtp231464846-281) [n:127.0.0.1:37273_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.control_collection.shard1.replica_n1:QUERY./select.requests&key=solr.core.control_collection.shard1.replica_n1:INDEX.sizeInBytes&key=solr.core.control_collection.shard1.replica_n1:UPDATE./update.requests} status=0 QTime=17 [junit4] 2> 158908 INFO (qtp231464846-283) [n:127.0.0.1:37273_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.control_collection.shard1.replica_n1:QUERY./select.requests&key=solr.core.control_collection.shard1.replica_n1:INDEX.sizeInBytes&key=solr.core.control_collection.shard1.replica_n1:UPDATE./update.requests} status=0 QTime=0 [junit4] 2> 158910 INFO (qtp231464846-282) [n:127.0.0.1:37273_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.jvm:os.processCpuLoad&key=solr.node:CONTAINER.fs.coreRoot.usableSpace&key=solr.jvm:os.systemLoadAverage&key=solr.jvm:memory.heap.used} status=0 QTime=0 [junit4] 2> 158924 INFO (qtp231464846-282) [n:127.0.0.1:37273_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.jvm:os.processCpuLoad&key=solr.node:CONTAINER.fs.coreRoot.usableSpace&key=solr.jvm:os.systemLoadAverage&key=solr.jvm:memory.heap.used} status=0 QTime=0 [junit4] 2> 158944 INFO (qtp231464846-282) [n:127.0.0.1:37273_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.jvm:os.processCpuLoad&key=solr.node:CONTAINER.fs.coreRoot.usableSpace&key=solr.jvm:os.systemLoadAverage&key=solr.jvm:memory.heap.used} status=0 QTime=0 [junit4] 2> 158988 INFO (qtp1871829840-398) [n:127.0.0.1:36074_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard2.replica_n1:UPDATE./update.requests&key=solr.core.collection1.shard2.replica_n1:INDEX.sizeInBytes&key=solr.core.collection1.shard2.replica_n1:QUERY./select.requests} status=0 QTime=0 [junit4] 2> 159004 INFO (qtp1871829840-402) [n:127.0.0.1:36074_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard2.replica_n1:UPDATE./update.requests&key=solr.core.collection1.shard2.replica_n1:INDEX.sizeInBytes&key=solr.core.collection1.shard2.replica_n1:QUERY./select.requests} status=0 QTime=0 [junit4] 2> 159017 INFO (qtp1871829840-399) [n:127.0.0.1:36074_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard2.replica_n1:UPDATE./update.requests&key=solr.core.collection1.shard2.replica_n1:INDEX.sizeInBytes&key=solr.core.collection1.shard2.replica_n1:QUERY./select.requests} status=0 QTime=0 [junit4] 2> 159069 INFO (qtp1871829840-401) [n:127.0.0.1:36074_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.jvm:os.processCpuLoad&key=solr.node:CONTAINER.fs.coreRoot.usableSpace&key=solr.jvm:os.systemLoadAverage&key=solr.jvm:memory.heap.used} status=0 QTime=13 [junit4] 2> 159090 INFO (qtp1871829840-400) [n:127.0.0.1:36074_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.jvm:os.processCpuLoad&key=solr.node:CONTAINER.fs.coreRoot.usableSpace&key=solr.jvm:os.systemLoadAverage&key=solr.jvm:memory.heap.used} status=0 QTime=0 [junit4] 2> 159092 INFO (qtp1871829840-398) [n:127.0.0.1:36074_ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.jvm:os.processCpuLoad&key=solr.node:CONTAINER.fs.coreRoot.usableSpace&key=solr.jvm:os.systemLoadAverage&key=solr.jvm:memory.heap.used} status=0 QTime=0 [junit4] 2> 159752 WARN (qtp382465680-354) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection ] o.a.s.h.a.CollectionsHandler Force leader attempt 2. Waiting 5 secs for an active leader. State of the slice: shard1:{ [junit4] 2> "range":"80000000-7fffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{ [junit4] 2> "core_node4":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n1", [junit4] 2> "base_url":"http://127.0.0.1:46600";, [junit4] 2> "node_name":"127.0.0.1:46600_", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}, [junit4] 2> "core_node5":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n2", [junit4] 2> "base_url":"http://127.0.0.1:46600";, [junit4] 2> "node_name":"127.0.0.1:46600_", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}, [junit4] 2> "core_node6":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n3", [junit4] 2> "base_url":"http://127.0.0.1:43067";, [junit4] 2> "node_name":"127.0.0.1:43067_", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}}} [junit4] 2> 161200 INFO (zkCallback-70-thread-2) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n2/ [junit4] 2> 161200 INFO (zkCallback-70-thread-2) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.u.PeerSync PeerSync: core=forceleader_lower_terms_collection_shard1_replica_n2 url=http://127.0.0.1:46600 START replicas=[http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n1/] nUpdates=100 [junit4] 2> 161264 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=48046,localport=46600], receiveBufferSize:531000 [junit4] 2> 161326 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=33052,localport=46728], receiveBufferSize=530904 [junit4] 2> 161334 INFO (qtp382465680-534) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n1] webapp= path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 161354 INFO (zkCallback-70-thread-2) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.u.PeerSync PeerSync: core=forceleader_lower_terms_collection_shard1_replica_n2 url=http://127.0.0.1:46600 Received 1 versions from http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n1/ fingerprint:null [junit4] 2> 161379 INFO (qtp382465680-537) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n1] webapp= path=/get params={distrib=false&qt=/get&checkCanHandleVersionRanges=false&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 161398 INFO (zkCallback-70-thread-2) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.u.PeerSync PeerSync: core=forceleader_lower_terms_collection_shard1_replica_n2 url=http://127.0.0.1:46600 No additional versions requested. ourHighThreshold=1621557647598682112 otherLowThreshold=1621557647598682112 ourHighest=1621557647598682112 otherHighest=1621557647598682112 [junit4] 2> 161435 INFO (zkCallback-70-thread-2) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.u.PeerSync PeerSync: core=forceleader_lower_terms_collection_shard1_replica_n2 url=http://127.0.0.1:46600 DONE. sync succeeded [junit4] 2> 161435 INFO (zkCallback-70-thread-2) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 161435 INFO (zkCallback-70-thread-2) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.SyncStrategy http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n2/: try and ask http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n1/ to sync [junit4] 2> 161437 INFO (qtp382465680-351) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.u.PeerSync PeerSync: core=forceleader_lower_terms_collection_shard1_replica_n1 url=http://127.0.0.1:46600 START replicas=[http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n2/] nUpdates=100 [junit4] 2> 161438 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=48050,localport=46600], receiveBufferSize:531000 [junit4] 2> 161459 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=33052,localport=46732], receiveBufferSize=530904 [junit4] 2> 161621 INFO (recoveryExecutor-67-thread-2-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n2 c:forceleader_lower_terms_collection s:shard1 r:core_node5) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.RecoveryStrategy RecoveryStrategy has been closed [junit4] 2> 161621 INFO (recoveryExecutor-67-thread-2-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n2 c:forceleader_lower_terms_collection s:shard1 r:core_node5) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.RecoveryStrategy Finished recovery process, successful=[false] [junit4] 2> 162951 INFO (qtp382465680-355) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.s.SolrIndexSearcher Opening [Searcher@70c86676[forceleader_lower_terms_collection_shard1_replica_n2] realtime] [junit4] 2> 163193 INFO (qtp382465680-355) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.u.IndexFingerprint IndexFingerprint millis:1726.0 result:{maxVersionSpecified=9223372036854775807, maxVersionEncountered=1621557647598682112, maxInHash=1621557647598682112, versionsHash=-8564769800428475808, numVersions=1, numDocs=1, maxDoc=1} [junit4] 2> 163194 INFO (qtp382465680-355) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/get params={distrib=false&qt=/get&getFingerprint=9223372036854775807&wt=javabin&version=2} status=0 QTime=1729 [junit4] 2> 163324 INFO (qtp382465680-351) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@34342c36[forceleader_lower_terms_collection_shard1_replica_n1] realtime] [junit4] 2> 163324 INFO (qtp382465680-351) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.u.IndexFingerprint IndexFingerprint millis:110.0 result:{maxVersionSpecified=9223372036854775807, maxVersionEncountered=1621557647598682112, maxInHash=1621557647598682112, versionsHash=-8564769800428475808, numVersions=1, numDocs=1, maxDoc=1} [junit4] 2> 163325 INFO (qtp382465680-351) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.u.PeerSync We are already in sync. No need to do a PeerSync [junit4] 2> 163325 INFO (qtp382465680-351) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n1] webapp= path=/get params={distrib=false&qt=/get&getVersions=100&sync=http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n2/&wt=javabin&version=2} status=0 QTime=1888 [junit4] 2> 163325 INFO (zkCallback-70-thread-2) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.SyncStrategy http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n2/: sync completed with http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n1/ [junit4] 2> 163360 ERROR (zkCallback-70-thread-2) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.ShardLeaderElectionContext WARNING: Potential data loss -- Replica core_node5 became leader after timeout (leaderVoteWait) without being up-to-date with the previous leader [junit4] 2> 163360 INFO (zkCallback-70-thread-2) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.ShardLeaderElectionContextBase Creating leader registration node /collections/forceleader_lower_terms_collection/leaders/shard1/leader after winning as /collections/forceleader_lower_terms_collection/leader_elect/shard1/election/73943407926575114-core_node5-n_0000000001 [junit4] 2> 163377 INFO (zkCallback-70-thread-2) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n2/ shard1 [junit4] 2> 163409 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=48070,localport=46600], receiveBufferSize:531000 [junit4] 2> 163410 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=33052,localport=46752], receiveBufferSize=530904 [junit4] 2> 163434 INFO (qtp382465680-536) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/admin/ping params={wt=javabin&version=2} hits=0 status=0 QTime=1 [junit4] 2> 163434 INFO (qtp382465680-536) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/admin/ping params={wt=javabin&version=2} status=0 QTime=1 [junit4] 2> 163435 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[forceleader_lower_terms_collection_shard1_replica_n1] [junit4] 2> 163435 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=tlog{file=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J2/temp/solr.cloud.ForceLeaderTest_A3F5576C084DAA87-001/shard-1-001/cores/forceleader_lower_terms_collection_shard1_replica_n1/data/tlog/tlog.0000000000000000000 refcount=1}} [junit4] 2> 163435 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.RecoveryStrategy Publishing state of core [forceleader_lower_terms_collection_shard1_replica_n1] as recovering, leader is [http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n2/] and I am [http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n1/] [junit4] 2> 163439 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.ZkShardTerms Successful update of terms at /collections/forceleader_lower_terms_collection/terms/shard1 to Terms{values={core_node6=2, core_node4_recovering=2, core_node4=2, core_node5=2}, version=7} [junit4] 2> 163440 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://127.0.0.1:46600]; [WaitForState: action=PREPRECOVERY&core=forceleader_lower_terms_collection_shard1_replica_n2&nodeName=127.0.0.1:46600_&coreNodeName=core_node4&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true] [junit4] 2> 163449 INFO (qtp382465680-353) [n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true [junit4] 2> 163449 INFO (qtp382465680-353) [n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=forceleader_lower_terms_collection, shard=shard1, thisCore=forceleader_lower_terms_collection_shard1_replica_n2, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=down, localState=active, nodeName=127.0.0.1:46600_, coreNodeName=core_node4, onlyIfActiveCheckResult=false, nodeProps: core_node4:{"core":"forceleader_lower_terms_collection_shard1_replica_n1","base_url":"http://127.0.0.1:46600","node_name":"127.0.0.1:46600_","state":"down","type":"NRT"} [junit4] 2> 163607 INFO (watches-72-thread-2) [ ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=forceleader_lower_terms_collection, shard=shard1, thisCore=forceleader_lower_terms_collection_shard1_replica_n2, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=recovering, localState=active, nodeName=127.0.0.1:46600_, coreNodeName=core_node4, onlyIfActiveCheckResult=false, nodeProps: core_node4:{"core":"forceleader_lower_terms_collection_shard1_replica_n1","base_url":"http://127.0.0.1:46600","node_name":"127.0.0.1:46600_","state":"recovering","type":"NRT"} [junit4] 2> 163607 INFO (qtp382465680-353) [n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={nodeName=127.0.0.1:46600_&onlyIfLeaderActive=true&core=forceleader_lower_terms_collection_shard1_replica_n2&coreNodeName=core_node4&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=0 QTime=158 [junit4] 2> 164173 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.RecoveryStrategy Attempting to PeerSync from [http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n2/] - recoveringAfterStartup=[true] [junit4] 2> 164174 WARN (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.u.PeerSyncWithLeader no frame of reference to tell if we've missed updates [junit4] 2> 164174 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.RecoveryStrategy PeerSync Recovery was not successful - trying replication. [junit4] 2> 164174 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.RecoveryStrategy Starting Replication Recovery. [junit4] 2> 164174 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.RecoveryStrategy Attempting to replicate from [http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n2/]. [junit4] 2> 164176 INFO (qtp382465680-534) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1621557673453420544,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 164177 INFO (qtp382465680-534) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@2d819a0a commitCommandVersion:1621557673453420544 [junit4] 2> 164211 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=48078,localport=46600], receiveBufferSize:531000 [junit4] 2> 164246 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=33052,localport=46760], receiveBufferSize=530904 [junit4] 2> 164284 INFO (qtp382465680-352) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.u.p.DistributedUpdateProcessor Ignoring commit while not ACTIVE - state: BUFFERING replay: false [junit4] 2> 164299 INFO (qtp382465680-352) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [forceleader_lower_terms_collection_shard1_replica_n1] webapp= path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=false&commit=true&softCommit=false&distrib.from=http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n2/&commit_end_point=replicas&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 15 [junit4] 2> 164358 INFO (qtp382465680-534) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.s.SolrIndexSearcher Opening [Searcher@60377184[forceleader_lower_terms_collection_shard1_replica_n2] realtime] [junit4] 2> 164372 INFO (qtp382465680-534) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 164373 INFO (qtp382465680-534) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 197 [junit4] 2> 164397 INFO (qtp382465680-355) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0 [junit4] 2> 164409 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.h.IndexFetcher Master's generation: 2 [junit4] 2> 164409 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.h.IndexFetcher Master's version: 1546437905745 [junit4] 2> 164409 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.h.IndexFetcher Slave's generation: 1 [junit4] 2> 164409 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.h.IndexFetcher Slave's version: 0 [junit4] 2> 164409 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.h.IndexFetcher Starting replication process [junit4] 2> 164431 INFO (qtp382465680-351) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/replication params={generation=2&qt=/replication&tlogFiles=false&wt=javabin&version=2&command=filelist} status=0 QTime=13 [junit4] 2> 164432 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.h.IndexFetcher Number of files in latest index in master: 4 [junit4] 2> 164484 WARN (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.h.IndexFetcher File _0.cfe did not match. expected checksum is 4099452556 and actual is checksum 1624102856. expected length is 734 and actual length is 734 [junit4] 2> 164485 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.h.IndexFetcher Starting download (fullCopy=true) to RawDirectoryWrapper(RAMDirectory@1acade12 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@71605d01) [junit4] 2> 164485 WARN (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.h.IndexFetcher File _0.cfe did not match. expected checksum is 4099452556 and actual is checksum 1624102856. expected length is 734 and actual length is 734 [junit4] 2> 164580 INFO (qtp382465680-535) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/replication params={generation=2&qt=/replication&file=_0.cfe&checksum=true&wt=filestream&command=filecontent} status=0 QTime=37 [junit4] 2> 164721 WARN (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.h.IndexFetcher File _0.si did not match. expected checksum is 915972134 and actual is checksum 3239537431. expected length is 384 and actual length is 384 [junit4] 2> 164723 INFO (qtp382465680-536) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/replication params={generation=2&qt=/replication&file=_0.si&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 164757 INFO (qtp382465680-354) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection ] o.a.s.h.a.CollectionsHandler Successfully issued FORCELEADER command for collection: forceleader_lower_terms_collection, shard: shard1 [junit4] 2> 164757 INFO (qtp382465680-354) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=FORCELEADER&collection=forceleader_lower_terms_collection&shard=shard1&wt=javabin&version=2} status=0 QTime=15017 [junit4] 2> 164760 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.AbstractDistribZkTestBase Wait for recoveries to finish - collection: forceleader_lower_terms_collection failOnTimeout:true timeout (sec):330 [junit4] 2> 164810 WARN (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.h.IndexFetcher File _0.cfs did not match. expected checksum is 134947986 and actual is checksum 189787435. expected length is 4130 and actual length is 4130 [junit4] 2> 164831 INFO (qtp382465680-352) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/replication params={generation=2&qt=/replication&file=_0.cfs&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 1> replica:core_node4 rstate:recovering live:true [junit4] 2> 164884 INFO (qtp382465680-534) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/replication params={generation=2&qt=/replication&file=segments_2&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 164886 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.h.IndexFetcher Bytes downloaded: 5452, Bytes skipped downloading: 0 [junit4] 2> 164886 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.h.IndexFetcher Total time taken for download (fullCopy=true,bytesDownloaded=5452) : 0 secs (null bytes/sec) to RawDirectoryWrapper(RAMDirectory@1acade12 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@71605d01) [junit4] 1> replica:core_node4 rstate:recovering live:true [junit4] 2> 164887 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.SolrCore Updating index properties... index=index.20190102170506050 [junit4] 2> 164888 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.h.IndexFetcher removing old index directory MockDirectoryWrapper(NRTCachingDirectory(RAMDirectory@140cd7fb lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@2fe199c8; maxCacheMB=0.095703125 maxMergeSizeMB=0.322265625)) [junit4] 2> 164889 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=50, maxMergeAtOnceExplicit=10, maxMergedSegmentMB=62.1328125, floorSegmentMB=0.845703125, forceMergeDeletesPctAllowed=2.8854376273646984, segmentsPerTier=47.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.5632882375330474, deletesPctAllowed=42.31848737042188 [junit4] 2> 164939 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used. [junit4] 2> 164941 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@77e63a6e[forceleader_lower_terms_collection_shard1_replica_n1] main] [junit4] 2> 164997 INFO (searcherExecutor-136-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.SolrCore [forceleader_lower_terms_collection_shard1_replica_n1] Registered new searcher Searcher@77e63a6e[forceleader_lower_terms_collection_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.7.0):c1:[diagnostics={java.runtime.version=1.8.0_191-b12, java.vendor=Oracle Corporation, java.version=1.8.0_191, java.vm.version=25.191-b12, lucene.version=7.7.0, os=Linux, os.arch=amd64, os.version=4.4.0-112-generic, source=flush, timestamp=1546437903104}]:[attributes={Lucene50StoredFieldsFormat.mode=BEST_SPEED}])))} [junit4] 2> 164998 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.RecoveryStrategy No replay needed. [junit4] 2> 164998 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.RecoveryStrategy Replication Recovery was successful. [junit4] 2> 164998 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.RecoveryStrategy Registering as Active after recovery. [junit4] 2> 165013 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.ZkShardTerms Successful update of terms at /collections/forceleader_lower_terms_collection/terms/shard1 to Terms{values={core_node6=2, core_node4=2, core_node5=2}, version=8} [junit4] 2> 165014 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.RecoveryStrategy Updating version bucket highest from index after successful recovery. [junit4] 2> 165049 INFO (recoveryExecutor-67-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.RecoveryStrategy Finished recovery process, successful=[true] [junit4] 1> replica:core_node4 rstate:active live:true [junit4] 1> replica:core_node5 rstate:active live:true [junit4] 1> replica:core_node6 rstate:down live:false [junit4] 1> no one is recoverying [junit4] 2> 165139 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.AbstractDistribZkTestBase Recoveries finished - collection: forceleader_lower_terms_collection [junit4] 2> 165176 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.ForceLeaderTest After forcing leader: shard1:{ [junit4] 2> "range":"80000000-7fffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{ [junit4] 2> "core_node4":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n1", [junit4] 2> "base_url":"http://127.0.0.1:46600";, [junit4] 2> "node_name":"127.0.0.1:46600_", [junit4] 2> "state":"active", [junit4] 2> "type":"NRT"}, [junit4] 2> "core_node5":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n2", [junit4] 2> "base_url":"http://127.0.0.1:46600";, [junit4] 2> "node_name":"127.0.0.1:46600_", [junit4] 2> "state":"active", [junit4] 2> "type":"NRT", [junit4] 2> "leader":"true"}, [junit4] 2> "core_node6":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n3", [junit4] 2> "base_url":"http://127.0.0.1:43067";, [junit4] 2> "node_name":"127.0.0.1:43067_", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}}} [junit4] 2> 165176 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.ForceLeaderTest Sending doc 4... [junit4] 2> 165177 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=48086,localport=46600], receiveBufferSize:531000 [junit4] 2> 165248 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=33052,localport=46768], receiveBufferSize=530904 [junit4] 2> 165322 INFO (qtp382465680-351) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.ZkShardTerms Successful update of terms at /collections/forceleader_lower_terms_collection/terms/shard1 to Terms{values={core_node6=2, core_node4=3, core_node5=3}, version=9} [junit4] 2> 165339 INFO (qtp382465680-535) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [forceleader_lower_terms_collection_shard1_replica_n1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n2/&wt=javabin&version=2}{add=[4 (1621557674560716800)]} 0 39 [junit4] 2> 165357 INFO (qtp382465680-351) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/update params={wt=javabin&version=2}{add=[4 (1621557674560716800)]} 0 125 [junit4] 2> 165358 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.ForceLeaderTest Committing... [junit4] 2> 165360 INFO (qtp382465680-536) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1621557674694934528,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 165373 INFO (qtp382465680-536) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@2d819a0a commitCommandVersion:1621557674694934528 [junit4] 2> 165382 INFO (qtp382465680-354) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1621557674718003200,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 165382 INFO (qtp382465680-354) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@66ebd36f commitCommandVersion:1621557674718003200 [junit4] 2> 165901 INFO (qtp382465680-536) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.s.SolrIndexSearcher Opening [Searcher@40433d46[forceleader_lower_terms_collection_shard1_replica_n2] main] [junit4] 2> 165902 INFO (qtp382465680-354) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@b2fbcfb[forceleader_lower_terms_collection_shard1_replica_n1] main] [junit4] 2> 165903 INFO (qtp382465680-354) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 165906 INFO (searcherExecutor-136-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n1 c:forceleader_lower_terms_collection s:shard1 r:core_node4) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.SolrCore [forceleader_lower_terms_collection_shard1_replica_n1] Registered new searcher Searcher@b2fbcfb[forceleader_lower_terms_collection_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.7.0):c1:[diagnostics={java.runtime.version=1.8.0_191-b12, java.vendor=Oracle Corporation, java.version=1.8.0_191, java.vm.version=25.191-b12, lucene.version=7.7.0, os=Linux, os.arch=amd64, os.version=4.4.0-112-generic, source=flush, timestamp=1546437903104}]:[attributes={Lucene50StoredFieldsFormat.mode=BEST_SPEED}]) Uninverting(_1(7.7.0):c1:[diagnostics={os=Linux, java.vendor=Oracle Corporation, java.version=1.8.0_191, java.vm.version=25.191-b12, lucene.version=7.7.0, os.arch=amd64, java.runtime.version=1.8.0_191-b12, source=flush, os.version=4.4.0-112-generic, timestamp=1546437907183}]:[attributes={Lucene50StoredFieldsFormat.mode=BEST_SPEED}])))} [junit4] 2> 165907 INFO (qtp382465680-354) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [forceleader_lower_terms_collection_shard1_replica_n1] webapp= path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:46600/forceleader_lower_terms_collection_shard1_replica_n2/&commit_end_point=replicas&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 525 [junit4] 2> 165993 INFO (qtp382465680-536) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 166012 INFO (searcherExecutor-138-thread-1-processing-n:127.0.0.1:46600_ x:forceleader_lower_terms_collection_shard1_replica_n2 c:forceleader_lower_terms_collection s:shard1 r:core_node5) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.SolrCore [forceleader_lower_terms_collection_shard1_replica_n2] Registered new searcher Searcher@40433d46[forceleader_lower_terms_collection_shard1_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.7.0):c1:[diagnostics={os=Linux, java.vendor=Oracle Corporation, java.version=1.8.0_191, java.vm.version=25.191-b12, lucene.version=7.7.0, os.arch=amd64, java.runtime.version=1.8.0_191-b12, source=flush, os.version=4.4.0-112-generic, timestamp=1546437903104}]:[attributes={Lucene50StoredFieldsFormat.mode=BEST_SPEED}]) Uninverting(_1(7.7.0):c1:[diagnostics={os=Linux, java.vendor=Oracle Corporation, java.version=1.8.0_191, java.vm.version=25.191-b12, lucene.version=7.7.0, os.arch=amd64, java.runtime.version=1.8.0_191-b12, source=flush, os.version=4.4.0-112-generic, timestamp=1546437907181}]:[attributes={Lucene50StoredFieldsFormat.mode=BEST_SPEED}])))} [junit4] 2> 166103 INFO (qtp382465680-536) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/update params={waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 743 [junit4] 2> 166104 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.ForceLeaderTest Doc 4 sent and commit issued [junit4] 2> 166177 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=48110,localport=46600], receiveBufferSize:531000 [junit4] 2> 166232 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=33052,localport=46792], receiveBufferSize=530904 [junit4] 2> 166391 INFO (qtp382465680-537) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n1] webapp= path=/get params={distrib=false&qt=/get&id=1&wt=javabin&version=2} status=0 QTime=178 [junit4] 2> 166608 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=48122,localport=46600], receiveBufferSize:531000 [junit4] 2> 166641 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=33052,localport=46804], receiveBufferSize=530904 [junit4] 2> 166730 INFO (qtp382465680-534) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/get params={distrib=false&qt=/get&id=1&wt=javabin&version=2} status=0 QTime=107 [junit4] 2> 166732 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=48126,localport=46600], receiveBufferSize:531000 [junit4] 2> 166758 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=33052,localport=46808], receiveBufferSize=530904 [junit4] 2> 166759 INFO (qtp382465680-535) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/get params={distrib=false&qt=/get&id=1&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 166852 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=48130,localport=46600], receiveBufferSize:531000 [junit4] 2> 166868 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=33052,localport=46812], receiveBufferSize=530904 [junit4] 2> 166886 INFO (qtp382465680-355) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n1] webapp= path=/get params={distrib=false&qt=/get&id=4&wt=javabin&version=2} status=0 QTime=1 [junit4] 2> 166905 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=48134,localport=46600], receiveBufferSize:531000 [junit4] 2> 166913 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=33052,localport=46816], receiveBufferSize=530904 [junit4] 2> 167001 INFO (qtp382465680-351) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n1] webapp= path=/get params={distrib=false&qt=/get&id=4&wt=javabin&version=2} status=0 QTime=80 [junit4] 2> 167004 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=48138,localport=46600], receiveBufferSize:531000 [junit4] 2> 167015 INFO (SocketProxy-Acceptor-46600) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=33052,localport=46820], receiveBufferSize=530904 [junit4] 2> 167016 INFO (qtp382465680-536) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node4 x:forceleader_lower_terms_collection_shard1_replica_n1] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n1] webapp= path=/get params={distrib=false&qt=/get&id=4&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 167021 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.ForceLeaderTest Checking doc counts... [junit4] 2> 167032 INFO (qtp382465680-355) [n:127.0.0.1:46600_ c:forceleader_lower_terms_collection s:shard1 r:core_node5 x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n2] webapp= path=/select params={q=*:*&wt=javabin&version=2} hits=2 status=0 QTime=9 [junit4] 2> 167054 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.ForceLeaderTest Bringing back originally killed leader... [junit4] 2> 167055 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.c.SocketProxy Re-opening connectivity to http://127.0.0.1:43067/ [junit4] 2> 167055 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.e.JettySolrRunner Start Jetty (original configured port=0) [junit4] 2> 167055 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.e.j.s.AbstractConnector Ignoring deprecated socket close linger time [junit4] 2> 167056 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.e.JettySolrRunner Trying to start Jetty on port 36366 try number 1 ... [junit4] 2> 167056 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.e.j.s.Server jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 1.8.0_191-b12 [junit4] 2> 167058 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0 [junit4] 2> 167058 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.e.j.s.session No SessionScavenger set, using defaults [junit4] 2> 167058 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.e.j.s.session node0 Scavenging every 660000ms [junit4] 2> 167059 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@4bdf1278{/,null,AVAILABLE} [junit4] 2> 167069 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@1f34aacd{HTTP/1.1,[http/1.1]}{127.0.0.1:36366} [junit4] 2> 167069 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.e.j.s.Server Started @167244ms [junit4] 2> 167069 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J2/temp/solr.cloud.ForceLeaderTest_A3F5576C084DAA87-001/tempDir-002/jetty2, replicaType=NRT, solrconfig=solrconfig.xml, hostContext=/, hostPort=43067, coreRootDirectory=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J2/temp/solr.cloud.ForceLeaderTest_A3F5576C084DAA87-001/shard-2-001/cores} [junit4] 2> 167069 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 167069 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory [junit4] 2> 167069 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.7.0 [junit4] 2> 167069 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 167069 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 167069 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2019-01-02T14:05:08.637Z [junit4] 2> 167114 INFO (zkConnectionManagerCallback-125-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 167117 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper) [junit4] 2> 167117 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J2/temp/solr.cloud.ForceLeaderTest_A3F5576C084DAA87-001/shard-2-001/solr.xml [junit4] 2> 167121 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored [junit4] 2> 167121 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored [junit4] 2> 167159 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@37897e1b, but no JMX reporters were configured - adding default JMX reporter. [junit4] 2> 167440 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:35500/solr [junit4] 2> 167463 INFO (zkConnectionManagerCallback-129-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 167495 INFO (zkConnectionManagerCallback-131-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 167500 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3) [junit4] 2> 167503 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.ZkController Publish node=127.0.0.1:43067_ as DOWN [junit4] 2> 167504 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores [junit4] 2> 167504 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43067_ [junit4] 2> 167507 INFO (zkCallback-77-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 167507 INFO (zkCallback-50-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 167507 INFO (zkCallback-95-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 167507 INFO (zkCallback-61-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 167507 INFO (zkCallback-88-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 167507 INFO (zkCallback-70-thread-3) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 167507 INFO (zkCallback-43-thread-4) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 167523 INFO (zkCallback-130-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 167542 INFO (zkConnectionManagerCallback-138-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 167551 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 167554 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:35500/solr ready [junit4] 2> 167554 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s. [...truncated too long message...] olr/clusterstate.json [junit4] 2> 3 /solr/clusterprops.json [junit4] 2> [junit4] 2> Maximum concurrent children watches above limit: [junit4] 2> [junit4] 2> 3 /solr/live_nodes [junit4] 2> 3 /solr/collections [junit4] 2> [junit4] 2> 109478 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.ZkTestServer parse host and port list: 127.0.0.1:35198 [junit4] 2> 109478 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[A3F5576C084DAA87]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1 35198 [junit4] 2> NOTE: download the large Jenkins line-docs file by running 'ant get-jenkins-line-docs' in the lucene directory. [junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ForceLeaderTest -Dtests.method=testReplicasInLowerTerms -Dtests.seed=A3F5576C084DAA87 -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=th-TH-u-nu-thai-x-lvariant-TH -Dtests.timezone=Asia/Aqtau -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [junit4] ERROR 32.7s J1 | ForceLeaderTest.testReplicasInLowerTerms <<< [junit4] > Throwable #1: org.apache.solr.client.solrj.SolrServerException: Timeout occured while waiting response from server at: http://127.0.0.1:34889 [junit4] > at __randomizedtesting.SeedInfo.seed([A3F5576C084DAA87:2DC1772FC8EA0AF3]:0) [junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:654) [junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:255) [junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:244) [junit4] > at org.apache.solr.client.solrj.impl.LBHttpSolrClient.doRequest(LBHttpSolrClient.java:484) [junit4] > at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:414) [junit4] > at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(CloudSolrClient.java:1110) [junit4] > at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:884) [junit4] > at org.apache.solr.client.solrj.impl.CloudSolrClient.request(CloudSolrClient.java:817) [junit4] > at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:194) [junit4] > at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:211) [junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createServers(AbstractFullDistribZkTestBase.java:338) [junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsFixedStatement.callStatement(BaseDistributedSearchTestCase.java:1061) [junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:1035) [junit4] > at java.lang.Thread.run(Thread.java:748) [junit4] > Caused by: java.net.SocketTimeoutException: Read timed out [junit4] > at java.net.SocketInputStream.socketRead0(Native Method) [junit4] > at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) [junit4] > at java.net.SocketInputStream.read(SocketInputStream.java:171) [junit4] > at java.net.SocketInputStream.read(SocketInputStream.java:141) [junit4] > at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137) [junit4] > at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153) [junit4] > at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:282) [junit4] > at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138) [junit4] > at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56) [junit4] > at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259) [junit4] > at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163) [junit4] > at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:165) [junit4] > at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273) [junit4] > at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125) [junit4] > at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272) [junit4] > at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185) [junit4] > at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89) [junit4] > at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110) [junit4] > at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185) [junit4] > at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83) [junit4] > at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56) [junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:542) [junit4] > ... 43 more [junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.ForceLeaderTest_A3F5576C084DAA87-001 [junit4] 2> Jan 02, 2019 2:13:52 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks [junit4] 2> WARNING: Will linger awaiting termination of 1 leaked thread(s). [junit4] 2> NOTE: test params are: codec=Asserting(Lucene70): {}, docValues:{}, maxPointsInLeafNode=1305, maxMBSortInHeap=6.593897944484806, sim=RandomSimilarity(queryNorm=true): {}, locale=th-TH-u-nu-thai-x-lvariant-TH, timezone=Asia/Aqtau [junit4] 2> NOTE: Linux 4.4.0-112-generic amd64/Oracle Corporation 1.8.0_191 (64-bit)/cpus=4,threads=1,free=215602776,total=332398592 [junit4] 2> NOTE: All tests run in this JVM: [ForceLeaderTest] [junit4] Completed [3/5 (3!)] on J1 in 103.62s, 3 tests, 2 errors, 1 skipped <<< FAILURES! [junit4] [junit4] HEARTBEAT J0 PID(7...@lucene2-us-west.apache.org): 2019-01-02T14:14:50, stalled for 71.4s at: ForceLeaderTest.testReplicasInLIRNoLeader [junit4] HEARTBEAT J2 PID(7...@lucene2-us-west.apache.org): 2019-01-02T14:14:50, stalled for 65.1s at: ForceLeaderTest.testReplicasInLIRNoLeader [junit4] HEARTBEAT J0 PID(7...@lucene2-us-west.apache.org): 2019-01-02T14:15:50, stalled for 131s at: ForceLeaderTest.testReplicasInLIRNoLeader [junit4] HEARTBEAT J2 PID(7...@lucene2-us-west.apache.org): 2019-01-02T14:15:50, stalled for 125s at: ForceLeaderTest.testReplicasInLIRNoLeader [junit4] HEARTBEAT J2 PID(7...@lucene2-us-west.apache.org): 2019-01-02T14:16:50, stalled for 185s at: ForceLeaderTest.testReplicasInLIRNoLeader [junit4] Suite: org.apache.solr.cloud.ForceLeaderTest [junit4] OK 185s J0 | ForceLeaderTest.testReplicasInLIRNoLeader [junit4] OK 40.7s J0 | ForceLeaderTest.testReplicasInLowerTerms [junit4] Completed [4/5 (3!)] on J0 in 227.77s, 3 tests, 1 skipped [junit4] [junit4] Suite: org.apache.solr.cloud.ForceLeaderTest [junit4] OK 186s J2 | ForceLeaderTest.testReplicasInLIRNoLeader [junit4] OK 41.1s J2 | ForceLeaderTest.testReplicasInLowerTerms [junit4] Completed [5/5 (3!)] on J2 in 228.32s, 3 tests, 1 skipped [junit4] [junit4] [junit4] Tests with failures [seed: A3F5576C084DAA87]: [junit4] - org.apache.solr.cloud.ForceLeaderTest.testReplicasInLIRNoLeader [junit4] - org.apache.solr.cloud.ForceLeaderTest.testReplicasInLIRNoLeader [junit4] - org.apache.solr.cloud.ForceLeaderTest.testReplicasInLIRNoLeader [junit4] - org.apache.solr.cloud.ForceLeaderTest.testReplicasInLowerTerms [junit4] - org.apache.solr.cloud.ForceLeaderTest.testReplicasInLowerTerms [junit4] - org.apache.solr.cloud.ForceLeaderTest.testReplicasInLowerTerms [junit4] [junit4] [junit4] JVM J0: 3.03 .. 325.92 = 322.89s [junit4] JVM J1: 2.75 .. 113.00 = 110.25s [junit4] JVM J2: 3.38 .. 332.44 = 329.06s [junit4] Execution time total: 5 minutes 32 seconds [junit4] Tests summary: 5 suites, 15 tests, 6 errors, 5 ignored BUILD FAILED /home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/lucene/common-build.xml:1572: The following error occurred while executing this line: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/lucene/common-build.xml:1099: There were test failures: 5 suites, 15 tests, 6 errors, 5 ignored [seed: A3F5576C084DAA87] Total time: 5 minutes 41 seconds [repro] Setting last failure code to 256 [repro] Failures at the tip of branch_7x: [repro] 3/5 failed: org.apache.solr.cloud.ForceLeaderTest [repro] git checkout 302184dd7ff09f091c0290484743929044789e14 Note: checking out '302184dd7ff09f091c0290484743929044789e14'. You are in 'detached HEAD' state. You can look around, make experimental changes and commit them, and you can discard any commits you make in this state without impacting any branches by performing another checkout. If you want to create a new branch to retain commits you create, you may do so (now or later) by using -b with the checkout command again. Example: git checkout -b <new-branch-name> HEAD is now at 302184d... SOLR-12514: Rule-base Authorization plugin skips authorization if querying node does not have collection replica [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: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org
