Build: https://builds.apache.org/job/Lucene-Solr-repro/2634/
[...truncated 28 lines...] [repro] Jenkins log URL: https://builds.apache.org/job/Lucene-Solr-NightlyTests-7.x/424/consoleText [repro] Revision: ecd4a3b49c0eb51b688997654f345efe0d92c85c [repro] Ant options: -Dtests.multiplier=2 -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-7.x/test-data/enwiki.random.lines.txt [repro] Repro line: ant test -Dtestcase=HdfsChaosMonkeySafeLeaderTest -Dtests.seed=D2A541849C903D90 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=mt-MT -Dtests.timezone=PST8PDT -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1 [repro] Repro line: ant test -Dtestcase=TestSimTriggerIntegration -Dtests.method=testNodeLostTriggerRestoreState -Dtests.seed=D2A541849C903D90 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=he-IL -Dtests.timezone=AET -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1 [repro] Repro line: ant test -Dtestcase=ForceLeaderTest -Dtests.method=testReplicasInLIRNoLeader -Dtests.seed=D2A541849C903D90 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=en-SG -Dtests.timezone=SST -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1 [repro] Repro line: ant test -Dtestcase=LIROnShardRestartTest -Dtests.method=testAllReplicasInLIR -Dtests.seed=D2A541849C903D90 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=uk -Dtests.timezone=Australia/Broken_Hill -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1 [repro] Repro line: ant test -Dtestcase=LIROnShardRestartTest -Dtests.method=testSeveralReplicasInLIR -Dtests.seed=D2A541849C903D90 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=uk -Dtests.timezone=Australia/Broken_Hill -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1 [repro] Repro line: ant test -Dtestcase=StressHdfsTest -Dtests.method=test -Dtests.seed=D2A541849C903D90 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=zh -Dtests.timezone=Asia/Bangkok -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1 [repro] git rev-parse --abbrev-ref HEAD [repro] git rev-parse HEAD [repro] Initial local git branch/revision: 2bd6f246b026b7d576097a4e4c3ebb293fc2b0d0 [repro] git fetch [repro] git checkout ecd4a3b49c0eb51b688997654f345efe0d92c85c [...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] HdfsChaosMonkeySafeLeaderTest [repro] TestSimTriggerIntegration [repro] StressHdfsTest [repro] ForceLeaderTest [repro] LIROnShardRestartTest [repro] ant compile-test [...truncated 3605 lines...] [repro] ant test-nocompile -Dtests.dups=5 -Dtests.maxfailures=25 -Dtests.class="*.HdfsChaosMonkeySafeLeaderTest|*.TestSimTriggerIntegration|*.StressHdfsTest|*.ForceLeaderTest|*.LIROnShardRestartTest" -Dtests.showOutput=onerror -Dtests.multiplier=2 -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.seed=D2A541849C903D90 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=mt-MT -Dtests.timezone=PST8PDT -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1 [...truncated 24176 lines...] [junit4] 2> 582314 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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> 583315 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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> 583315 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 583315 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 583315 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=1 commError=false errorCode=510 [junit4] 2> 583315 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 583315 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 583316 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=2 commError=false errorCode=510 [junit4] 2> 583316 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 583316 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 583318 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=3 commError=false errorCode=510 [junit4] 2> 583318 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 583318 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 583318 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=4 commError=false errorCode=510 [junit4] 2> 583318 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 583318 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 583319 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=5 commError=false errorCode=510 [junit4] 2> 583319 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 583319 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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> 584320 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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> 584320 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 584320 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 584320 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=1 commError=false errorCode=510 [junit4] 2> 584320 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 584320 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 584321 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=2 commError=false errorCode=510 [junit4] 2> 584321 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 584321 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 584321 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=3 commError=false errorCode=510 [junit4] 2> 584321 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 584321 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 584321 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=4 commError=false errorCode=510 [junit4] 2> 584321 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 584321 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 584322 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=5 commError=false errorCode=510 [junit4] 2> 584322 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 584322 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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> 585323 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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> 585323 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 585323 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 585323 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=1 commError=false errorCode=510 [junit4] 2> 585323 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 585323 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 585324 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=2 commError=false errorCode=510 [junit4] 2> 585324 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 585324 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 585324 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=3 commError=false errorCode=510 [junit4] 2> 585324 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 585324 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 585324 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=4 commError=false errorCode=510 [junit4] 2> 585324 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 585324 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 585325 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=5 commError=false errorCode=510 [junit4] 2> 585325 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 585325 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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> 586326 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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> 586326 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 586326 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 586326 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=1 commError=false errorCode=510 [junit4] 2> 586326 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 586326 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 586327 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=2 commError=false errorCode=510 [junit4] 2> 586327 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 586327 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 586327 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=3 commError=false errorCode=510 [junit4] 2> 586327 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 586327 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 586328 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=4 commError=false errorCode=510 [junit4] 2> 586328 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 586328 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 586328 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=5 commError=false errorCode=510 [junit4] 2> 586328 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 586328 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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> 587329 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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> 587329 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 587329 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 587329 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=1 commError=false errorCode=510 [junit4] 2> 587329 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 587329 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 587330 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=2 commError=false errorCode=510 [junit4] 2> 587330 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 587330 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 587334 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=3 commError=false errorCode=510 [junit4] 2> 587334 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 587334 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 587335 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=4 commError=false errorCode=510 [junit4] 2> 587335 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 587335 WARN (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient Re-trying request to collection(s) [forceleader_lower_terms_collection] after stale state error from server. [junit4] 2> 587335 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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=5 commError=false errorCode=510 [junit4] 2> 587335 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.CloudSolrClient request was not communication error it seems [junit4] 2> 587335 ERROR (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] 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> 587335 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.ForceLeaderTest Document couldn't be sent, which is expected. [junit4] 2> 587335 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.ForceLeaderTest Do force leader... [junit4] 2> 587355 INFO (zkConnectionManagerCallback-632-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 587356 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3) [junit4] 2> 587357 INFO (TEST-ForceLeaderTest.testReplicasInLowerTerms-seed#[D2A541849C903D90]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:43814/solr ready [junit4] 2> 587358 INFO (SocketProxy-Acceptor-38248) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=42028,localport=38248], receiveBufferSize:531000 [junit4] 2> 587358 INFO (SocketProxy-Acceptor-38248) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=34403,localport=49730], receiveBufferSize=530904 [junit4] 2> 587359 INFO (qtp925117619-4193) [n:127.0.0.1:38248_mo_%2Fvt ] 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> 587359 INFO (qtp925117619-4193) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection ] o.a.s.h.a.CollectionsHandler Force leader invoked, state: znodeVersion: 0 [junit4] 2> live nodes:[127.0.0.1:38248_mo_%2Fvt, 127.0.0.1:39008_mo_%2Fvt, 127.0.0.1:39550_mo_%2Fvt] [junit4] 2> collections:{forceleader_lower_terms_collection=DocCollection(forceleader_lower_terms_collection//collections/forceleader_lower_terms_collection/state.json/7)={ [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_node3":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n1", [junit4] 2> "base_url":"http://127.0.0.1:37340/mo_/vt";, [junit4] 2> "node_name":"127.0.0.1:37340_mo_%2Fvt", [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:39550/mo_/vt";, [junit4] 2> "node_name":"127.0.0.1:39550_mo_%2Fvt", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}, [junit4] 2> "core_node6":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n4", [junit4] 2> "base_url":"http://127.0.0.1:38248/mo_/vt";, [junit4] 2> "node_name":"127.0.0.1:38248_mo_%2Fvt", [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"}, control_collection=DocCollection(control_collection//collections/control_collection/state.json/3)={ [junit4] 2> "pullReplicas":"0", [junit4] 2> "replicationFactor":"1", [junit4] 2> "shards":{"shard1":{ [junit4] 2> "range":"80000000-7fffffff", [junit4] 2> "state":"active", [junit4] 2> "replicas":{"core_node2":{ [junit4] 2> "core":"control_collection_shard1_replica_n1", [junit4] 2> "base_url":"http://127.0.0.1:38248/mo_/vt";, [junit4] 2> "node_name":"127.0.0.1:38248_mo_%2Fvt", [junit4] 2> "state":"active", [junit4] 2> "type":"NRT", [junit4] 2> "leader":"true"}}}}, [junit4] 2> "router":{"name":"compositeId"}, [junit4] 2> "maxShardsPerNode":"1", [junit4] 2> "autoAddReplicas":"false", [junit4] 2> "nrtReplicas":"1", [junit4] 2> "tlogReplicas":"0"}, collection1=LazyCollectionRef(collection1)} [junit4] 2> 587361 INFO (qtp925117619-4193) [n:127.0.0.1:38248_mo_%2Fvt 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=1, core_node3=2, core_node5=2}, version=5} [junit4] 2> 587362 INFO (qtp925117619-4193) [n:127.0.0.1:38248_mo_%2Fvt 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_node3=2, core_node5=2}, version=6} [junit4] 2> 591662 INFO (SocketProxy-Acceptor-38248) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=42044,localport=38248], receiveBufferSize:531000 [junit4] 2> 591662 INFO (SocketProxy-Acceptor-38248) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=34403,localport=49746], receiveBufferSize=530904 [junit4] 2> 591664 INFO (qtp925117619-4190) [n:127.0.0.1:38248_mo_%2Fvt ] 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&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n4:INDEX.sizeInBytes} status=0 QTime=1 [junit4] 2> 591665 INFO (qtp925117619-4194) [n:127.0.0.1:38248_mo_%2Fvt ] 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&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n4:INDEX.sizeInBytes} status=0 QTime=0 [junit4] 2> 591666 INFO (qtp925117619-4192) [n:127.0.0.1:38248_mo_%2Fvt ] 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&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n4:INDEX.sizeInBytes} status=0 QTime=0 [junit4] 2> 591667 INFO (qtp925117619-4191) [n:127.0.0.1:38248_mo_%2Fvt ] 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> 591668 INFO (qtp925117619-4190) [n:127.0.0.1:38248_mo_%2Fvt ] 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> 591669 INFO (qtp925117619-4194) [n:127.0.0.1:38248_mo_%2Fvt ] 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> 591671 INFO (qtp925117619-4192) [n:127.0.0.1:38248_mo_%2Fvt ] 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> 591672 INFO (qtp925117619-4191) [n:127.0.0.1:38248_mo_%2Fvt ] 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> 591674 INFO (qtp2084883817-4270) [n:127.0.0.1:39008_mo_%2Fvt ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard1.replica_n2:INDEX.sizeInBytes} status=0 QTime=0 [junit4] 2> 591674 INFO (qtp2084883817-4272) [n:127.0.0.1:39008_mo_%2Fvt ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard1.replica_n2:INDEX.sizeInBytes} status=0 QTime=0 [junit4] 2> 591675 INFO (qtp2084883817-4273) [n:127.0.0.1:39008_mo_%2Fvt ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.collection1.shard1.replica_n2:INDEX.sizeInBytes} status=0 QTime=0 [junit4] 2> 591676 INFO (qtp2084883817-4274) [n:127.0.0.1:39008_mo_%2Fvt ] 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> 591677 INFO (qtp2084883817-4271) [n:127.0.0.1:39008_mo_%2Fvt ] 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> 591678 INFO (qtp2084883817-4270) [n:127.0.0.1:39008_mo_%2Fvt ] 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> 591679 INFO (qtp2084883817-4272) [n:127.0.0.1:39008_mo_%2Fvt ] 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> 591680 INFO (qtp2084883817-4273) [n:127.0.0.1:39008_mo_%2Fvt ] 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> 591681 INFO (SocketProxy-Acceptor-39550) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=54422,localport=39550], receiveBufferSize:531000 [junit4] 2> 591681 INFO (SocketProxy-Acceptor-39550) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=38865,localport=60788], receiveBufferSize=530904 [junit4] 2> 591682 INFO (qtp914639892-4259) [n:127.0.0.1:39550_mo_%2Fvt ] 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&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:INDEX.sizeInBytes} status=0 QTime=0 [junit4] 2> 591683 INFO (qtp914639892-4258) [n:127.0.0.1:39550_mo_%2Fvt ] 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&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:INDEX.sizeInBytes} status=0 QTime=0 [junit4] 2> 591709 INFO (qtp914639892-4257) [n:127.0.0.1:39550_mo_%2Fvt ] 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&key=solr.core.forceleader_lower_terms_collection.shard1.replica_n2:INDEX.sizeInBytes} status=0 QTime=25 [junit4] 2> 591711 INFO (qtp914639892-4261) [n:127.0.0.1:39550_mo_%2Fvt ] 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> 591712 INFO (qtp914639892-4260) [n:127.0.0.1:39550_mo_%2Fvt ] 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> 591713 INFO (qtp914639892-4259) [n:127.0.0.1:39550_mo_%2Fvt ] 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> 591714 INFO (qtp914639892-4258) [n:127.0.0.1:39550_mo_%2Fvt ] 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> 591715 INFO (qtp914639892-4257) [n:127.0.0.1:39550_mo_%2Fvt ] 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> 591718 INFO (AutoscalingActionExecutor-510-thread-1) [ ] o.a.s.c.a.ExecutePlanAction No operations to execute for event: { [junit4] 2> "id":"67683959db660bT1fnnr0hylf36mr6o204j6y3l6", [junit4] 2> "source":".auto_add_replicas", [junit4] 2> "eventTime":29106518131172875, [junit4] 2> "eventType":"NODELOST", [junit4] 2> "properties":{ [junit4] 2> "eventTimes":[29106518131172875], [junit4] 2> "preferredOperation":"movereplica", [junit4] 2> "_enqueue_time_":29106528134920812, [junit4] 2> "nodeNames":["127.0.0.1:37340_mo_%2Fvt"]}} [junit4] 2> 592362 WARN (qtp925117619-4193) [n:127.0.0.1:38248_mo_%2Fvt 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_node3":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n1", [junit4] 2> "base_url":"http://127.0.0.1:37340/mo_/vt";, [junit4] 2> "node_name":"127.0.0.1:37340_mo_%2Fvt", [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:39550/mo_/vt";, [junit4] 2> "node_name":"127.0.0.1:39550_mo_%2Fvt", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}, [junit4] 2> "core_node6":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n4", [junit4] 2> "base_url":"http://127.0.0.1:38248/mo_/vt";, [junit4] 2> "node_name":"127.0.0.1:38248_mo_%2Fvt", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}}} [junit4] 2> 596307 INFO (zkCallback-582-thread-3) [n:127.0.0.1:39550_mo_%2Fvt 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> 596307 WARN (zkCallback-582-thread-3) [n:127.0.0.1:39550_mo_%2Fvt 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> 597362 WARN (qtp925117619-4193) [n:127.0.0.1:38248_mo_%2Fvt 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_node3":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n1", [junit4] 2> "base_url":"http://127.0.0.1:37340/mo_/vt";, [junit4] 2> "node_name":"127.0.0.1:37340_mo_%2Fvt", [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:39550/mo_/vt";, [junit4] 2> "node_name":"127.0.0.1:39550_mo_%2Fvt", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}, [junit4] 2> "core_node6":{ [junit4] 2> "core":"forceleader_lower_terms_collection_shard1_replica_n4", [junit4] 2> "base_url":"http://127.0.0.1:38248/mo_/vt";, [junit4] 2> "node_name":"127.0.0.1:38248_mo_%2Fvt", [junit4] 2> "state":"down", [junit4] 2> "type":"NRT"}}} [junit4] 2> 598808 INFO (zkCallback-582-thread-3) [n:127.0.0.1:39550_mo_%2Fvt 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:39550/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n2/ [junit4] 2> 598808 INFO (zkCallback-582-thread-3) [n:127.0.0.1:39550_mo_%2Fvt 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:39550/mo_/vt START replicas=[http://127.0.0.1:38248/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n4/] nUpdates=100 [junit4] 2> 598809 INFO (SocketProxy-Acceptor-38248) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=42062,localport=38248], receiveBufferSize:531000 [junit4] 2> 598809 INFO (SocketProxy-Acceptor-38248) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=34403,localport=49764], receiveBufferSize=530904 [junit4] 2> 598810 INFO (qtp925117619-4194) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n4] webapp=/mo_/vt path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=0 [junit4] 2> 598810 INFO (zkCallback-582-thread-3) [n:127.0.0.1:39550_mo_%2Fvt 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:39550/mo_/vt Received 1 versions from http://127.0.0.1:38248/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n4/ fingerprint:null [junit4] 2> 598811 INFO (zkCallback-582-thread-3) [n:127.0.0.1:39550_mo_%2Fvt 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:39550/mo_/vt No additional versions requested. ourHighThreshold=1621904972726665216 otherLowThreshold=1621904972726665216 ourHighest=1621904972726665216 otherHighest=1621904972726665216 [junit4] 2> 598811 INFO (zkCallback-582-thread-3) [n:127.0.0.1:39550_mo_%2Fvt 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:39550/mo_/vt DONE. sync succeeded [junit4] 2> 598811 INFO (zkCallback-582-thread-3) [n:127.0.0.1:39550_mo_%2Fvt 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> 598811 INFO (zkCallback-582-thread-3) [n:127.0.0.1:39550_mo_%2Fvt 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:39550/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n2/: try and ask http://127.0.0.1:38248/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n4/ to sync [junit4] 2> 598812 INFO (qtp925117619-4192) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.u.PeerSync PeerSync: core=forceleader_lower_terms_collection_shard1_replica_n4 url=http://127.0.0.1:38248/mo_/vt START replicas=[http://127.0.0.1:39550/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n2/] nUpdates=100 [junit4] 2> 598819 INFO (qtp914639892-4261) [n:127.0.0.1:39550_mo_%2Fvt 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@13c6a735[forceleader_lower_terms_collection_shard1_replica_n2] realtime] [junit4] 2> 598820 INFO (qtp914639892-4261) [n:127.0.0.1:39550_mo_%2Fvt 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:5.0 result:{maxVersionSpecified=9223372036854775807, maxVersionEncountered=1621904972726665216, maxInHash=1621904972726665216, versionsHash=4774203817078019985, numVersions=1, numDocs=1, maxDoc=1} [junit4] 2> 598820 INFO (qtp914639892-4261) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/get params={distrib=false&qt=/get&getFingerprint=9223372036854775807&wt=javabin&version=2} status=0 QTime=6 [junit4] 2> 598876 INFO (qtp925117619-4192) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.s.SolrIndexSearcher Opening [Searcher@74d3fe0f[forceleader_lower_terms_collection_shard1_replica_n4] realtime] [junit4] 2> 598876 INFO (qtp925117619-4192) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.u.IndexFingerprint IndexFingerprint millis:56.0 result:{maxVersionSpecified=9223372036854775807, maxVersionEncountered=1621904972726665216, maxInHash=1621904972726665216, versionsHash=4774203817078019985, numVersions=1, numDocs=1, maxDoc=1} [junit4] 2> 598877 INFO (qtp925117619-4192) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.u.PeerSync We are already in sync. No need to do a PeerSync [junit4] 2> 598877 INFO (qtp925117619-4192) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.c.S.Request [forceleader_lower_terms_collection_shard1_replica_n4] webapp=/mo_/vt path=/get params={distrib=false&qt=/get&getVersions=100&sync=http://127.0.0.1:39550/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n2/&wt=javabin&version=2} status=0 QTime=65 [junit4] 2> 598878 INFO (zkCallback-582-thread-3) [n:127.0.0.1:39550_mo_%2Fvt 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:39550/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n2/: sync completed with http://127.0.0.1:38248/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n4/ [junit4] 2> 598878 ERROR (zkCallback-582-thread-3) [n:127.0.0.1:39550_mo_%2Fvt 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> 598878 INFO (zkCallback-582-thread-3) [n:127.0.0.1:39550_mo_%2Fvt 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/73965118099816459-core_node5-n_0000000001 [junit4] 2> 598881 INFO (zkCallback-582-thread-4) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forceleader_lower_terms_collection/state.json] for collection [forceleader_lower_terms_collection] has occurred - updating... (live nodes size: [3]) [junit4] 2> 598881 INFO (zkCallback-553-thread-3) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forceleader_lower_terms_collection/state.json] for collection [forceleader_lower_terms_collection] has occurred - updating... (live nodes size: [3]) [junit4] 2> 598881 INFO (zkCallback-582-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forceleader_lower_terms_collection/state.json] for collection [forceleader_lower_terms_collection] has occurred - updating... (live nodes size: [3]) [junit4] 2> 598881 INFO (zkCallback-553-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forceleader_lower_terms_collection/state.json] for collection [forceleader_lower_terms_collection] has occurred - updating... (live nodes size: [3]) [junit4] 2> 598882 INFO (recoveryExecutor-579-thread-1-processing-n:127.0.0.1:39550_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n2 c:forceleader_lower_terms_collection s:shard1 r:core_node5) [n:127.0.0.1:39550_mo_%2Fvt 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> 598882 INFO (recoveryExecutor-579-thread-1-processing-n:127.0.0.1:39550_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n2 c:forceleader_lower_terms_collection s:shard1 r:core_node5) [n:127.0.0.1:39550_mo_%2Fvt 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> 598882 INFO (zkCallback-582-thread-3) [n:127.0.0.1:39550_mo_%2Fvt 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:39550/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n2/ shard1 [junit4] 2> 598882 INFO (SocketProxy-Acceptor-39550) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=54440,localport=39550], receiveBufferSize:531000 [junit4] 2> 598883 INFO (SocketProxy-Acceptor-39550) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=38865,localport=60806], receiveBufferSize=530904 [junit4] 2> 598884 INFO (qtp914639892-4259) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/admin/ping params={wt=javabin&version=2} hits=0 status=0 QTime=1 [junit4] 2> 598884 INFO (qtp914639892-4259) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/admin/ping params={wt=javabin&version=2} status=0 QTime=1 [junit4] 2> 598885 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[forceleader_lower_terms_collection_shard1_replica_n4] [junit4] 2> 598885 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] 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/J1/temp/solr.cloud.ForceLeaderTest_D2A541849C903D90-001/control-001/cores/forceleader_lower_terms_collection_shard1_replica_n4/data/tlog/tlog.0000000000000000000 refcount=1}} [junit4] 2> 598885 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.c.RecoveryStrategy Publishing state of core [forceleader_lower_terms_collection_shard1_replica_n4] as recovering, leader is [http://127.0.0.1:39550/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n2/] and I am [http://127.0.0.1:38248/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n4/] [junit4] 2> 598886 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.c.ZkShardTerms Successful update of terms at /collections/forceleader_lower_terms_collection/terms/shard1 to Terms{values={core_node6=2, core_node6_recovering=2, core_node3=2, core_node5=2}, version=7} [junit4] 2> 598887 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://127.0.0.1:39550/mo_/vt]; [WaitForState: action=PREPRECOVERY&core=forceleader_lower_terms_collection_shard1_replica_n2&nodeName=127.0.0.1:38248_mo_%252Fvt&coreNodeName=core_node6&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true] [junit4] 2> 598888 INFO (qtp914639892-4258) [n:127.0.0.1:39550_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n2] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node6, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true [junit4] 2> 598888 INFO (qtp914639892-4258) [n:127.0.0.1:39550_mo_%2Fvt 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:38248_mo_%2Fvt, coreNodeName=core_node6, onlyIfActiveCheckResult=false, nodeProps: core_node6:{"core":"forceleader_lower_terms_collection_shard1_replica_n4","base_url":"http://127.0.0.1:38248/mo_/vt","node_name":"127.0.0.1:38248_mo_%2Fvt","state":"down","type":"NRT"} [junit4] 2> 598989 INFO (zkCallback-553-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forceleader_lower_terms_collection/state.json] for collection [forceleader_lower_terms_collection] has occurred - updating... (live nodes size: [3]) [junit4] 2> 598989 INFO (zkCallback-582-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forceleader_lower_terms_collection/state.json] for collection [forceleader_lower_terms_collection] has occurred - updating... (live nodes size: [3]) [junit4] 2> 598989 INFO (zkCallback-553-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forceleader_lower_terms_collection/state.json] for collection [forceleader_lower_terms_collection] has occurred - updating... (live nodes size: [3]) [junit4] 2> 598989 INFO (zkCallback-582-thread-3) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forceleader_lower_terms_collection/state.json] for collection [forceleader_lower_terms_collection] has occurred - updating... (live nodes size: [3]) [junit4] 2> 598990 INFO (watches-586-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:38248_mo_%2Fvt, coreNodeName=core_node6, onlyIfActiveCheckResult=false, nodeProps: core_node6:{"core":"forceleader_lower_terms_collection_shard1_replica_n4","base_url":"http://127.0.0.1:38248/mo_/vt","node_name":"127.0.0.1:38248_mo_%2Fvt","state":"recovering","type":"NRT"} [junit4] 2> 598990 INFO (qtp914639892-4258) [n:127.0.0.1:39550_mo_%2Fvt 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:38248_mo_%252Fvt&onlyIfLeaderActive=true&core=forceleader_lower_terms_collection_shard1_replica_n2&coreNodeName=core_node6&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=0 QTime=101 [junit4] 2> 599490 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.c.RecoveryStrategy Attempting to PeerSync from [http://127.0.0.1:39550/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n2/] - recoveringAfterStartup=[true] [junit4] 2> 599490 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.u.PeerSyncWithLeader no frame of reference to tell if we've missed updates [junit4] 2> 599491 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.c.RecoveryStrategy PeerSync Recovery was not successful - trying replication. [junit4] 2> 599491 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.c.RecoveryStrategy Starting Replication Recovery. [junit4] 2> 599491 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.c.RecoveryStrategy Attempting to replicate from [http://127.0.0.1:39550/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n2/]. [junit4] 2> 599492 INFO (qtp914639892-4257) [n:127.0.0.1:39550_mo_%2Fvt 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_=1621904992536363008,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 599493 INFO (qtp914639892-4257) [n:127.0.0.1:39550_mo_%2Fvt 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@6bde8506 commitCommandVersion:1621904992536363008 [junit4] 2> 599494 INFO (SocketProxy-Acceptor-38248) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=42070,localport=38248], receiveBufferSize:531000 [junit4] 2> 599496 INFO (SocketProxy-Acceptor-38248) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=34403,localport=49772], receiveBufferSize=530904 [junit4] 2> 599497 INFO (qtp925117619-4190) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.u.p.DistributedUpdateProcessor Ignoring commit while not ACTIVE - state: BUFFERING replay: false [junit4] 2> 599498 INFO (qtp925117619-4190) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.u.p.LogUpdateProcessorFactory [forceleader_lower_terms_collection_shard1_replica_n4] webapp=/mo_/vt path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=false&commit=true&softCommit=false&distrib.from=http://127.0.0.1:39550/mo_/vt/forceleader_lower_terms_collection_shard1_replica_n2/&commit_end_point=replicas&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 1 [junit4] 2> 599499 INFO (qtp914639892-4257) [n:127.0.0.1:39550_mo_%2Fvt 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@2b0cd1aa[forceleader_lower_terms_collection_shard1_replica_n2] realtime] [junit4] 2> 599500 INFO (qtp914639892-4257) [n:127.0.0.1:39550_mo_%2Fvt 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> 599500 INFO (qtp914639892-4257) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/update params={waitSearcher=true&openSearcher=false&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 9 [junit4] 2> 599503 INFO (qtp914639892-4261) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0 [junit4] 2> 599503 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher Master's generation: 2 [junit4] 2> 599504 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher Master's version: 1546769135034 [junit4] 2> 599504 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher Slave's generation: 1 [junit4] 2> 599504 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher Slave's version: 0 [junit4] 2> 599504 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher Starting replication process [junit4] 2> 599505 INFO (qtp914639892-4260) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&tlogFiles=false&wt=javabin&version=2&command=filelist} status=0 QTime=0 [junit4] 2> 599542 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher Number of files in latest index in master: 25 [junit4] 2> 599542 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0_LuceneVarGapDocFreqInterval_0.pos did not match. expected checksum is 610947597 and actual is checksum 2335096906. expected length is 97 and actual length is 97 [junit4] 2> 599542 INFO (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher Starting download (fullCopy=true) to MockDirectoryWrapper(RAMDirectory@7b89e03 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@7813c3d) [junit4] 2> 599542 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0_LuceneVarGapDocFreqInterval_0.pos did not match. expected checksum is 610947597 and actual is checksum 2335096906. expected length is 97 and actual length is 97 [junit4] 2> 599543 INFO (qtp914639892-4259) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0_LuceneVarGapDocFreqInterval_0.pos&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 599582 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0.nvd did not match. expected checksum is 3377608374 and actual is checksum 646995336. expected length is 59 and actual length is 59 [junit4] 2> 599582 INFO (qtp914639892-4258) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0.nvd&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 599622 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0_LuceneVarGapDocFreqInterval_0.tib did not match. expected checksum is 4229969806 and actual is checksum 2594963035. expected length is 206 and actual length is 206 [junit4] 2> 599622 INFO (qtp914639892-4257) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0_LuceneVarGapDocFreqInterval_0.tib&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 599662 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0_Lucene70_1.dvd did not match. expected checksum is 36138015 and actual is checksum 1732269913. expected length is 73 and actual length is 73 [junit4] 2> 599662 INFO (qtp914639892-4261) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0_Lucene70_1.dvd&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 599702 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0.dii did not match. expected checksum is 677699858 and actual is checksum 1189673555. expected length is 83 and actual length is 83 [junit4] 2> 599702 INFO (qtp914639892-4260) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0.dii&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 599746 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0_TestBloomFilteredLucenePostings_0.doc did not match. expected checksum is 3941116746 and actual is checksum 1688869492. expected length is 133 and actual length is 133 [junit4] 2> 599746 INFO (qtp914639892-4259) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0_TestBloomFilteredLucenePostings_0.doc&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 599786 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0_LuceneVarGapDocFreqInterval_0.tiv did not match. expected checksum is 965287047 and actual is checksum 3737583068. expected length is 127 and actual length is 127 [junit4] 2> 599786 INFO (qtp914639892-4258) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0_LuceneVarGapDocFreqInterval_0.tiv&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 599826 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0_Lucene70_0.dvd did not match. expected checksum is 358381660 and actual is checksum 1882931994. expected length is 73 and actual length is 73 [junit4] 2> 599826 INFO (qtp914639892-4257) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0_Lucene70_0.dvd&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 599866 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0_Memory_0.mdvd did not match. expected checksum is 2352606422 and actual is checksum 785040329. expected length is 105 and actual length is 105 [junit4] 2> 599866 INFO (qtp914639892-4261) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0_Memory_0.mdvd&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 599906 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0_Memory_0.mdvm did not match. expected checksum is 3440362628 and actual is checksum 2697857015. expected length is 136 and actual length is 136 [junit4] 2> 599907 INFO (qtp914639892-4260) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0_Memory_0.mdvm&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 599946 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0.dim did not match. expected checksum is 2482956082 and actual is checksum 877518548. expected length is 334 and actual length is 334 [junit4] 2> 599946 INFO (qtp914639892-4259) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0.dim&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 599986 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0.si did not match. expected checksum is 3938919187 and actual is checksum 3588089260. expected length is 894 and actual length is 894 [junit4] 2> 599986 INFO (qtp914639892-4258) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0.si&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 600026 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0.fdx did not match. expected checksum is 98813526 and actual is checksum 315335318. expected length is 83 and actual length is 83 [junit4] 2> 600026 INFO (qtp914639892-4257) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0.fdx&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 600066 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0.fdt did not match. expected checksum is 3082521764 and actual is checksum 1499895475. expected length is 126 and actual length is 126 [junit4] 2> 600067 INFO (qtp914639892-4261) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0.fdt&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 600110 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0_Lucene70_0.dvm did not match. expected checksum is 921101644 and actual is checksum 3588346419. expected length is 147 and actual length is 147 [junit4] 2> 600111 INFO (qtp914639892-4260) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0_Lucene70_0.dvm&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 600150 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0_TestBloomFilteredLucenePostings_0.blm did not match. expected checksum is 1430196715 and actual is checksum 3721942751. expected length is 147 and actual length is 147 [junit4] 2> 600151 INFO (qtp914639892-4259) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0_TestBloomFilteredLucenePostings_0.blm&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 600190 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0_TestBloomFilteredLucenePostings_0.tim did not match. expected checksum is 891890122 and actual is checksum 4264526085. expected length is 289 and actual length is 289 [junit4] 2> 600190 INFO (qtp914639892-4258) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0_TestBloomFilteredLucenePostings_0.tim&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 600230 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0_TestBloomFilteredLucenePostings_0.tip did not match. expected checksum is 400391040 and actual is checksum 1908374060. expected length is 146 and actual length is 146 [junit4] 2> 600230 INFO (qtp914639892-4257) [n:127.0.0.1:39550_mo_%2Fvt 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=/mo_/vt path=/replication params={generation=2&qt=/replication&file=_0_TestBloomFilteredLucenePostings_0.tip&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0 [junit4] 2> 600270 WARN (recoveryExecutor-550-thread-1-processing-n:127.0.0.1:38248_mo_%2Fvt x:forceleader_lower_terms_collection_shard1_replica_n4 c:forceleader_lower_terms_collection s:shard1 r:core_node6) [n:127.0.0.1:38248_mo_%2Fvt c:forceleader_lower_terms_collection s:shard1 r:core_node6 x:forceleader_lower_terms_collection_shard1_replica_n4] o.a.s.h.IndexFetcher File _0_TestBloomFiltered [...truncated too long message...] [junit4] 2> 1894459 INFO (TEST-StressHdfsTest.test-seed#[D2A541849C903D90]) [ ] o.a.s.c.ZkTestServer parse host and port list: 127.0.0.1:43012 [junit4] 2> 1894459 INFO (TEST-StressHdfsTest.test-seed#[D2A541849C903D90]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1 43012 [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=StressHdfsTest -Dtests.method=test -Dtests.seed=D2A541849C903D90 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-7.x/test-data/enwiki.random.lines.txt -Dtests.locale=mt-MT -Dtests.timezone=PST8PDT -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1 [junit4] FAILURE 375s J2 | StressHdfsTest.test <<< [junit4] > Throwable #1: java.lang.AssertionError: There are still nodes recoverying - waited for 330 seconds [junit4] > at __randomizedtesting.SeedInfo.seed([D2A541849C903D90:5AF17E5E326C5068]:0) [junit4] > at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:195) [junit4] > at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:143) [junit4] > at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:138) [junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.waitForRecoveriesToFinish(AbstractFullDistribZkTestBase.java:1008) [junit4] > at org.apache.solr.cloud.hdfs.StressHdfsTest.createAndDeleteCollection(StressHdfsTest.java:164) [junit4] > at org.apache.solr.cloud.hdfs.StressHdfsTest.test(StressHdfsTest.java:108) [junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsFixedStatement.callStatement(BaseDistributedSearchTestCase.java:1063) [junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:1035) [junit4] > at java.lang.Thread.run(Thread.java:748) [junit4] 2> 1894461 WARN (SUITE-StressHdfsTest-seed#[D2A541849C903D90]-worker) [ ] o.a.h.h.s.d.DirectoryScanner DirectoryScanner: shutdown has been called [junit4] 2> 1894481 INFO (SUITE-StressHdfsTest-seed#[D2A541849C903D90]-worker) [ ] o.m.log Stopped HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:0 [junit4] 2> 1894486 WARN (DataNode: [[[DISK]file:/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.StressHdfsTest_D2A541849C903D90-002/tempDir-001/hdfsBaseDir/data/data3/, [DISK]file:/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.StressHdfsTest_D2A541849C903D90-002/tempDir-001/hdfsBaseDir/data/data4/]] heartbeating to lucene2-us-west.apache.org/127.0.0.1:39715) [ ] o.a.h.h.s.d.DataNode Ending block pool service for: Block pool BP-169252904-127.0.0.1-1546770053233 (Datanode Uuid db9a908d-04db-40d1-bee0-ecda38406f0f) service to lucene2-us-west.apache.org/127.0.0.1:39715 [junit4] 2> 1894585 WARN (SUITE-StressHdfsTest-seed#[D2A541849C903D90]-worker) [ ] o.a.h.h.s.d.DirectoryScanner DirectoryScanner: shutdown has been called [junit4] 2> 1894619 INFO (SUITE-StressHdfsTest-seed#[D2A541849C903D90]-worker) [ ] o.m.log Stopped HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:0 [junit4] 2> 1894621 WARN (DataNode: [[[DISK]file:/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.StressHdfsTest_D2A541849C903D90-002/tempDir-001/hdfsBaseDir/data/data1/, [DISK]file:/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.StressHdfsTest_D2A541849C903D90-002/tempDir-001/hdfsBaseDir/data/data2/]] heartbeating to lucene2-us-west.apache.org/127.0.0.1:39715) [ ] o.a.h.h.s.d.IncrementalBlockReportManager IncrementalBlockReportManager interrupted [junit4] 2> 1894621 WARN (DataNode: [[[DISK]file:/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.StressHdfsTest_D2A541849C903D90-002/tempDir-001/hdfsBaseDir/data/data1/, [DISK]file:/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.StressHdfsTest_D2A541849C903D90-002/tempDir-001/hdfsBaseDir/data/data2/]] heartbeating to lucene2-us-west.apache.org/127.0.0.1:39715) [ ] o.a.h.h.s.d.DataNode Ending block pool service for: Block pool BP-169252904-127.0.0.1-1546770053233 (Datanode Uuid ec228f54-87b9-4ef2-a59b-5cc950087bd8) service to lucene2-us-west.apache.org/127.0.0.1:39715 [junit4] 2> 1894643 INFO (SUITE-StressHdfsTest-seed#[D2A541849C903D90]-worker) [ ] o.m.log Stopped HttpServer2$selectchannelconnectorwithsafestar...@lucene2-us-west.apache.org:0 [junit4] 2> 1894643 WARN (1045950252@qtp-35952080-0 - Acceptor0 HttpServer2$selectchannelconnectorwithsafestar...@lucene2-us-west.apache.org:39252) [ ] o.a.h.h.HttpServer2 HttpServer Acceptor: isRunning is false. Rechecking. [junit4] 2> 1894644 WARN (1045950252@qtp-35952080-0 - Acceptor0 HttpServer2$selectchannelconnectorwithsafestar...@lucene2-us-west.apache.org:39252) [ ] o.a.h.h.HttpServer2 HttpServer Acceptor: isRunning is false [junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.StressHdfsTest_D2A541849C903D90-002 [junit4] 2> Jan 06, 2019 10:27:10 AM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks [junit4] 2> WARNING: Will linger awaiting termination of 32 leaked thread(s). [junit4] 2> NOTE: test params are: codec=Asserting(Lucene70): {multiDefault=BlockTreeOrds(blocksize=128), id=PostingsFormat(name=Direct), text=PostingsFormat(name=Memory), txt_t=PostingsFormat(name=Memory)}, docValues:{range_facet_l_dv=DocValuesFormat(name=Asserting), _version_=DocValuesFormat(name=Lucene70), intDefault=DocValuesFormat(name=Lucene70), id_i1=DocValuesFormat(name=Direct), range_facet_i_dv=DocValuesFormat(name=Lucene70), intDvoDefault=DocValuesFormat(name=Lucene70), range_facet_l=DocValuesFormat(name=Lucene70), timestamp=DocValuesFormat(name=Lucene70)}, maxPointsInLeafNode=331, maxMBSortInHeap=7.533478839417678, sim=RandomSimilarity(queryNorm=false): {}, locale=mt-MT, timezone=PST8PDT [junit4] 2> NOTE: Linux 4.4.0-112-generic amd64/Oracle Corporation 1.8.0_191 (64-bit)/cpus=4,threads=4,free=146465744,total=485490688 [junit4] 2> NOTE: All tests run in this JVM: [LIROnShardRestartTest, TestSimTriggerIntegration, HdfsChaosMonkeySafeLeaderTest, ForceLeaderTest, LIROnShardRestartTest, LIROnShardRestartTest, StressHdfsTest, StressHdfsTest] [junit4] Completed [25/25 (14!)] on J2 in 380.17s, 1 test, 1 failure <<< FAILURES! [junit4] [junit4] [junit4] Tests with failures [seed: D2A541849C903D90] (first 10 out of 16): [junit4] - org.apache.solr.cloud.LIROnShardRestartTest.testAllReplicasInLIR [junit4] - org.apache.solr.cloud.autoscaling.sim.TestSimTriggerIntegration.testNodeMarkersRegistration [junit4] - org.apache.solr.cloud.autoscaling.sim.TestSimTriggerIntegration.testNodeMarkersRegistration [junit4] - org.apache.solr.cloud.LIROnShardRestartTest.testAllReplicasInLIR [junit4] - org.apache.solr.cloud.LIROnShardRestartTest.testSeveralReplicasInLIR [junit4] - org.apache.solr.cloud.autoscaling.sim.TestSimTriggerIntegration.testNodeMarkersRegistration [junit4] - org.apache.solr.cloud.hdfs.HdfsChaosMonkeySafeLeaderTest (suite) [junit4] - org.apache.solr.cloud.ForceLeaderTest.testReplicasInLIRNoLeader [junit4] - org.apache.solr.cloud.LIROnShardRestartTest.testAllReplicasInLIR [junit4] - org.apache.solr.cloud.LIROnShardRestartTest.testSeveralReplicasInLIR [junit4] [junit4] [junit4] JVM J0: 0.78 .. 1552.18 = 1551.40s [junit4] JVM J1: 0.73 .. 1655.39 = 1654.66s [junit4] JVM J2: 0.70 .. 1900.53 = 1899.83s [junit4] Execution time total: 31 minutes 40 seconds [junit4] Tests summary: 25 suites, 90 tests, 1 suite-level error, 7 errors, 8 failures, 20 ignored (15 assumptions) 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: 25 suites, 90 tests, 1 suite-level error, 7 errors, 8 failures, 20 ignored (15 assumptions) [seed: D2A541849C903D90] Total time: 31 minutes 42 seconds [repro] Setting last failure code to 256 [repro] Failures: [repro] 1/5 failed: org.apache.solr.cloud.hdfs.HdfsChaosMonkeySafeLeaderTest [repro] 2/5 failed: org.apache.solr.cloud.ForceLeaderTest [repro] 3/5 failed: org.apache.solr.cloud.LIROnShardRestartTest [repro] 4/5 failed: org.apache.solr.cloud.autoscaling.sim.TestSimTriggerIntegration [repro] 4/5 failed: org.apache.solr.cloud.hdfs.StressHdfsTest [repro] git checkout 2bd6f246b026b7d576097a4e4c3ebb293fc2b0d0 Previous HEAD position was ecd4a3b... SOLR-12514: FIxed the test and another bug HEAD is now at 2bd6f24... SOLR-11126: New Node-level health check handler at /admin/info/healthcheck and /node/health paths that checks if the node is live, connected to zookeeper and not shutdown [repro] Exiting with code 256 Archiving artifacts [Fast Archiver] No artifacts from Lucene-Solr-repro Repro-Lucene-Solr-Tests-7.x#1190 to compare, so performing full copy of artifacts Recording test results Build step 'Publish JUnit test result report' changed build result to UNSTABLE Email was triggered for: Unstable (Test Failures) Sending email for trigger: Unstable (Test Failures)
--------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
