You are viewing a plain text version of this content. The canonical link for it is here.
Posted to builds@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2020/06/12 11:53:33 UTC
[JENKINS] Lucene-Solr-NightlyTests-master - Build # 2221 - Still
Unstable
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-master/2221/
2 tests failed.
FAILED: org.apache.lucene.index.TestAllFilesDetectBitFlips.testCFS
Error Message:
Unexpected exception type, expected any of [CorruptIndexException, IndexFormatTooOldException, IndexFormatTooNewException] but got: java.lang.IllegalStateException: invalid input type 97
Stack Trace:
junit.framework.AssertionFailedError: Unexpected exception type, expected any of [CorruptIndexException, IndexFormatTooOldException, IndexFormatTooNewException] but got: java.lang.IllegalStateException: invalid input type 97
at __randomizedtesting.SeedInfo.seed([63035C02B7585C4:1CF574124D481658]:0)
at org.apache.lucene.util.LuceneTestCase.expectThrowsAnyOf(LuceneTestCase.java:2774)
at org.apache.lucene.index.TestAllFilesDetectBitFlips.corruptFile(TestAllFilesDetectBitFlips.java:128)
at org.apache.lucene.index.TestAllFilesDetectBitFlips.checkBitFlips(TestAllFilesDetectBitFlips.java:88)
at org.apache.lucene.index.TestAllFilesDetectBitFlips.doTest(TestAllFilesDetectBitFlips.java:81)
at org.apache.lucene.index.TestAllFilesDetectBitFlips.testCFS(TestAllFilesDetectBitFlips.java:47)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1754)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:942)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:978)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:992)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:370)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:819)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:470)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:951)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:836)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:887)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:898)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:370)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.lambda$forkTimeoutingTask$0(ThreadLeakControl.java:826)
at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: java.lang.IllegalStateException: invalid input type 97
at org.apache.lucene.util.fst.FST.<init>(FST.java:455)
at org.apache.lucene.codecs.blocktree.FieldReader.<init>(FieldReader.java:87)
at org.apache.lucene.codecs.blocktree.BlockTreeTermsReader.<init>(BlockTreeTermsReader.java:192)
at org.apache.lucene.codecs.lucene84.Lucene84PostingsFormat.fieldsProducer(Lucene84PostingsFormat.java:441)
at org.apache.lucene.codecs.perfield.PerFieldPostingsFormat$FieldsReader.<init>(PerFieldPostingsFormat.java:315)
at org.apache.lucene.codecs.perfield.PerFieldPostingsFormat.fieldsProducer(PerFieldPostingsFormat.java:395)
at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:114)
at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:83)
at org.apache.lucene.index.StandardDirectoryReader$1.doBody(StandardDirectoryReader.java:66)
at org.apache.lucene.index.StandardDirectoryReader$1.doBody(StandardDirectoryReader.java:58)
at org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfos.java:727)
at org.apache.lucene.index.StandardDirectoryReader.open(StandardDirectoryReader.java:81)
at org.apache.lucene.index.DirectoryReader.open(DirectoryReader.java:63)
at org.apache.lucene.index.TestAllFilesDetectBitFlips.lambda$corruptFile$0(TestAllFilesDetectBitFlips.java:130)
at org.apache.lucene.util.LuceneTestCase._expectThrows(LuceneTestCase.java:2869)
at org.apache.lucene.util.LuceneTestCase.expectThrowsAnyOf(LuceneTestCase.java:2762)
... 40 more
FAILED: org.apache.solr.cloud.ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms
Error Message:
Address already in use
Stack Trace:
java.net.BindException: Address already in use
at __randomizedtesting.SeedInfo.seed([77E764DEE5FC91E1:F9D3449D255B3195]:0)
at java.base/sun.nio.ch.Net.bind0(Native Method)
at java.base/sun.nio.ch.Net.bind(Net.java:461)
at java.base/sun.nio.ch.Net.bind(Net.java:453)
at java.base/sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:227)
at java.base/sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:80)
at org.eclipse.jetty.server.ServerConnector.openAcceptChannel(ServerConnector.java:342)
at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:307)
at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80)
at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:231)
at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:72)
at org.eclipse.jetty.server.Server.doStart(Server.java:385)
at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:72)
at org.apache.solr.client.solrj.embedded.JettySolrRunner.retryOnPortBindFailure(JettySolrRunner.java:566)
at org.apache.solr.client.solrj.embedded.JettySolrRunner.start(JettySolrRunner.java:504)
at org.apache.solr.client.solrj.embedded.JettySolrRunner.start(JettySolrRunner.java:472)
at org.apache.solr.cloud.ForceLeaderTest.bringBackOldLeaderAndSendDoc(ForceLeaderTest.java:250)
at org.apache.solr.cloud.ForceLeaderTest.testReplicasInLowerTerms(ForceLeaderTest.java:173)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1754)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:942)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:978)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:992)
at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsFixedStatement.callStatement(BaseDistributedSearchTestCase.java:1090)
at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:1061)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:370)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:819)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:470)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:951)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:836)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:887)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:898)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:370)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.lambda$forkTimeoutingTask$0(ThreadLeakControl.java:826)
at java.base/java.lang.Thread.run(Thread.java:834)
Build Log:
[...truncated 1503 lines...]
[junit4] Suite: org.apache.lucene.index.TestAllFilesDetectBitFlips
[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=TestAllFilesDetectBitFlips -Dtests.method=testCFS -Dtests.seed=63035C02B7585C4 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=pt-LU -Dtests.timezone=Mexico/BajaNorte -Dtests.asserts=true -Dtests.file.encoding=US-ASCII
[junit4] FAILURE 0.90s J0 | TestAllFilesDetectBitFlips.testCFS <<<
[junit4] > Throwable #1: junit.framework.AssertionFailedError: Unexpected exception type, expected any of [CorruptIndexException, IndexFormatTooOldException, IndexFormatTooNewException] but got: java.lang.IllegalStateException: invalid input type 97
[junit4] > at __randomizedtesting.SeedInfo.seed([63035C02B7585C4:1CF574124D481658]:0)
[junit4] > at org.apache.lucene.util.LuceneTestCase.expectThrowsAnyOf(LuceneTestCase.java:2774)
[junit4] > at org.apache.lucene.index.TestAllFilesDetectBitFlips.corruptFile(TestAllFilesDetectBitFlips.java:128)
[junit4] > at org.apache.lucene.index.TestAllFilesDetectBitFlips.checkBitFlips(TestAllFilesDetectBitFlips.java:88)
[junit4] > at org.apache.lucene.index.TestAllFilesDetectBitFlips.doTest(TestAllFilesDetectBitFlips.java:81)
[junit4] > at org.apache.lucene.index.TestAllFilesDetectBitFlips.testCFS(TestAllFilesDetectBitFlips.java:47)
[junit4] > at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4] > at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[junit4] > at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4] > at java.base/java.lang.reflect.Method.invoke(Method.java:566)
[junit4] > at java.base/java.lang.Thread.run(Thread.java:834)
[junit4] > Caused by: java.lang.IllegalStateException: invalid input type 97
[junit4] > at org.apache.lucene.util.fst.FST.<init>(FST.java:455)
[junit4] > at org.apache.lucene.codecs.blocktree.FieldReader.<init>(FieldReader.java:87)
[junit4] > at org.apache.lucene.codecs.blocktree.BlockTreeTermsReader.<init>(BlockTreeTermsReader.java:192)
[junit4] > at org.apache.lucene.codecs.lucene84.Lucene84PostingsFormat.fieldsProducer(Lucene84PostingsFormat.java:441)
[junit4] > at org.apache.lucene.codecs.perfield.PerFieldPostingsFormat$FieldsReader.<init>(PerFieldPostingsFormat.java:315)
[junit4] > at org.apache.lucene.codecs.perfield.PerFieldPostingsFormat.fieldsProducer(PerFieldPostingsFormat.java:395)
[junit4] > at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:114)
[junit4] > at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:83)
[junit4] > at org.apache.lucene.index.StandardDirectoryReader$1.doBody(StandardDirectoryReader.java:66)
[junit4] > at org.apache.lucene.index.StandardDirectoryReader$1.doBody(StandardDirectoryReader.java:58)
[junit4] > at org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfos.java:727)
[junit4] > at org.apache.lucene.index.StandardDirectoryReader.open(StandardDirectoryReader.java:81)
[junit4] > at org.apache.lucene.index.DirectoryReader.open(DirectoryReader.java:63)
[junit4] > at org.apache.lucene.index.TestAllFilesDetectBitFlips.lambda$corruptFile$0(TestAllFilesDetectBitFlips.java:130)
[junit4] > at org.apache.lucene.util.LuceneTestCase._expectThrows(LuceneTestCase.java:2869)
[junit4] > at org.apache.lucene.util.LuceneTestCase.expectThrowsAnyOf(LuceneTestCase.java:2762)
[junit4] > ... 40 more
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/lucene/build/core/test/J0/temp/lucene.index.TestAllFilesDetectBitFlips_63035C02B7585C4-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene86): {}, docValues:{}, maxPointsInLeafNode=922, maxMBSortInHeap=5.1792864045185905, sim=Asserting(org.apache.lucene.search.similarities.AssertingSimilarity@16b489bf), locale=pt-LU, timezone=Mexico/BajaNorte
[junit4] 2> NOTE: Linux 4.4.0-170-generic amd64/Oracle Corporation 11.0.4 (64-bit)/cpus=8,threads=1,free=107679456,total=408944640
[junit4] 2> NOTE: All tests run in this JVM: [TestFlex, TestUpgradeIndexMergePolicy, TestConjunctionDISI, TestSwappedIndexFiles, TestPolygon, TestPerFieldPostingsFormat, TestVirtualMethod, TestTermdocPerf, TestIndexOrDocValuesQuery, TestIndexTooManyDocs, TestDirectory, TestIntroSorter, TestSpanContainQuery, TestMixedDocValuesUpdates, TestNotDocIdSet, TestFieldInfos, TestNRTReaderWithThreads, TestMaxClauseLimit, TestIndexingSequenceNumbers, TestElevationComparator, TestField, TestSpanFirstQuery, TestAxiomaticF3LOG, TestTryDelete, TestLatLonShapeEncoding, TestCachingCollector, TestMultiPhraseQuery, TestSimpleWKTShapeParsing, TestFilterIterator, TestBufferedChecksum, TestSpanTermQuery, TestSpanNotQuery, TestReqExclBulkScorer, TestNot, TestFilterDirectoryReader, TestTermVectors, TestPayloads, TestSearchWithThreads, TestNIOFSDirectory, TestForceMergeForever, TestSimpleSearchEquivalence, TestOmitNorms, TestOperations, TestDistributionLL, TestMultiTermQueryRewrites, TestSmallFloat, TestIntSet, TestPrefixInBooleanQuery, TestMathUtil, TestParallelLeafReader, TestLucene60FieldInfoFormat, TestOneMergeWrappingMergePolicy, TestDocValues, TestCloseableThreadLocal, TestSegmentReader, TestAllFilesDetectTruncation, TestDocumentsWriterDeleteQueue, TestLatLonPointShapeQueries, TestDoubleRangeFieldQueries, TestLRUQueryCache, TestByteSlices, TestDateTools, TestAxiomaticF2EXP, TestReadOnlyIndex, TestCircle2D, TestTermRangeQuery, TestConstantScoreScorer, TestTimSorterWorstCase, TestCrash, TestNoMergeScheduler, TestTragicIndexWriterDeadlock, TestSegmentToThreadMapping, TestBasicModelIne, TestIndexOptions, TestNewestSegment, TestIndexFileDeleter, TestLongBitSet, TestIndexWriterOnDiskFull, TestMinShouldMatch2, TestCharTermAttributeImpl, TestAtomicUpdate, TestIntRange, TestLucene86PointsFormat, TestSortedNumericSortField, TestBytesRef, TestMultiLevelSkipList, TestDirectPacked, TestFieldUpdatesBuffer, LimitedFiniteStringsIteratorTest, TestRateLimiter, TestSleepingLockWrapper, Test2BPostings, TestAssertions, TestXYLineShapeQueries, TestXYPointShapeQueries, TestXYShape, TestXYShapeEncoding, TestLine2D, TestPoint, TestPoint2D, TestRectangle2D, TestXYLine, TestXYPoint, TestXYRectangle, Test2BBinaryDocValues, Test2BNumericDocValues, Test2BPoints, Test2BSortedDocValuesOrds, Test2BTerms, TestAddIndexes, TestAllFilesCheckIndexHeader, TestAllFilesDetectBitFlips]
[junit4] Completed [332/563 (1!)] on J0 in 13.31s, 2 tests, 1 failure <<< FAILURES!
[...truncated 12998 lines...]
[junit4] Suite: org.apache.solr.cloud.ForceLeaderWithTlogReplicasTest
[junit4] 2> 3803563 INFO (SUITE-ForceLeaderWithTlogReplicasTest-seed#[77E764DEE5FC91E1]-worker) [ ] o.a.s.SolrTestCase Setting 'solr.default.confdir' system property to test-framework derived value of '/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/server/solr/configsets/_default/conf'
[junit4] 2> 3803579 INFO (SUITE-ForceLeaderWithTlogReplicasTest-seed#[77E764DEE5FC91E1]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> 3803580 INFO (SUITE-ForceLeaderWithTlogReplicasTest-seed#[77E764DEE5FC91E1]-worker) [ ] o.a.s.SolrTestCaseJ4 Created dataDir: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/data-dir-169-001
[junit4] 2> 3803580 INFO (SUITE-ForceLeaderWithTlogReplicasTest-seed#[77E764DEE5FC91E1]-worker) [ ] o.a.s.SolrTestCaseJ4 Using TrieFields (NUMERIC_POINTS_SYSPROP=false) w/NUMERIC_DOCVALUES_SYSPROP=false
[junit4] 2> 3803581 INFO (SUITE-ForceLeaderWithTlogReplicasTest-seed#[77E764DEE5FC91E1]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.SolrTestCaseJ4$SuppressSSL(bugUrl="https://issues.apache.org/jira/browse/SOLR-5776")
[junit4] 2> 3803581 INFO (SUITE-ForceLeaderWithTlogReplicasTest-seed#[77E764DEE5FC91E1]-worker) [ ] o.a.s.BaseDistributedSearchTestCase Setting hostContext system property: /t_i/g
[junit4] 2> 3803599 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 3803599 INFO (ZkTestServer Run Thread) [ ] o.a.s.c.ZkTestServer client port: 0.0.0.0/0.0.0.0:0
[junit4] 2> 3803599 INFO (ZkTestServer Run Thread) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 3803699 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer start zk server on port: 38535
[junit4] 2> 3803699 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer waitForServerUp: 127.0.0.1:38535
[junit4] 2> 3803699 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer parse host and port list: 127.0.0.1:38535
[junit4] 2> 3803699 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1 38535
[junit4] 2> 3803701 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3803703 INFO (zkConnectionManagerCallback-22585-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3803703 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3803706 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3803707 INFO (zkConnectionManagerCallback-22587-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3803707 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3803708 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer put /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/core/src/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4] 2> 3803723 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer put /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/core/src/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4] 2> 3803725 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer put /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/core/src/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 3803726 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer put /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/core/src/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4] 2> 3803728 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer put /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/core/src/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4] 2> 3803729 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer put /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/core/src/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4] 2> 3803731 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer put /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/core/src/test-files/solr/collection1/conf/enumsConfig.xml to /configs/conf1/enumsConfig.xml
[junit4] 2> 3803733 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer put /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/core/src/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4] 2> 3803734 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer put /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/core/src/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 3803736 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer put /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/core/src/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4] 2> 3803737 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer put /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/core/src/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4] 2> 3803738 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.AbstractFullDistribZkTestBase Will use TLOG replicas unless explicitly asked otherwise
[junit4] 2> 3804228 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.s.e.JettySolrRunner Start Jetty (configured port=0, binding port=0)
[junit4] 2> 3804228 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.s.e.JettySolrRunner Trying to start Jetty on port 0 try number 2 ...
[junit4] 2> 3804228 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.e.j.s.Server jetty-9.4.27.v20200227; built: 2020-02-27T18:37:21.340Z; git: a304fd9f351f337e7c0e2a7c28878dd536149c6c; jvm 11.0.4+10-LTS
[junit4] 2> 3804229 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 3804229 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 3804229 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.e.j.s.session node0 Scavenging every 600000ms
[junit4] 2> 3804229 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@70715fa3{/t_i/g,null,AVAILABLE}
[junit4] 2> 3804230 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@619d2111{HTTP/1.1, (http/1.1, h2c)}{127.0.0.1:42660}
[junit4] 2> 3804230 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.e.j.s.Server Started @3804269ms
[junit4] 2> 3804230 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/t_i/g, solr.data.dir=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/tempDir-001/control/data, hostPort=37132, coreRootDirectory=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/control-001/cores, replicaType=NRT}
[junit4] 2> 3804230 ERROR (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3804230 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
[junit4] 2> 3804230 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 9.0.0
[junit4] 2> 3804230 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3804230 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr
[junit4] 2> 3804230 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2020-06-12T09:58:23.576760Z
[junit4] 2> 3804231 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3804232 INFO (zkConnectionManagerCallback-22589-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3804232 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3804347 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 3804347 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/control-001/solr.xml
[junit4] 2> 3804360 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e, but no JMX reporters were configured - adding default JMX reporter.
[junit4] 2> 3806726 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.h.c.HttpShardHandlerFactory Host whitelist initialized: WhitelistHostChecker [whitelistHosts=null, whitelistHostCheckingEnabled=false]
[junit4] 2> 3806727 WARN (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.e.j.u.s.S.config Trusting all certificates configured for Client@224ed9d9[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3806727 WARN (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for Client@224ed9d9[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3806747 WARN (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.e.j.u.s.S.config Trusting all certificates configured for Client@4faa0609[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3806747 WARN (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for Client@4faa0609[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3806769 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:38535/solr
[junit4] 2> 3806770 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3806771 INFO (zkConnectionManagerCallback-22600-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3806771 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3806891 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3806892 INFO (zkConnectionManagerCallback-22602-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3806892 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3807163 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:37132_t_i%2Fg
[junit4] 2> 3807163 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.Overseer Overseer (id=72957497593561092-127.0.0.1:37132_t_i%2Fg-n_0000000000) starting
[junit4] 2> 3807175 INFO (OverseerStateUpdate-72957497593561092-127.0.0.1:37132_t_i%2Fg-n_0000000000) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.Overseer Starting to work on the main queue : 127.0.0.1:37132_t_i%2Fg
[junit4] 2> 3807175 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37132_t_i%2Fg
[junit4] 2> 3807187 INFO (OverseerStateUpdate-72957497593561092-127.0.0.1:37132_t_i%2Fg-n_0000000000) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 3807190 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.p.PackageLoader /packages.json updated to version -1
[junit4] 2> 3807190 WARN (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.CoreContainer Not all security plugins configured! authentication=disabled authorization=disabled. Solr is only as secure as you make it. Consider configuring authentication/authorization before exposing Solr to users internal or external. See https://s.apache.org/solrsecurity for more info
[junit4] 2> 3807339 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 3807427 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e
[junit4] 2> 3807495 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e
[junit4] 2> 3807495 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e
[junit4] 2> 3807505 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/control-001/cores
[junit4] 2> 3807513 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3807515 INFO (zkConnectionManagerCallback-22619-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3807515 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3807516 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 3807517 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:38535/solr ready
[junit4] 2> 3807518 INFO (SocketProxy-Acceptor-37132) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=42390,localport=37132], receiveBufferSize: 531000
[junit4] 2> 3807518 INFO (SocketProxy-Acceptor-37132) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=42660,localport=39864], receiveBufferSize=530904
[junit4] 2> 3807519 INFO (qtp1496899731-96045) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params collection.configName=conf1&name=control_collection&nrtReplicas=1&action=CREATE&numShards=1&createNodeSet=127.0.0.1:37132_t_i%252Fg&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 3807522 INFO (OverseerThreadFactory-22609-thread-1-processing-n:127.0.0.1:37132_t_i%2Fg) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.a.c.CreateCollectionCmd Create collection control_collection
[junit4] 2> 3807632 INFO (SocketProxy-Acceptor-37132) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=42394,localport=37132], receiveBufferSize: 531000
[junit4] 2> 3807633 INFO (SocketProxy-Acceptor-37132) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=42660,localport=39868], receiveBufferSize=530904
[junit4] 2> 3807634 INFO (qtp1496899731-96044) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 3807634 INFO (qtp1496899731-96044) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CONTAINER.cores&wt=javabin&version=2&group=solr.node} status=0 QTime=1
[junit4] 2> 3807640 INFO (OverseerStateUpdate-72957497593561092-127.0.0.1:37132_t_i%2Fg-n_0000000000) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.o.SliceMutator createReplica() {
[junit4] 2> "operation":"ADDREPLICA",
[junit4] 2> "collection":"control_collection",
[junit4] 2> "shard":"shard1",
[junit4] 2> "core":"control_collection_shard1_replica_n1",
[junit4] 2> "state":"down",
[junit4] 2> "base_url":"http://127.0.0.1:37132/t_i/g",
[junit4] 2> "node_name":"127.0.0.1:37132_t_i%2Fg",
[junit4] 2> "type":"NRT",
[junit4] 2> "waitForFinalState":"false"}
[junit4] 2> 3807859 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg x:control_collection_shard1_replica_n1 ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node2&collection.configName=conf1&newCollection=true&name=control_collection_shard1_replica_n1&action=CREATE&numShards=1&collection=control_collection&shard=shard1&wt=javabin&version=2&replicaType=NRT
[junit4] 2> 3807882 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 9.0.0
[junit4] 2> 3807905 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.s.IndexSchema Schema name=test
[junit4] 2> 3808132 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 3808153 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.CoreContainer Creating SolrCore 'control_collection_shard1_replica_n1' using configuration from configset conf1, trusted=true
[junit4] 2> 3808154 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.control_collection.shard1.replica_n1' (registry 'solr.core.control_collection.shard1.replica_n1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e
[junit4] 2> 3808154 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.SolrCore [[control_collection_shard1_replica_n1] ] Opening new SolrCore at [/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/control-001/cores/control_collection_shard1_replica_n1], dataDir=[/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/control-001/cores/control_collection_shard1_replica_n1/data/]
[junit4] 2> 3808157 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=22, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.4674088592564648]
[junit4] 2> 3808159 WARN (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,attributes = {initParams=a, name=/dump, class=DumpRequestHandler},args = {defaults={a=A, b=B}}}
[junit4] 2> 3808295 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 3808295 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 3808297 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 3808297 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 3808299 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=47, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
[junit4] 2> 3808301 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 3808301 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 3808302 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 ms
[junit4] 2> 3808302 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1669286757817909248
[junit4] 2> 3808307 INFO (searcherExecutor-22621-thread-1-processing-n:127.0.0.1:37132_t_i%2Fg x:control_collection_shard1_replica_n1 c:control_collection s:shard1 r:core_node2) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.SolrCore [control_collection_shard1_replica_n1] Registered new searcher autowarm time: 0 ms
[junit4] 2> 3808310 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.ZkShardTerms Successful update of terms at /collections/control_collection/terms/shard1 to Terms{values={core_node2=0}, version=0}
[junit4] 2> 3808310 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.ShardLeaderElectionContextBase make sure parent is created /collections/control_collection/leaders/shard1
[junit4] 2> 3808314 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 3808314 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 3808314 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:37132/t_i/g/control_collection_shard1_replica_n1/
[junit4] 2> 3808314 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 3808314 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.SyncStrategy http://127.0.0.1:37132/t_i/g/control_collection_shard1_replica_n1/ has no replicas
[junit4] 2> 3808314 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.ShardLeaderElectionContextBase Creating leader registration node /collections/control_collection/leaders/shard1/leader after winning as /collections/control_collection/leader_elect/shard1/election/72957497593561092-core_node2-n_0000000000
[junit4] 2> 3808316 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:37132/t_i/g/control_collection_shard1_replica_n1/ shard1
[junit4] 2> 3808419 INFO (zkCallback-22601-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/control_collection/state.json] for collection [control_collection] has occurred - updating... (live nodes size: [1])
[junit4] 2> 3808419 INFO (zkCallback-22601-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/control_collection/state.json] for collection [control_collection] has occurred - updating... (live nodes size: [1])
[junit4] 2> 3808420 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg c:control_collection s:shard1 r:core_node2 x:control_collection_shard1_replica_n1 ] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 3808422 INFO (qtp1496899731-96046) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node2&collection.configName=conf1&newCollection=true&name=control_collection_shard1_replica_n1&action=CREATE&numShards=1&collection=control_collection&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=563
[junit4] 2> 3808424 INFO (qtp1496899731-96045) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 45 seconds. Check all shard replicas
[junit4] 2> 3808524 INFO (zkCallback-22601-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/control_collection/state.json] for collection [control_collection] has occurred - updating... (live nodes size: [1])
[junit4] 2> 3808524 INFO (zkCallback-22601-thread-3) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/control_collection/state.json] for collection [control_collection] has occurred - updating... (live nodes size: [1])
[junit4] 2> 3808525 INFO (qtp1496899731-96045) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={collection.configName=conf1&name=control_collection&nrtReplicas=1&action=CREATE&numShards=1&createNodeSet=127.0.0.1:37132_t_i%252Fg&wt=javabin&version=2} status=0 QTime=1006
[junit4] 2> 3808525 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.AbstractFullDistribZkTestBase Waiting to see 1 active replicas in collection: control_collection
[junit4] 2> 3808531 INFO (zkCallback-22601-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/control_collection/state.json] for collection [control_collection] has occurred - updating... (live nodes size: [1])
[junit4] 2> 3808636 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3808637 INFO (zkConnectionManagerCallback-22630-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3808637 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3808639 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 3808640 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:38535/solr ready
[junit4] 2> 3808640 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ChaosMonkey monkey: init - expire sessions:false cause connection loss:false
[junit4] 2> 3808640 INFO (SocketProxy-Acceptor-37132) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=42422,localport=37132], receiveBufferSize: 531000
[junit4] 2> 3808641 INFO (SocketProxy-Acceptor-37132) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=42660,localport=39896], receiveBufferSize=530904
[junit4] 2> 3808641 INFO (qtp1496899731-96044) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params collection.configName=conf1&name=collection1&nrtReplicas=1&action=CREATE&numShards=2&createNodeSet=&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 3808665 INFO (OverseerThreadFactory-22609-thread-2-processing-n:127.0.0.1:37132_t_i%2Fg) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.a.c.CreateCollectionCmd Create collection collection1
[junit4] 2> 3808665 INFO (OverseerCollectionConfigSetProcessor-72957497593561092-127.0.0.1:37132_t_i%2Fg-n_0000000000) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000000 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 3808870 WARN (OverseerThreadFactory-22609-thread-2-processing-n:127.0.0.1:37132_t_i%2Fg) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.a.c.CreateCollectionCmd It is unusual to create a collection (collection1) without cores.
[junit4] 2> 3808872 INFO (qtp1496899731-96044) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 45 seconds. Check all shard replicas
[junit4] 2> 3808873 INFO (qtp1496899731-96044) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={collection.configName=conf1&name=collection1&nrtReplicas=1&action=CREATE&numShards=2&createNodeSet=&wt=javabin&version=2} status=0 QTime=232
[junit4] 2> 3808874 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.SolrCloudTestCase active slice count: 2 expected: 2
[junit4] 2> 3808874 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.SolrCloudTestCase active replica count: 0 expected replica count: 0
[junit4] 2> 3808875 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.SolrCloudTestCase active slice count: 2 expected: 2
[junit4] 2> 3808875 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.SolrCloudTestCase active replica count: 0 expected replica count: 0
[junit4] 2> 3808875 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.SolrCloudTestCase active slice count: 2 expected: 2
[junit4] 2> 3808875 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.SolrCloudTestCase active replica count: 0 expected replica count: 0
[junit4] 2> 3808875 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.AbstractFullDistribZkTestBase Creating jetty instances pullReplicaCount=0 numOtherReplicas=3
[junit4] 2> 3809241 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 1 in directory /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/shard-1-001 of type TLOG in shard 2
[junit4] 2> 3809243 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Start Jetty (configured port=0, binding port=0)
[junit4] 2> 3809243 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Trying to start Jetty on port 0 try number 2 ...
[junit4] 2> 3809243 INFO (closeThreadPool-22631-thread-1) [ ] o.e.j.s.Server jetty-9.4.27.v20200227; built: 2020-02-27T18:37:21.340Z; git: a304fd9f351f337e7c0e2a7c28878dd536149c6c; jvm 11.0.4+10-LTS
[junit4] 2> 3809244 INFO (closeThreadPool-22631-thread-1) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 3809244 INFO (closeThreadPool-22631-thread-1) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 3809244 INFO (closeThreadPool-22631-thread-1) [ ] o.e.j.s.session node0 Scavenging every 660000ms
[junit4] 2> 3809244 INFO (closeThreadPool-22631-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@352762f{/t_i/g,null,AVAILABLE}
[junit4] 2> 3809245 INFO (closeThreadPool-22631-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@21a3da6{HTTP/1.1, (http/1.1, h2c)}{127.0.0.1:41363}
[junit4] 2> 3809245 INFO (closeThreadPool-22631-thread-1) [ ] o.e.j.s.Server Started @3809284ms
[junit4] 2> 3809245 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/t_i/g, solrconfig=solrconfig.xml, solr.data.dir=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/tempDir-001/jetty1, hostPort=33742, coreRootDirectory=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/shard-1-001/cores, replicaType=TLOG}
[junit4] 2> 3809245 ERROR (closeThreadPool-22631-thread-1) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3809245 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
[junit4] 2> 3809245 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 9.0.0
[junit4] 2> 3809245 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3809245 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr
[junit4] 2> 3809245 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2020-06-12T09:58:28.591475Z
[junit4] 2> 3809246 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3809247 INFO (zkConnectionManagerCallback-22633-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3809247 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3809349 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 3809349 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/shard-1-001/solr.xml
[junit4] 2> 3809354 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e, but no JMX reporters were configured - adding default JMX reporter.
[junit4] 2> 3809827 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 2 in directory /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/shard-2-001 of type TLOG in shard 1
[junit4] 2> 3809828 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Start Jetty (configured port=0, binding port=0)
[junit4] 2> 3809828 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Trying to start Jetty on port 0 try number 2 ...
[junit4] 2> 3809828 INFO (closeThreadPool-22631-thread-2) [ ] o.e.j.s.Server jetty-9.4.27.v20200227; built: 2020-02-27T18:37:21.340Z; git: a304fd9f351f337e7c0e2a7c28878dd536149c6c; jvm 11.0.4+10-LTS
[junit4] 2> 3809829 INFO (closeThreadPool-22631-thread-2) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 3809829 INFO (closeThreadPool-22631-thread-2) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 3809829 INFO (closeThreadPool-22631-thread-2) [ ] o.e.j.s.session node0 Scavenging every 600000ms
[junit4] 2> 3809829 INFO (closeThreadPool-22631-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@74ef70ff{/t_i/g,null,AVAILABLE}
[junit4] 2> 3809830 INFO (closeThreadPool-22631-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@700c6c51{HTTP/1.1, (http/1.1, h2c)}{127.0.0.1:35258}
[junit4] 2> 3809830 INFO (closeThreadPool-22631-thread-2) [ ] o.e.j.s.Server Started @3809869ms
[junit4] 2> 3809830 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/t_i/g, solrconfig=solrconfig.xml, solr.data.dir=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/tempDir-001/jetty2, hostPort=43870, coreRootDirectory=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/shard-2-001/cores, replicaType=TLOG}
[junit4] 2> 3809830 ERROR (closeThreadPool-22631-thread-2) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3809830 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
[junit4] 2> 3809830 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 9.0.0
[junit4] 2> 3809830 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3809830 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr
[junit4] 2> 3809830 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2020-06-12T09:58:29.176621Z
[junit4] 2> 3809831 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3809832 INFO (zkConnectionManagerCallback-22638-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3809832 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3809934 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 3809934 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/shard-2-001/solr.xml
[junit4] 2> 3809939 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e, but no JMX reporters were configured - adding default JMX reporter.
[junit4] 2> 3810668 INFO (OverseerCollectionConfigSetProcessor-72957497593561092-127.0.0.1:37132_t_i%2Fg-n_0000000000) [n:127.0.0.1:37132_t_i%2Fg ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000002 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 3812262 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.h.c.HttpShardHandlerFactory Host whitelist initialized: WhitelistHostChecker [whitelistHosts=null, whitelistHostCheckingEnabled=false]
[junit4] 2> 3812263 WARN (closeThreadPool-22631-thread-2) [ ] o.e.j.u.s.S.config Trusting all certificates configured for Client@73e63b2[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3812263 WARN (closeThreadPool-22631-thread-2) [ ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for Client@73e63b2[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3812335 WARN (closeThreadPool-22631-thread-2) [ ] o.e.j.u.s.S.config Trusting all certificates configured for Client@24fdced8[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3812335 WARN (closeThreadPool-22631-thread-2) [ ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for Client@24fdced8[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3812337 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:38535/solr
[junit4] 2> 3812387 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3812411 INFO (zkConnectionManagerCallback-22649-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3812411 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3812542 INFO (closeThreadPool-22631-thread-2) [n:127.0.0.1:43870_t_i%2Fg ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3812543 INFO (zkConnectionManagerCallback-22651-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3812543 INFO (closeThreadPool-22631-thread-2) [n:127.0.0.1:43870_t_i%2Fg ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3812578 INFO (closeThreadPool-22631-thread-2) [n:127.0.0.1:43870_t_i%2Fg ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 3812582 INFO (closeThreadPool-22631-thread-2) [n:127.0.0.1:43870_t_i%2Fg ] o.a.s.c.ZkController Publish node=127.0.0.1:43870_t_i%2Fg as DOWN
[junit4] 2> 3812583 INFO (closeThreadPool-22631-thread-2) [n:127.0.0.1:43870_t_i%2Fg ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 3812583 INFO (closeThreadPool-22631-thread-2) [n:127.0.0.1:43870_t_i%2Fg ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43870_t_i%2Fg
[junit4] 2> 3812585 INFO (zkCallback-22601-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 3812609 INFO (closeThreadPool-22631-thread-2) [n:127.0.0.1:43870_t_i%2Fg ] o.a.s.p.PackageLoader /packages.json updated to version -1
[junit4] 2> 3812610 WARN (closeThreadPool-22631-thread-2) [n:127.0.0.1:43870_t_i%2Fg ] o.a.s.c.CoreContainer Not all security plugins configured! authentication=disabled authorization=disabled. Solr is only as secure as you make it. Consider configuring authentication/authorization before exposing Solr to users internal or external. See https://s.apache.org/solrsecurity for more info
[junit4] 2> 3812619 INFO (zkCallback-22650-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 3812619 INFO (zkCallback-22629-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 3812704 INFO (closeThreadPool-22631-thread-2) [n:127.0.0.1:43870_t_i%2Fg ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 3812741 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 3 in directory /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/shard-3-001 of type TLOG in shard 2
[junit4] 2> 3812742 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.c.s.e.JettySolrRunner Start Jetty (configured port=0, binding port=0)
[junit4] 2> 3812742 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.c.s.e.JettySolrRunner Trying to start Jetty on port 0 try number 2 ...
[junit4] 2> 3812742 INFO (closeThreadPool-22631-thread-3) [ ] o.e.j.s.Server jetty-9.4.27.v20200227; built: 2020-02-27T18:37:21.340Z; git: a304fd9f351f337e7c0e2a7c28878dd536149c6c; jvm 11.0.4+10-LTS
[junit4] 2> 3812743 INFO (closeThreadPool-22631-thread-3) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 3812743 INFO (closeThreadPool-22631-thread-3) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 3812743 INFO (closeThreadPool-22631-thread-3) [ ] o.e.j.s.session node0 Scavenging every 600000ms
[junit4] 2> 3812744 INFO (closeThreadPool-22631-thread-3) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@3c68b685{/t_i/g,null,AVAILABLE}
[junit4] 2> 3812744 INFO (closeThreadPool-22631-thread-3) [ ] o.e.j.s.AbstractConnector Started ServerConnector@5432c0ee{HTTP/1.1, (http/1.1, h2c)}{127.0.0.1:39455}
[junit4] 2> 3812744 INFO (closeThreadPool-22631-thread-3) [ ] o.e.j.s.Server Started @3812784ms
[junit4] 2> 3812744 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/t_i/g, solrconfig=solrconfig.xml, solr.data.dir=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/tempDir-001/jetty3, hostPort=34217, coreRootDirectory=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/shard-3-001/cores, replicaType=TLOG}
[junit4] 2> 3812744 ERROR (closeThreadPool-22631-thread-3) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 3812744 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
[junit4] 2> 3812744 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 9.0.0
[junit4] 2> 3812744 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 3812744 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr
[junit4] 2> 3812744 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2020-06-12T09:58:32.090956Z
[junit4] 2> 3812778 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3812779 INFO (zkConnectionManagerCallback-22660-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3812779 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3812839 INFO (closeThreadPool-22631-thread-2) [n:127.0.0.1:43870_t_i%2Fg ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e
[junit4] 2> 3812873 INFO (closeThreadPool-22631-thread-2) [n:127.0.0.1:43870_t_i%2Fg ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e
[junit4] 2> 3812873 INFO (closeThreadPool-22631-thread-2) [n:127.0.0.1:43870_t_i%2Fg ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e
[junit4] 2> 3812881 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 3812881 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/shard-3-001/solr.xml
[junit4] 2> 3812886 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e, but no JMX reporters were configured - adding default JMX reporter.
[junit4] 2> 3812896 INFO (closeThreadPool-22631-thread-2) [n:127.0.0.1:43870_t_i%2Fg ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/shard-2-001/cores
[junit4] 2> 3812952 INFO (closeThreadPool-22631-thread-2) [ ] o.a.s.c.AbstractFullDistribZkTestBase waitForLiveNode: 127.0.0.1:43870_t_i%2Fg
[junit4] 2> 3814047 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.h.c.HttpShardHandlerFactory Host whitelist initialized: WhitelistHostChecker [whitelistHosts=null, whitelistHostCheckingEnabled=false]
[junit4] 2> 3814048 WARN (closeThreadPool-22631-thread-3) [ ] o.e.j.u.s.S.config Trusting all certificates configured for Client@208aa850[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3814048 WARN (closeThreadPool-22631-thread-3) [ ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for Client@208aa850[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3814059 WARN (closeThreadPool-22631-thread-3) [ ] o.e.j.u.s.S.config Trusting all certificates configured for Client@62576a28[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3814060 WARN (closeThreadPool-22631-thread-3) [ ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for Client@62576a28[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3814061 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:38535/solr
[junit4] 2> 3814062 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3814071 INFO (zkConnectionManagerCallback-22672-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3814074 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3814205 INFO (closeThreadPool-22631-thread-3) [n:127.0.0.1:34217_t_i%2Fg ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3814221 INFO (zkConnectionManagerCallback-22674-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3814222 INFO (closeThreadPool-22631-thread-3) [n:127.0.0.1:34217_t_i%2Fg ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3814228 INFO (closeThreadPool-22631-thread-3) [n:127.0.0.1:34217_t_i%2Fg ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 3814232 INFO (closeThreadPool-22631-thread-3) [n:127.0.0.1:34217_t_i%2Fg ] o.a.s.c.ZkController Publish node=127.0.0.1:34217_t_i%2Fg as DOWN
[junit4] 2> 3814233 INFO (closeThreadPool-22631-thread-3) [n:127.0.0.1:34217_t_i%2Fg ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 3814233 INFO (closeThreadPool-22631-thread-3) [n:127.0.0.1:34217_t_i%2Fg ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34217_t_i%2Fg
[junit4] 2> 3814234 INFO (zkCallback-22629-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 3814234 INFO (zkCallback-22601-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 3814234 INFO (zkCallback-22650-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 3814235 INFO (zkCallback-22673-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 3814237 INFO (closeThreadPool-22631-thread-3) [n:127.0.0.1:34217_t_i%2Fg ] o.a.s.p.PackageLoader /packages.json updated to version -1
[junit4] 2> 3814237 WARN (closeThreadPool-22631-thread-3) [n:127.0.0.1:34217_t_i%2Fg ] o.a.s.c.CoreContainer Not all security plugins configured! authentication=disabled authorization=disabled. Solr is only as secure as you make it. Consider configuring authentication/authorization before exposing Solr to users internal or external. See https://s.apache.org/solrsecurity for more info
[junit4] 2> 3814360 INFO (closeThreadPool-22631-thread-3) [n:127.0.0.1:34217_t_i%2Fg ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 3814491 INFO (closeThreadPool-22631-thread-3) [n:127.0.0.1:34217_t_i%2Fg ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e
[junit4] 2> 3814544 INFO (closeThreadPool-22631-thread-3) [n:127.0.0.1:34217_t_i%2Fg ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e
[junit4] 2> 3814544 INFO (closeThreadPool-22631-thread-3) [n:127.0.0.1:34217_t_i%2Fg ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e
[junit4] 2> 3814546 INFO (closeThreadPool-22631-thread-3) [n:127.0.0.1:34217_t_i%2Fg ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/shard-3-001/cores
[junit4] 2> 3814570 INFO (closeThreadPool-22631-thread-3) [ ] o.a.s.c.AbstractFullDistribZkTestBase waitForLiveNode: 127.0.0.1:34217_t_i%2Fg
[junit4] 2> 3816512 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.h.c.HttpShardHandlerFactory Host whitelist initialized: WhitelistHostChecker [whitelistHosts=null, whitelistHostCheckingEnabled=false]
[junit4] 2> 3816513 WARN (closeThreadPool-22631-thread-1) [ ] o.e.j.u.s.S.config Trusting all certificates configured for Client@36bb0089[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3816513 WARN (closeThreadPool-22631-thread-1) [ ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for Client@36bb0089[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3816517 WARN (closeThreadPool-22631-thread-1) [ ] o.e.j.u.s.S.config Trusting all certificates configured for Client@2cf8c449[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3816517 WARN (closeThreadPool-22631-thread-1) [ ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for Client@2cf8c449[provider=null,keyStore=null,trustStore=null]
[junit4] 2> 3816518 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:38535/solr
[junit4] 2> 3816519 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3816520 INFO (zkConnectionManagerCallback-22690-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3816520 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3816623 INFO (closeThreadPool-22631-thread-1) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 3816624 INFO (zkConnectionManagerCallback-22692-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 3816624 INFO (closeThreadPool-22631-thread-1) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 3816631 INFO (closeThreadPool-22631-thread-1) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3)
[junit4] 2> 3816635 INFO (closeThreadPool-22631-thread-1) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.c.ZkController Publish node=127.0.0.1:33742_t_i%2Fg as DOWN
[junit4] 2> 3816636 INFO (closeThreadPool-22631-thread-1) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 3816636 INFO (closeThreadPool-22631-thread-1) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33742_t_i%2Fg
[junit4] 2> 3816638 INFO (zkCallback-22650-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3816638 INFO (zkCallback-22601-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3816638 INFO (zkCallback-22629-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3816638 INFO (zkCallback-22673-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3816638 INFO (zkCallback-22691-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 3816640 INFO (closeThreadPool-22631-thread-1) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.p.PackageLoader /packages.json updated to version -1
[junit4] 2> 3816641 WARN (closeThreadPool-22631-thread-1) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.c.CoreContainer Not all security plugins configured! authentication=disabled authorization=disabled. Solr is only as secure as you make it. Consider configuring authentication/authorization before exposing Solr to users internal or external. See https://s.apache.org/solrsecurity for more info
[junit4] 2> 3816665 INFO (closeThreadPool-22631-thread-1) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 3816697 INFO (closeThreadPool-22631-thread-1) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e
[junit4] 2> 3816712 INFO (closeThreadPool-22631-thread-1) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e
[junit4] 2> 3816712 INFO (closeThreadPool-22631-thread-1) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@322b5b6e
[junit4] 2> 3816714 INFO (closeThreadPool-22631-thread-1) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001/shard-1-001/cores
[junit4] 2> 3816744 INFO (closeThreadPool-22631-thread-1) [ ] o.a.s.c.AbstractFullDistribZkTestBase waitForLiveNode: 127.0.0.1:33742_t_i%2Fg
[junit4] 2> 3816746 INFO (SocketProxy-Acceptor-33742) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=41970,localport=33742], receiveBufferSize: 531000
[junit4] 2> 3816747 INFO (SocketProxy-Acceptor-33742) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=41363,localport=55202], receiveBufferSize=530904
[junit4] 2> 3816747 INFO (SocketProxy-Acceptor-33742) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=41974,localport=33742], receiveBufferSize: 531000
[junit4] 2> 3816747 INFO (SocketProxy-Acceptor-33742) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=41363,localport=55208], receiveBufferSize=530904
[junit4] 2> 3816747 INFO (SocketProxy-Acceptor-33742) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=41976,localport=33742], receiveBufferSize: 531000
[junit4] 2> 3816748 INFO (qtp215863885-96108) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :addreplica with params node=127.0.0.1:43870_t_i%252Fg&action=ADDREPLICA&collection=collection1&shard=shard1&type=TLOG&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 3816748 INFO (qtp215863885-96107) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :addreplica with params node=127.0.0.1:34217_t_i%252Fg&action=ADDREPLICA&collection=collection1&shard=shard2&type=TLOG&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 3816748 INFO (SocketProxy-Acceptor-33742) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=41363,localport=55210], receiveBufferSize=530904
[junit4] 2> 3816748 INFO (qtp215863885-96109) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :addreplica with params node=127.0.0.1:33742_t_i%252Fg&action=ADDREPLICA&collection=collection1&shard=shard2&type=TLOG&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 3816767 INFO (SocketProxy-Acceptor-33742) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=41982,localport=33742], receiveBufferSize: 531000
[junit4] 2> 3816768 INFO (SocketProxy-Acceptor-33742) [ ] o.a.s.c.s.c.SocketProxy proxy connection Socket[addr=/127.0.0.1,port=41363,localport=55214], receiveBufferSize=530904
[junit4] 2> 3816777 INFO (qtp215863885-96208) [n:127.0.0.1:33742_t_i%2Fg ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={prefix=CONTAINER.fs.usableSpace,CONTAINER.fs.totalSpace,CONTAINER.cores&wt=javabin&version=2&group=solr.node} status=0 QTime=9
[junit4] 2> 3816778 INFO (SocketProxy-Acceptor-34217) [ ] o.a.s.c.s.c.SocketProxy accepted Socket[addr=/127.0.0.1,port=35940,localport=34217], receiveBufferSize: 531000
[junit4] 2> 3816779 INFO (SocketProxy-Acceptor-34217) [ ] o.a.s.
[...truncated too long message...]
nprops.json
[junit4] 2> 3 /solr/collections/forceleader_lower_terms_collection/collectionprops.json
[junit4] 2> 2 /solr/collections/collection1/terms/shard1
[junit4] 2> 2 /solr/collections/control_collection/terms/shard1
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 68 /solr/collections/collection1/state.json
[junit4] 2> 68 /solr/collections/forceleader_lower_terms_collection/state.json
[junit4] 2> 13 /solr/collections/control_collection/state.json
[junit4] 2> 2 /solr/autoscaling.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 75 /solr/overseer/queue
[junit4] 2> 26 /solr/live_nodes
[junit4] 2> 23 /solr/overseer/collection-queue-work
[junit4] 2> 16 /solr/collections
[junit4] 2> 2 /solr/autoscaling/events/.scheduled_maintenance
[junit4] 2> 2 /solr/autoscaling/events/.auto_add_replicas
[junit4] 2> 2 /solr/overseer/queue-work
[junit4] 2>
[junit4] 2> 3907659 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer waitForServerDown: 127.0.0.1:38535
[junit4] 2> 3907659 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer parse host and port list: 127.0.0.1:38535
[junit4] 2> 3907659 INFO (TEST-ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms-seed#[77E764DEE5FC91E1]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1 38535
[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=ForceLeaderWithTlogReplicasTest -Dtests.method=testReplicasInLowerTerms -Dtests.seed=77E764DEE5FC91E1 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=nl-AW -Dtests.timezone=Asia/Macau -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] ERROR 104s J0 | ForceLeaderWithTlogReplicasTest.testReplicasInLowerTerms <<<
[junit4] > Throwable #1: java.net.BindException: Address already in use
[junit4] > at __randomizedtesting.SeedInfo.seed([77E764DEE5FC91E1:F9D3449D255B3195]:0)
[junit4] > at java.base/sun.nio.ch.Net.bind0(Native Method)
[junit4] > at java.base/sun.nio.ch.Net.bind(Net.java:461)
[junit4] > at java.base/sun.nio.ch.Net.bind(Net.java:453)
[junit4] > at java.base/sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:227)
[junit4] > at java.base/sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:80)
[junit4] > at org.eclipse.jetty.server.ServerConnector.openAcceptChannel(ServerConnector.java:342)
[junit4] > at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:307)
[junit4] > at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80)
[junit4] > at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:231)
[junit4] > at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:72)
[junit4] > at org.eclipse.jetty.server.Server.doStart(Server.java:385)
[junit4] > at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:72)
[junit4] > at org.apache.solr.client.solrj.embedded.JettySolrRunner.retryOnPortBindFailure(JettySolrRunner.java:566)
[junit4] > at org.apache.solr.client.solrj.embedded.JettySolrRunner.start(JettySolrRunner.java:504)
[junit4] > at org.apache.solr.client.solrj.embedded.JettySolrRunner.start(JettySolrRunner.java:472)
[junit4] > at org.apache.solr.cloud.ForceLeaderTest.bringBackOldLeaderAndSendDoc(ForceLeaderTest.java:250)
[junit4] > at org.apache.solr.cloud.ForceLeaderTest.testReplicasInLowerTerms(ForceLeaderTest.java:173)
[junit4] > at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4] > at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[junit4] > at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4] > at java.base/java.lang.reflect.Method.invoke(Method.java:566)
[junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsFixedStatement.callStatement(BaseDistributedSearchTestCase.java:1090)
[junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:1061)
[junit4] > at java.base/java.lang.Thread.run(Thread.java:834)
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.ForceLeaderWithTlogReplicasTest_77E764DEE5FC91E1-001
[junit4] 2> Jun 12, 2020 10:00:07 AM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 1 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=CheapBastard, sim=Asserting(org.apache.lucene.search.similarities.AssertingSimilarity@3ecfe542), locale=nl-AW, timezone=Asia/Macau
[junit4] 2> NOTE: Linux 4.4.0-170-generic amd64/Oracle Corporation 11.0.4 (64-bit)/cpus=8,threads=1,free=123270904,total=536870912
[junit4] 2> NOTE: All tests run in this JVM: [ForceLeaderTest, CurrencyFieldTypeTest, TestPartialUpdateDeduplication, LukeRequestHandlerTest, TestRemoteStreaming, TestIndexingPerformance, MultiDestinationAuditLoggerTest, SimplePostToolTest, AuditLoggerPluginTest, DistributedUpdateProcessorTest, TestNestedDocsSort, TestMissingGroups, SuggesterFSTTest, UpdateRequestProcessorFactoryTest, TestImplicitCoreProperties, TestSimExtremeIndexing, ExecutePlanActionTest, DeleteInactiveReplicaTest, RoutingToNodesWithPropertiesTest, TestFuzzyAnalyzedSuggestions, TestCorePropertiesReload, IndexSizeTriggerMixedBoundsTest, TestSubQueryTransformerCrossCore, TestValueSourceCache, TestCollectionsAPIViaSolrCloudCluster, TestConfigOverlay, TermVectorComponentDistributedTest, TestManagedSynonymGraphFilterFactory, ConnectionManagerTest, HdfsUnloadDistributedZkTest, MigrateRouteKeyTest, JWTAuthPluginTest, TestBadConfig, TestDistribDocBasedVersion, SuggesterWFSTTest, NestedAtomicUpdateTest, DirectoryFactoryTest, InfixSuggestersTest, OutOfBoxZkACLAndCredentialsProvidersTest, TestStandardQParsers, VersionInfoTest, TestDefaultStatsCache, ShardRoutingCustomTest, HighlighterMaxOffsetTest, CollectionsAPIDistributedZkTest, TestApiFramework, LeaderElectionContextKeyTest, TestRTGBase, SynonymTokenizerTest, HdfsChaosMonkeyNothingIsSafeTest, BooleanFieldTest, TestRetrieveFieldsOptimizer, TestNRTOpen, TestAddFieldRealTimeGet, AssignBackwardCompatibilityTest, TestReplicationHandler, AdminHandlersProxyTest, SolrXmlInZkTest, MoveReplicaHDFSTest, TestIBSimilarityFactory, TlogReplayBufferedWhileIndexingTest, TestDistribPackageStore, TestReRankQParserPlugin, TestSimNodeAddedTrigger, BlockCacheTest, TestEmbeddedSolrServerSchemaAPI, SolrPluginUtilsTest, ReplicationFactorTest, TestExclusionRuleCollectionAccess, TestSizeLimitedDistributedMap, JSONWriterTest, TestExceedMaxTermLength, TestPushWriter, TestCopyFieldCollectionResource, TestSmileRequest, SpellCheckCollatorTest, TestRandomDVFaceting, SearchRateTriggerTest, TestCloudPhrasesIdentificationComponent, SolrShardReporterTest, ChaosMonkeyNothingIsSafeTest, TestJmxIntegration, RegexBoostProcessorTest, TestCloudManagedSchema, TestUtilizeNode, TestNumericTerms64, CdcrBootstrapTest, TestExtendedDismaxParser, RequestHandlersTest, DistributedQueryComponentOptimizationTest, JavabinLoaderTest, TestPrepRecovery, XCJFQueryTest, LeaderVoteWaitTimeoutTest, AutoAddReplicasPlanActionTest, RankQueryTest, TestChildDocTransformerHierarchy, SpellingQueryConverterTest, TestConfigSetsAPIZkFailure, StatsComponentTest, TransactionLogTest, BasicAuthStandaloneTest, TestManagedSchemaAPI, SolrCoreCheckLockOnStartupTest, TestClusterProperties, DirectSolrSpellCheckerTest, TestMaxTokenLenTokenizer, TestReqParamsAPI, CircularListTest, CoreMergeIndexesAdminHandlerTest, TestLegacyNumericUtils, AtomicUpdateRemovalJavabinTest, TestSolrConfigHandler, TestSchemalessBufferedUpdates, CheckHdfsIndexTest, SolrMetricsIntegrationTest, TestPostingsSolrHighlighter, TestSnapshotCloudManager, AnalysisAfterCoreReloadTest, SolrJmxReporterTest, TestSolrIndexConfig, TestFieldCollectionResource, TestComplexPhraseLeadingWildcard, CloneFieldUpdateProcessorFactoryTest, URLClassifyProcessorTest, TestCSVResponseWriter, CoreAdminHandlerTest, TestNumericRangeQuery32, ClusterStateUpdateTest, MergeStrategyTest, LeaderFailoverAfterPartitionTest, TestRecoveryHdfs, DirectSolrConnectionTest, CdcrRequestHandlerTest, CustomTermsComponentTest, TestTlogReplica, DistributedSuggestComponentTest, TestClusterStateMutator, RecoveryAfterSoftCommitTest, TestCloudJSONFacetJoinDomain, DistributedFacetPivotLongTailTest, BitVectorTest, ActionThrottleTest, RegexBytesRefFilterTest, ZkStateWriterTest, MetricsHistoryHandlerTest, NodeAddedTriggerTest, HdfsRecoverLeaseTest, TestStressThreadBackup, EchoParamsTest, MinimalSchemaTest, OutputWriterTest, SampleTest, TestCrossCoreJoin, TestDistributedMissingSort, TestDistributedSearch, BasicDistributedZkTest, ChaosMonkeySafeLeaderWithPullReplicasTest, CloudExitableDirectoryReaderTest, DeleteLastCustomShardedReplicaTest, DeleteNodeTest, DeleteReplicaTest, DistribCursorPagingTest, DistribJoinFromCollectionTest, DistributedQueueTest, ForceLeaderWithTlogReplicasTest]
[junit4] Completed [390/910 (1!)] on J0 in 104.81s, 2 tests, 1 error, 1 skipped <<< FAILURES!
[...truncated 53757 lines...]
[JENKINS] Lucene-Solr-NightlyTests-master - Build # 2223 - Failure
Posted by Apache Jenkins Server <je...@builds.apache.org>.
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-master/2223/
1 tests failed.
FAILED: org.apache.lucene.search.TestSearcherManager.testConcurrentIndexCloseSearchAndRefresh
Error Message:
Java heap space
Stack Trace:
java.lang.OutOfMemoryError: Java heap space
Build Log:
[...truncated 2273 lines...]
[junit4] Suite: org.apache.lucene.search.TestSearcherManager
[junit4] 2> nzu 14, 2020 9:39:02 A.G com.carrotsearch.randomizedtesting.RandomizedRunner$QueueUncaughtExceptionsHandler uncaughtException
[junit4] 2> WARNING: Uncaught exception in thread: Thread[Thread-22745,5,TGRP-TestSearcherManager]
[junit4] 2> java.lang.OutOfMemoryError: Java heap space
[junit4] 2>
[junit4] 2> nzu 14, 2020 9:39:02 A.G com.carrotsearch.randomizedtesting.RandomizedRunner$QueueUncaughtExceptionsHandler uncaughtException
[junit4] 2> WARNING: Uncaught exception in thread: Thread[Thread-22742,5,TGRP-TestSearcherManager]
[junit4] 2> java.lang.OutOfMemoryError: Java heap space
[junit4] 2> at __randomizedtesting.SeedInfo.seed([25A35436FFEEBBCE]:0)
[junit4] 2> at org.apache.lucene.util.BytesRefBuilder.<init>(BytesRefBuilder.java:30)
[junit4] 2> at org.apache.lucene.codecs.blockterms.BlockTermsWriter$TermEntry.<init>(BlockTermsWriter.java:192)
[junit4] 2> at org.apache.lucene.codecs.blockterms.BlockTermsWriter$TermsWriter.write(BlockTermsWriter.java:259)
[junit4] 2> at org.apache.lucene.codecs.blockterms.BlockTermsWriter.write(BlockTermsWriter.java:146)
[junit4] 2> at org.apache.lucene.codecs.FieldsConsumer.merge(FieldsConsumer.java:105)
[junit4] 2> at org.apache.lucene.codecs.perfield.PerFieldPostingsFormat$FieldsWriter.merge(PerFieldPostingsFormat.java:197)
[junit4] 2> at org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:244)
[junit4] 2> at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:139)
[junit4] 2> at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4441)
[junit4] 2> at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:4035)
[junit4] 2> at org.apache.lucene.index.IndexWriter$IndexWriterMergeSource.merge(IndexWriter.java:5595)
[junit4] 2> at org.apache.lucene.index.SerialMergeScheduler.merge(SerialMergeScheduler.java:40)
[junit4] 2> at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:2133)
[junit4] 2> at org.apache.lucene.index.IndexWriter.processEvents(IndexWriter.java:5112)
[junit4] 2> at org.apache.lucene.index.IndexWriter.maybeProcessEvents(IndexWriter.java:5102)
[junit4] 2> at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1332)
[junit4] 2> at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1618)
[junit4] 2> at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1261)
[junit4] 2> at org.apache.lucene.search.TestSearcherManager$8.run(TestSearcherManager.java:577)
[junit4] 2>
[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=TestSearcherManager -Dtests.method=testConcurrentIndexCloseSearchAndRefresh -Dtests.seed=25A35436FFEEBBCE -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=agq -Dtests.timezone=Asia/Baghdad -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] ERROR 4706s J0 | TestSearcherManager.testConcurrentIndexCloseSearchAndRefresh <<<
[junit4] > Throwable #1: java.lang.OutOfMemoryError: Java heap spaceThrowable #2: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=23327, name=Thread-22745, state=RUNNABLE, group=TGRP-TestSearcherManager]
[junit4] > Caused by: java.lang.OutOfMemoryError: Java heap spaceThrowable #3: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=23324, name=Thread-22742, state=RUNNABLE, group=TGRP-TestSearcherManager]
[junit4] > Caused by: java.lang.OutOfMemoryError: Java heap space
[junit4] > at __randomizedtesting.SeedInfo.seed([25A35436FFEEBBCE]:0)
[junit4] > at org.apache.lucene.util.BytesRefBuilder.<init>(BytesRefBuilder.java:30)
[junit4] > at org.apache.lucene.codecs.blockterms.BlockTermsWriter$TermEntry.<init>(BlockTermsWriter.java:192)
[junit4] > at org.apache.lucene.codecs.blockterms.BlockTermsWriter$TermsWriter.write(BlockTermsWriter.java:259)
[junit4] > at org.apache.lucene.codecs.blockterms.BlockTermsWriter.write(BlockTermsWriter.java:146)
[junit4] > at org.apache.lucene.codecs.FieldsConsumer.merge(FieldsConsumer.java:105)
[junit4] > at org.apache.lucene.codecs.perfield.PerFieldPostingsFormat$FieldsWriter.merge(PerFieldPostingsFormat.java:197)
[junit4] > at org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:244)
[junit4] > at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:139)
[junit4] > at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4441)
[junit4] > at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:4035)
[junit4] > at org.apache.lucene.index.IndexWriter$IndexWriterMergeSource.merge(IndexWriter.java:5595)
[junit4] > at org.apache.lucene.index.SerialMergeScheduler.merge(SerialMergeScheduler.java:40)
[junit4] > at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:2133)
[junit4] > at org.apache.lucene.index.IndexWriter.processEvents(IndexWriter.java:5112)
[junit4] > at org.apache.lucene.index.IndexWriter.maybeProcessEvents(IndexWriter.java:5102)
[junit4] > at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1332)
[junit4] > at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1618)
[junit4] > at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1261)
[junit4] > at org.apache.lucene.search.TestSearcherManager$8.run(TestSearcherManager.java:577)
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/lucene/build/core/test/J0/temp/lucene.search.TestSearcherManager_25A35436FFEEBBCE-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene86): {date=PostingsFormat(name=LuceneFixedGap), extra35=Lucene84, extra13=Lucene84, extra36=PostingsFormat(name=MockRandom), extra14=PostingsFormat(name=MockRandom), extra8=PostingsFormat(name=LuceneFixedGap), extra33=PostingsFormat(name=LuceneFixedGap), extra11=PostingsFormat(name=LuceneFixedGap), extra9=BlockTreeOrds(blocksize=128), extra34=BlockTreeOrds(blocksize=128), extra12=BlockTreeOrds(blocksize=128), extra17=Lucene84, extra39=Lucene84, extra18=PostingsFormat(name=MockRandom), extra37=PostingsFormat(name=LuceneFixedGap), extra15=PostingsFormat(name=LuceneFixedGap), extra38=BlockTreeOrds(blocksize=128), extra16=BlockTreeOrds(blocksize=128), extra2=Lucene84, extra3=PostingsFormat(name=MockRandom), titleTokenized=BlockTreeOrds(blocksize=128), extra0=PostingsFormat(name=LuceneFixedGap), extra19=PostingsFormat(name=LuceneFixedGap), extra1=BlockTreeOrds(blocksize=128), body=PostingsFormat(name=LuceneFixedGap), title=Lucene84, extra6=Lucene84, extra7=PostingsFormat(name=MockRandom), extra4=PostingsFormat(name=LuceneFixedGap), extra5=BlockTreeOrds(blocksize=128), packID=PostingsFormat(name=LuceneFixedGap), extra31=Lucene84, extra32=PostingsFormat(name=MockRandom), extra10=PostingsFormat(name=MockRandom), extra30=BlockTreeOrds(blocksize=128), extra24=Lucene84, extra25=PostingsFormat(name=MockRandom), extra22=PostingsFormat(name=LuceneFixedGap), extra23=BlockTreeOrds(blocksize=128), extra28=Lucene84, extra29=PostingsFormat(name=MockRandom), docid=PostingsFormat(name=MockRandom), extra26=PostingsFormat(name=LuceneFixedGap), extra27=BlockTreeOrds(blocksize=128), field=PostingsFormat(name=LuceneFixedGap), extra20=Lucene84, extra21=PostingsFormat(name=MockRandom)}, docValues:{docid_intDV=DocValuesFormat(name=Asserting), titleDV=DocValuesFormat(name=Lucene80)}, maxPointsInLeafNode=1241, maxMBSortInHeap=6.037088176316164, sim=Asserting(org.apache.lucene.search.similarities.AssertingSimilarity@5e7419e), locale=agq, timezone=Asia/Baghdad
[junit4] 2> NOTE: Linux 4.15.0-54-generic amd64/Oracle Corporation 11.0.4 (64-bit)/cpus=4,threads=1,free=333220600,total=536870912
[junit4] 2> NOTE: All tests run in this JVM: [TestOperations, TestTermdocPerf, TestDocumentsWriterDeleteQueue, TestLockFactory, TestPagedBytes, TestIndexWriterUnicode, TestSpanFirstQuery, TestFieldInfos, TestDelegatingAnalyzerWrapper, TestMinShouldMatch2, TestTermRangeQuery, TestAtomicUpdate, TestMatchAllDocsQuery, TestIndexWriterConfig, TestUpgradeIndexMergePolicy, TestReadOnlyIndex, TestReusableStringReader, TestTryDelete, TestSameTokenSamePosition, TermInSetQueryTest, TestSubScorerFreqs, TestPerFieldPostingsFormat, TestPayloads, TestMergeSchedulerExternal, TestSegmentToThreadMapping, TestBufferedChecksum, TestBinaryDocValuesUpdates, TestIndexFileDeleter, TestAddIndexes, TestDocCount, TestAnalyzerWrapper, TestTopDocsCollector, TestPendingSoftDeletes, TestTopFieldCollectorEarlyTermination, TestInPlaceMergeSorter, TestMultiLevelSkipList, TestArrayUtil, TestLatLonShapeEncoding, TestLucene86PointsFormat, TestLMJelinekMercerSimilarity, LimitedFiniteStringsIteratorTest, TestCachingCollector, TestNearSpansOrdered, TestIntRange, TestLine2D, TestSpanTermQuery, TestDuelingCodecsAtNight, TestDateSort, TestTermVectors, TestScoreCachingWrappingScorer, TestIntroSorter, TestIsCurrent, TestAutomatonQueryUnicode, TestLatLonMultiLineShapeQueries, TestBooleanRewrites, TestXYRectangle, TestWildcardRandom, TestQueryRescorer, TestField, TestLucene60FieldInfoFormat, TestLongBitSet, TestSpanContainQuery, TestMultiTermQueryRewrites, TestReqExclBulkScorer, TestNGramPhraseQuery, TestXYShape, TestSegmentReader, TestFastCompressionMode, TestAllFilesDetectTruncation, TestIndexWriterFromReader, TestTermsEnum2, TestRadixSelector, TestOneMergeWrappingMergePolicy, TestDaciukMihovAutomatonBuilder, TestCharsRef, TestBytesRef, TestFeatureDoubleValues, TestGraphTokenStreamFiniteStrings, TestSimpleExplanations, TestTimSorterWorstCase, TestShardSearching, TestWordlistLoader, TestDateTools, TestDocValues, TestIndexWriterMergePolicy, TestLucene50StoredFieldsFormatHighCompression, TestNIOFSDirectory, TestElevationComparator, TestPointQueries, TestSortedNumericSortField, TestFilterDirectoryReader, TestFilterIterator, TestParallelLeafReader, TestAssertions, TestDemo, TestCharArraySet, TestCharFilter, TestCharacterUtils, TestToken, TestCharTermAttributeImpl, TestPackedTokenAttributeImpl, TestSimpleAttributeImpl, TestCodecUtil, TestHighCompressionMode, TestLucene50CompoundFormat, TestLucene50LiveDocsFormat, TestLucene50StoredFieldsFormat, TestLucene80NormsFormat, TestForUtil, TestLucene84PostingsFormat, TestPForUtil, TestBinaryDocument, TestDoubleRange, TestFeatureSort, TestLatLonLineShapeQueries, TestLatLonPoint, TestLatLonPointDistanceFeatureQuery, TestLatLonPointShapeQueries, TestLatLonPolygonShapeQueries, TestXYMultiPolygonShapeQueries, TestCircle, TestCircle2D, TestGeoEncodingUtils, TestPoint2D, TestPolygon, TestPolygon2D, TestSimpleWKTShapeParsing, TestTessellator, TestDirectoryReader, TestDirectoryReaderReopen, TestDoc, TestDocInverterPerFieldErrorInfo, TestDocsAndPositions, TestDocsWithFieldSet, TestFieldUpdatesBuffer, TestFieldsReader, TestFlex, TestFlushByRamOrCountsPolicy, TestForceMergeForever, TestFrozenBufferedUpdates, TestIndexManyDocuments, TestIndexOptions, TestIndexReaderClose, TestIndexTooManyDocs, TestIndexWriter, TestIndexWriterCommit, TestIndexWriterExceptions, TestIndexWriterOutOfFileDescriptors, TestIndexWriterReader, TestIndexWriterThreadsToSegments, TestIndexableField, TestIndexingSequenceNumbers, TestMultiDocValues, TestNRTReaderWithThreads, TestNRTThreads, TestDocIdSetIterator, TestDocValuesQueries, TestDoubleRangeFieldQueries, TestFuzzyQuery, TestIndexOrDocValuesQuery, TestIndexSearcher, TestLRUQueryCache, TestLatLonDocValuesQueries, TestLongRangeFieldQueries, TestSearcherManager]
[junit4] Completed [563/563 (1!)] on J0 in 5059.23s, 11 tests, 1 error <<< FAILURES!
[...truncated 1 lines...]
[junit4] JVM J0: stdout was not empty, see: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/lucene/build/core/test/temp/junit4-J0-20200614_045356_00316684261887993217031.sysout
[junit4] >>> JVM J0 emitted unexpected output (verbatim) ----
[junit4] java.lang.OutOfMemoryError: Java heap space
[junit4] Dumping heap to /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/heapdumps/java_pid25174.hprof ...
[junit4] Heap dump file created [874682938 bytes in 8.988 secs]
[junit4] <<< JVM J0: EOF ----
[...truncated 22526 lines...]
BUILD FAILED
/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/build.xml:653: The following error occurred while executing this line:
/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/build.xml:587: Some of the tests produced a heap dump, but did not fail. Maybe a suppressed OutOfMemoryError? Dumps created:
* java_pid25174.hprof
Total time: 352 minutes 47 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure - Any
Sending email for trigger: Failure - Any
[JENKINS] Lucene-Solr-NightlyTests-master - Build # 2222 - Still
Unstable
Posted by Apache Jenkins Server <je...@builds.apache.org>.
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-master/2222/
1 tests failed.
FAILED: org.apache.solr.cloud.autoscaling.sim.TestSimScenario.testSuggestions
Error Message:
OverseerTriggerThread never caught up to the latest znodeVersion
Stack Trace:
java.util.concurrent.TimeoutException: OverseerTriggerThread never caught up to the latest znodeVersion
at __randomizedtesting.SeedInfo.seed([D06D8A8D933578A8:76B1B3785D012F56]:0)
at org.apache.solr.util.TimeOut.waitFor(TimeOut.java:66)
at org.apache.solr.cloud.autoscaling.sim.SimScenario$LoadAutoscaling.execute(SimScenario.java:468)
at org.apache.solr.cloud.autoscaling.sim.SimScenario.run(SimScenario.java:1118)
at org.apache.solr.cloud.autoscaling.sim.TestSimScenario.testSuggestions(TestSimScenario.java:114)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1754)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:942)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:978)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:992)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:370)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:819)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:470)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:951)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:836)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:887)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:898)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:370)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.lambda$forkTimeoutingTask$0(ThreadLeakControl.java:826)
at java.base/java.lang.Thread.run(Thread.java:834)
Build Log:
[...truncated 12950 lines...]
[junit4] Suite: org.apache.solr.cloud.autoscaling.sim.TestSimScenario
[junit4] 2> 1655236 INFO (SUITE-TestSimScenario-seed#[D06D8A8D933578A8]-worker) [ ] o.a.s.SolrTestCase Setting 'solr.default.confdir' system property to test-framework derived value of '/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/server/solr/configsets/_default/conf'
[junit4] 2> 1655236 INFO (SUITE-TestSimScenario-seed#[D06D8A8D933578A8]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> 1655237 INFO (SUITE-TestSimScenario-seed#[D06D8A8D933578A8]-worker) [ ] o.a.s.SolrTestCaseJ4 Created dataDir: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.autoscaling.sim.TestSimScenario_D06D8A8D933578A8-001/data-dir-124-001
[junit4] 2> 1655238 WARN (SUITE-TestSimScenario-seed#[D06D8A8D933578A8]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=75 numCloses=75
[junit4] 2> 1655238 INFO (SUITE-TestSimScenario-seed#[D06D8A8D933578A8]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=false
[junit4] 2> 1655239 INFO (SUITE-TestSimScenario-seed#[D06D8A8D933578A8]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (true) via: @org.apache.solr.util.RandomizeSSL(reason="", value=0.0/0.0, ssl=0.0/0.0, clientAuth=0.0/0.0)
[junit4] 2> 1655241 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testIndexing
[junit4] 2> 1655251 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 1. CreateCluster numNodes=100
[junit4] 2> 1655252 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario CreateCluster numNodes=100
[junit4] 2> 1655255 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.SolrPaths solr home defaulted to 'solr/' (could not find system property or JNDI)
[junit4] 2> 1655269 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 1655269 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 1655270 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 1655270 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 1655271 DEBUG (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10000_solr
[junit4] 2> 1655272 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10000_solr]
[junit4] 2> 1655272 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 1655272 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 1655272 DEBUG (ScheduledTrigger-11898-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1 and last live nodes: 1
[junit4] 2> 1655274 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 1655281 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 2. LoadAutoscaling json={'cluster-policy':[]}
[junit4] 2> 1655282 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario LoadAutoscaling json={'cluster-policy':[]}
[junit4] 2> 1655282 DEBUG (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 1655283 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 2
[junit4] 2> 1655283 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 1655283 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 2
[junit4] 2> 1655288 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 3. RunSolrRequest path=/admin/collections&action=CREATE&autoAddReplicas=true&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=2
[junit4] 2> 1655288 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collections&action=CREATE&autoAddReplicas=true&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=2
[junit4] 2> 1655289 DEBUG (simCloudManagerPool-11897-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- simCreateCollection testCollection
[junit4] 2> 1655293 DEBUG (ScheduledTrigger-11898-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 1
[junit4] 2> 1655313 DEBUG (ScheduledTrigger-11898-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1655320 DEBUG (simCloudManagerPool-11897-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1)
[junit4] 2> 1655321 DEBUG (simCloudManagerPool-11897-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1 (currentVersion=2): {"core_node1":{
[junit4] 2> "core":"testCollection_shard1_replica_n1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10040_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}
[junit4] 2> 1655333 DEBUG (ScheduledTrigger-11898-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1655333 DEBUG (simCloudManagerPool-11897-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard2)
[junit4] 2> 1655333 DEBUG (simCloudManagerPool-11897-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard2 (currentVersion=3): {"core_node3":{
[junit4] 2> "core":"testCollection_shard2_replica_n3",
[junit4] 2> "shard":"shard2",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10030_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}
[junit4] 2> 1655334 DEBUG (simCloudManagerPool-11897-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- finished createCollection testCollection
[junit4] 2> 1655334 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 4. WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 1655334 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 1655354 DEBUG (ScheduledTrigger-11898-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1655355 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 5. RunSolrRequest path=/admin/autoscaling&httpMethod=POST&stream.body={'set-trigger':{'name':'indexSizeTrigger','event':'indexSize','waitFor':'10s','aboveDocs':1000,'enabled':true,'actions':[{'name':'compute_plan','class':'solr.ComputePlanAction'},{'name':'execute_plan','class':'solr.ExecutePlanAction'}]}}
[junit4] 2> 1655355 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/autoscaling&httpMethod=POST&stream.body={'set-trigger':{'name':'indexSizeTrigger','event':'indexSize','waitFor':'10s','aboveDocs':1000,'enabled':true,'actions':[{'name':'compute_plan','class':'solr.ComputePlanAction'},{'name':'execute_plan','class':'solr.ExecutePlanAction'}]}}
[junit4] 2> 1655362 DEBUG (simCloudManagerPool-11897-thread-6) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 1655362 DEBUG (simCloudManagerPool-11897-thread-6) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 3
[junit4] 2> 1655363 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 3
[junit4] 2> 1655363 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 6. SetEventListener trigger=indexSizeTrigger&stage=SUCCEEDED
[junit4] 2> 1655363 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario SetEventListener trigger=indexSizeTrigger&stage=SUCCEEDED
[junit4] 2> 1655363 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 1655363 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 3, lastZnodeVersion 3
[junit4] 2> 1655363 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 7. IndexDocs collection=testCollection&numDocs=3000
[junit4] 2> 1655363 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario IndexDocs collection=testCollection&numDocs=3000
[junit4] 2> 1655368 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 8. RunSimulator
[junit4] 2> 1655368 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario RunSimulator
[junit4] 2> 1655374 DEBUG (ScheduledTrigger-11898-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1655394 DEBUG (ScheduledTrigger-11898-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1655414 DEBUG (ScheduledTrigger-11898-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1655435 DEBUG (ScheduledTrigger-11898-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1655455 DEBUG (ScheduledTrigger-11898-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1655475 DEBUG (ScheduledTrigger-11898-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1655495 DEBUG (ScheduledTrigger-11898-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1655516 DEBUG (ScheduledTrigger-11898-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1655536 DEBUG (ScheduledTrigger-11898-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1655556 DEBUG (ScheduledTrigger-11898-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1655577 DEBUG (ScheduledTrigger-11898-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1655596 DEBUG (ScheduledTrigger-11898-thread-1) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"651b8e94a8f93eTaif7atyj9nm0abbq1u5m2orln",
[junit4] 2> "source":"indexSizeTrigger",
[junit4] 2> "eventTime":28459271841184062,
[junit4] 2> "eventType":"INDEXSIZE",
[junit4] 2> "properties":{
[junit4] 2> "aboveSize":{
[junit4] 2> "testCollection_shard1_replica_n1":"docs=1500, bytes=3082240",
[junit4] 2> "testCollection_shard2_replica_n3":"docs=1500, bytes=3082240"},
[junit4] 2> "belowSize":{},
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard1"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}},
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard2"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}}]}}
[junit4] 2> 1655596 DEBUG (ScheduledTrigger-11898-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [.auto_add_replicas, .scheduled_maintenance, indexSizeTrigger]
[junit4] 2> 1655597 DEBUG (ScheduledTrigger-11898-thread-1) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"651b8e94a8f93eTaif7atyj9nm0abbq1u5m2orln",
[junit4] 2> "source":"indexSizeTrigger",
[junit4] 2> "eventTime":28459271841184062,
[junit4] 2> "eventType":"INDEXSIZE",
[junit4] 2> "properties":{
[junit4] 2> "aboveSize":{
[junit4] 2> "testCollection_shard1_replica_n1":"docs=1500, bytes=3082240",
[junit4] 2> "testCollection_shard2_replica_n3":"docs=1500, bytes=3082240"},
[junit4] 2> "belowSize":{},
[junit4] 2> "_enqueue_time_":28459282281464362,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard1"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}},
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard2"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}}]}}
[junit4] 2> 1655597 DEBUG (AutoscalingActionExecutor-11899-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"651b8e94a8f93eTaif7atyj9nm0abbq1u5m2orln",
[junit4] 2> "source":"indexSizeTrigger",
[junit4] 2> "eventTime":28459271841184062,
[junit4] 2> "eventType":"INDEXSIZE",
[junit4] 2> "properties":{
[junit4] 2> "aboveSize":{
[junit4] 2> "testCollection_shard1_replica_n1":"docs=1500, bytes=3082240",
[junit4] 2> "testCollection_shard2_replica_n3":"docs=1500, bytes=3082240"},
[junit4] 2> "belowSize":{},
[junit4] 2> "_enqueue_time_":28459282281464362,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard1"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}},
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard2"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}}]}}
[junit4] 2> 1655597 DEBUG (AutoscalingActionExecutor-11899-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- processing event: {
[junit4] 2> "id":"651b8e94a8f93eTaif7atyj9nm0abbq1u5m2orln",
[junit4] 2> "source":"indexSizeTrigger",
[junit4] 2> "eventTime":28459271841184062,
[junit4] 2> "eventType":"INDEXSIZE",
[junit4] 2> "properties":{
[junit4] 2> "aboveSize":{
[junit4] 2> "testCollection_shard1_replica_n1":"docs=1500, bytes=3082240",
[junit4] 2> "testCollection_shard2_replica_n3":"docs=1500, bytes=3082240"},
[junit4] 2> "belowSize":{},
[junit4] 2> "_enqueue_time_":28459282281464362,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard1"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}},
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard2"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}}]}} with context properties: {BEFORE_ACTION=[compute_plan]}
[junit4] 2> 1655599 DEBUG (AutoscalingActionExecutor-11899-thread-1) [ ] o.a.s.c.a.ComputePlanAction Computed Plan: action=SPLITSHARD&collection=testCollection&shard=shard1&splitMethod=link&splitByPrefix=false
[junit4] 2> 1655599 DEBUG (AutoscalingActionExecutor-11899-thread-1) [ ] o.a.s.c.a.ComputePlanAction Computed Plan: action=SPLITSHARD&collection=testCollection&shard=shard2&splitMethod=link&splitByPrefix=false
[junit4] 2> 1655599 DEBUG (AutoscalingActionExecutor-11899-thread-1) [ ] o.a.s.c.a.ExecutePlanAction -- processing event: {
[junit4] 2> "id":"651b8e94a8f93eTaif7atyj9nm0abbq1u5m2orln",
[junit4] 2> "source":"indexSizeTrigger",
[junit4] 2> "eventTime":28459271841184062,
[junit4] 2> "eventType":"INDEXSIZE",
[junit4] 2> "properties":{
[junit4] 2> "__start__":2,
[junit4] 2> "aboveSize":{
[junit4] 2> "testCollection_shard1_replica_n1":"docs=1500, bytes=3082240",
[junit4] 2> "testCollection_shard2_replica_n3":"docs=1500, bytes=3082240"},
[junit4] 2> "belowSize":{},
[junit4] 2> "_enqueue_time_":28459282281464362,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard1"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}},
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard2"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}}]}} with context properties: {operations=[{
[junit4] 2> "class":"org.apache.solr.client.solrj.request.CollectionAdminRequest$SplitShard",
[junit4] 2> "method":"GET",
[junit4] 2> "params.action":"SPLITSHARD",
[junit4] 2> "params.collection":"testCollection",
[junit4] 2> "params.shard":"shard1",
[junit4] 2> "params.splitMethod":"link",
[junit4] 2> "params.splitByPrefix":"false"}, {
[junit4] 2> "class":"org.apache.solr.client.solrj.request.CollectionAdminRequest$SplitShard",
[junit4] 2> "method":"GET",
[junit4] 2> "params.action":"SPLITSHARD",
[junit4] 2> "params.collection":"testCollection",
[junit4] 2> "params.shard":"shard2",
[junit4] 2> "params.splitMethod":"link",
[junit4] 2> "params.splitByPrefix":"false"}], AFTER_ACTION=[compute_plan], BEFORE_ACTION=[compute_plan, execute_plan]}
[junit4] 2> 1655599 DEBUG (AutoscalingActionExecutor-11899-thread-1) [ ] o.a.s.c.a.ExecutePlanAction Executing operation: action=SPLITSHARD&collection=testCollection&shard=shard1&splitMethod=link&splitByPrefix=false
[junit4] 2> 1655700 INFO (simCloudManagerPool-11897-thread-8) [ ] o.a.s.c.a.c.SplitShardCmd numSubShards set at: 2
[junit4] 2> 1655751 DEBUG (simCloudManagerPool-11897-thread-11) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1_1)
[junit4] 2> 1655751 DEBUG (simCloudManagerPool-11897-thread-11) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1_1 (currentVersion=9): {"core_node12":{
[junit4] 2> "core":"testCollection_shard1_1_replica_n11",
[junit4] 2> "shard":"shard1_1",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10018_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1546240,
[junit4] 2> "base_url":"http://127.0.0.1:10018/solr",
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":0.0014400482177734375,
[junit4] 2> "SEARCHER.searcher.numDocs":750}}
[junit4] 2> 1655751 DEBUG (simCloudManagerPool-11897-thread-12) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1_0)
[junit4] 2> 1655751 DEBUG (simCloudManagerPool-11897-thread-12) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1_0 (currentVersion=10): {"core_node10":{
[junit4] 2> "core":"testCollection_shard1_0_replica_n9",
[junit4] 2> "shard":"shard1_0",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1556480,
[junit4] 2> "base_url":"http://127.0.0.1:10004/solr",
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":0.0014495849609375,
[junit4] 2> "SEARCHER.searcher.numDocs":750}}
[junit4] 2> 1655754 DEBUG (AutoscalingActionExecutor-11899-thread-1) [ ] o.a.s.c.a.ExecutePlanAction Executing operation: action=SPLITSHARD&collection=testCollection&shard=shard2&splitMethod=link&splitByPrefix=false
[junit4] 2> 1655858 INFO (simCloudManagerPool-11897-thread-15) [ ] o.a.s.c.a.c.SplitShardCmd numSubShards set at: 2
[junit4] 2> 1655904 DEBUG (simCloudManagerPool-11897-thread-18) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard2_1)
[junit4] 2> 1655905 DEBUG (simCloudManagerPool-11897-thread-18) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard2_1 (currentVersion=16): {"core_node22":{
[junit4] 2> "core":"testCollection_shard2_1_replica_n21",
[junit4] 2> "shard":"shard2_1",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10018_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1546240,
[junit4] 2> "base_url":"http://127.0.0.1:10018/solr",
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":0.0014400482177734375,
[junit4] 2> "SEARCHER.searcher.numDocs":750}}
[junit4] 2> 1655905 DEBUG (simCloudManagerPool-11897-thread-21) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard2_0)
[junit4] 2> 1655905 DEBUG (simCloudManagerPool-11897-thread-21) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard2_0 (currentVersion=17): {"core_node18":{
[junit4] 2> "core":"testCollection_shard2_0_replica_n17",
[junit4] 2> "shard":"shard2_0",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10082_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1556480,
[junit4] 2> "base_url":"http://127.0.0.1:10082/solr",
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":0.0014495849609375,
[junit4] 2> "SEARCHER.searcher.numDocs":750}}
[junit4] 2> 1655905 DEBUG (simCloudManagerPool-11897-thread-15) [ ] o.a.s.c.a.s.SimClusterStateProvider ** no leader in testCollection / shard2_0:{
[junit4] 2> "parent":"shard2",
[junit4] 2> "stateTimestamp":"1592037702133445900",
[junit4] 2> "range":"0-3fffffff",
[junit4] 2> "state":"construction",
[junit4] 2> "replicas":{
[junit4] 2> "core_node18":{
[junit4] 2> "core":"testCollection_shard2_0_replica_n17",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1556480,
[junit4] 2> "node_name":"127.0.0.1:10082_solr",
[junit4] 2> "base_url":"http://127.0.0.1:10082/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":0.0014495849609375,
[junit4] 2> "SEARCHER.searcher.numDocs":750},
[junit4] 2> "core_node20":{
[junit4] 2> "core":"testCollection_shard2_0_replica_n19",
[junit4] 2> "SEARCHER.searcher.maxDoc":750,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":1556480,
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "base_url":"http://127.0.0.1:10004/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":0.0014495849609375,
[junit4] 2> "SEARCHER.searcher.numDocs":750}}}
[junit4] 2> 1655909 DEBUG (AutoscalingActionExecutor-11899-thread-1) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"651b8e94a8f93eTaif7atyj9nm0abbq1u5m2orln",
[junit4] 2> "source":"indexSizeTrigger",
[junit4] 2> "eventTime":28459271841184062,
[junit4] 2> "eventType":"INDEXSIZE",
[junit4] 2> "properties":{
[junit4] 2> "__start__":2,
[junit4] 2> "aboveSize":{
[junit4] 2> "testCollection_shard1_replica_n1":"docs=1500, bytes=3082240",
[junit4] 2> "testCollection_shard2_replica_n3":"docs=1500, bytes=3082240"},
[junit4] 2> "belowSize":{},
[junit4] 2> "_enqueue_time_":28459282281464362,
[junit4] 2> "requestedOps":[
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard1"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}},
[junit4] 2> {
[junit4] 2> "action":"SPLITSHARD",
[junit4] 2> "hints":{
[junit4] 2> "COLL_SHARD":[{
[junit4] 2> "first":"testCollection",
[junit4] 2> "second":"shard2"}],
[junit4] 2> "PARAMS":{
[junit4] 2> "splitByPrefix":false,
[junit4] 2> "splitMethod":"link"}}}]}}
[junit4] 2> 1655910 DEBUG (AutoscalingActionExecutor-11899-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: indexSizeTrigger after 100ms
[junit4] 2> 1655910 DEBUG (AutoscalingActionExecutor-11899-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: .scheduled_maintenance after 100ms
[junit4] 2> 1655910 DEBUG (AutoscalingActionExecutor-11899-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: .auto_add_replicas after 100ms
[junit4] 2> 1655910 DEBUG (AutoscalingActionExecutor-11899-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 15625 ms for event id=651b8e94a8f93eTaif7atyj9nm0abbq1u5m2orln
[junit4] 2> 1656010 DEBUG (ScheduledTrigger-11898-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656030 DEBUG (ScheduledTrigger-11898-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656050 DEBUG (ScheduledTrigger-11898-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656071 DEBUG (ScheduledTrigger-11898-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656091 DEBUG (ScheduledTrigger-11898-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656111 DEBUG (ScheduledTrigger-11898-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656131 DEBUG (ScheduledTrigger-11898-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656152 DEBUG (ScheduledTrigger-11898-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656172 DEBUG (ScheduledTrigger-11898-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656192 DEBUG (ScheduledTrigger-11898-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656213 DEBUG (ScheduledTrigger-11898-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656233 DEBUG (ScheduledTrigger-11898-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656253 DEBUG (ScheduledTrigger-11898-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656273 DEBUG (ScheduledTrigger-11898-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656294 DEBUG (ScheduledTrigger-11898-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656314 DEBUG (ScheduledTrigger-11898-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656334 DEBUG (ScheduledTrigger-11898-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656355 DEBUG (ScheduledTrigger-11898-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656375 DEBUG (ScheduledTrigger-11898-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656395 DEBUG (ScheduledTrigger-11898-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656415 DEBUG (ScheduledTrigger-11898-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656436 DEBUG (ScheduledTrigger-11898-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656456 DEBUG (ScheduledTrigger-11898-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656476 DEBUG (ScheduledTrigger-11898-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656497 DEBUG (ScheduledTrigger-11898-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656517 DEBUG (ScheduledTrigger-11898-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656537 DEBUG (ScheduledTrigger-11898-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656557 DEBUG (ScheduledTrigger-11898-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 100 and last live nodes: 100
[junit4] 2> 1656568 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 9. WaitEvent trigger=indexSizeTrigger&wait=60
[junit4] 2> 1656568 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario WaitEvent trigger=indexSizeTrigger&wait=60
[junit4] 2> 1656569 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 10. Assert condition=not_null&key=_trigger_event_indexSizeTrigger
[junit4] 2> 1656569 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario Assert condition=not_null&key=_trigger_event_indexSizeTrigger
[junit4] 2> 1656570 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 11. Assert condition=equals&key=_trigger_event_indexSizeTrigger/eventType&expected=INDEXSIZE
[junit4] 2> 1656570 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario Assert condition=equals&key=_trigger_event_indexSizeTrigger/eventType&expected=INDEXSIZE
[junit4] 2> 1656570 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 12. Assert condition=equals&key=_trigger_event_indexSizeTrigger/properties/requestedOps[0]/action&expected=SPLITSHARD
[junit4] 2> 1656570 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario Assert condition=equals&key=_trigger_event_indexSizeTrigger/properties/requestedOps[0]/action&expected=SPLITSHARD
[junit4] 2> 1656570 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 13. WaitCollection collection=testCollection&shards=6&withInactive=true&requireLeaders=false&replicas=2
[junit4] 2> 1656570 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario WaitCollection collection=testCollection&shards=6&withInactive=true&requireLeaders=false&replicas=2
[junit4] 2> 1656571 DEBUG (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 1656571 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Interrupted
[junit4] 2> => java.lang.InterruptedException
[junit4] 2> at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2056)
[junit4] 2> java.lang.InterruptedException: null
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2056) ~[?:?]
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2090) ~[?:?]
[junit4] 2> at org.apache.solr.cloud.autoscaling.OverseerTriggerThread.run(OverseerTriggerThread.java:206) ~[java/:?]
[junit4] 2> at java.lang.Thread.run(Thread.java:834) [?:?]
[junit4] 2> 1656572 DEBUG (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 1656572 DEBUG (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 1656572 DEBUG (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 1656572 DEBUG (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 1656572 DEBUG (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 1656573 INFO (TEST-TestSimScenario.testIndexing-seed#[D06D8A8D933578A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testIndexing
[junit4] 2> 1656576 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testSplitShard
[junit4] 2> 1656576 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 1. CreateCluster numNodes=2
[junit4] 2> 1656576 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario CreateCluster numNodes=2
[junit4] 2> 1656579 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10100_solr
[junit4] 2> 1656579 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 1656579 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 1656579 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 1656579 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 2. LoadAutoscaling json={'cluster-policy':[]}
[junit4] 2> 1656579 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario LoadAutoscaling json={'cluster-policy':[]}
[junit4] 2> 1656580 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 1656580 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 1656580 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 1656580 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10100_solr, 127.0.0.1:10101_solr]
[junit4] 2> 1656580 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 1656580 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 1
[junit4] 2> 1656580 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 2
[junit4] 2> 1656580 DEBUG (ScheduledTrigger-11904-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656580 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 1656580 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 2
[junit4] 2> 1656585 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 3. RunSolrRequest path=/admin/collections&action=CREATE&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=5
[junit4] 2> 1656585 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collections&action=CREATE&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=5
[junit4] 2> 1656586 DEBUG (simCloudManagerPool-11903-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- simCreateCollection testCollection
[junit4] 2> 1656601 DEBUG (ScheduledTrigger-11904-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656607 DEBUG (simCloudManagerPool-11903-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1)
[junit4] 2> 1656607 DEBUG (simCloudManagerPool-11903-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1 (currentVersion=2): {"core_node1":{
[junit4] 2> "core":"testCollection_shard1_replica_n1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10101_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}
[junit4] 2> 1656607 DEBUG (simCloudManagerPool-11903-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- finished createCollection testCollection
[junit4] 2> 1656607 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 4. WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 1656607 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 1656621 DEBUG (ScheduledTrigger-11904-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656628 DEBUG (simCloudManagerPool-11903-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard2)
[junit4] 2> 1656628 DEBUG (simCloudManagerPool-11903-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard2 (currentVersion=4): {"core_node3":{
[junit4] 2> "core":"testCollection_shard2_replica_n3",
[junit4] 2> "shard":"shard2",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10101_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}
[junit4] 2> 1656638 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 5. SetShardMetrics collection=testCollection&shard=shard1&INDEX.sizeInBytes=1000000000
[junit4] 2> 1656638 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario SetShardMetrics collection=testCollection&shard=shard1&INDEX.sizeInBytes=1000000000
[junit4] 2> 1656639 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 6. SetNodeMetrics nodeset=#ANY&freedisk=1.5
[junit4] 2> 1656639 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario SetNodeMetrics nodeset=#ANY&freedisk=1.5
[junit4] 2> 1656639 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 7. RunSolrRequest path=/admin/collection&action=SPLITSHARD&collection=testCollection&shard=shard1&splitMethod=${method}
[junit4] 2> 1656640 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collection&action=SPLITSHARD&collection=testCollection&shard=shard1&splitMethod=REWRITE
[junit4] 2> 1656641 DEBUG (ScheduledTrigger-11904-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656642 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 1656642 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 1656642 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 1656642 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 1656642 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 1656642 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 1656642 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 1656643 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 1. CreateCluster numNodes=2
[junit4] 2> 1656643 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario CreateCluster numNodes=2
[junit4] 2> 1656645 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10102_solr
[junit4] 2> 1656645 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 1656645 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 2. LoadAutoscaling json={'cluster-policy':[]}
[junit4] 2> 1656645 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario LoadAutoscaling json={'cluster-policy':[]}
[junit4] 2> 1656645 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 1656646 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 1656646 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 1656646 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 1656648 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10102_solr, 127.0.0.1:10103_solr]
[junit4] 2> 1656649 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 1656649 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 1656649 DEBUG (ScheduledTrigger-11910-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656650 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 3. RunSolrRequest path=/admin/collections&action=CREATE&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=5
[junit4] 2> 1656650 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collections&action=CREATE&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=5
[junit4] 2> 1656653 DEBUG (simCloudManagerPool-11909-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- simCreateCollection testCollection
[junit4] 2> 1656669 DEBUG (ScheduledTrigger-11910-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656675 DEBUG (simCloudManagerPool-11909-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1)
[junit4] 2> 1656675 DEBUG (simCloudManagerPool-11909-thread-2) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1 (currentVersion=2): {"core_node1":{
[junit4] 2> "core":"testCollection_shard1_replica_n1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10102_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}
[junit4] 2> 1656689 DEBUG (ScheduledTrigger-11910-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656700 DEBUG (simCloudManagerPool-11909-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard2)
[junit4] 2> 1656700 DEBUG (simCloudManagerPool-11909-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard2 (currentVersion=4): {"core_node3":{
[junit4] 2> "core":"testCollection_shard2_replica_n3",
[junit4] 2> "shard":"shard2",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10102_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}
[junit4] 2> 1656700 DEBUG (simCloudManagerPool-11909-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- finished createCollection testCollection
[junit4] 2> 1656700 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 4. WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 1656700 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 1656710 DEBUG (ScheduledTrigger-11910-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656711 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 5. SetShardMetrics collection=testCollection&shard=shard1&INDEX.sizeInBytes=1000000000
[junit4] 2> 1656711 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario SetShardMetrics collection=testCollection&shard=shard1&INDEX.sizeInBytes=1000000000
[junit4] 2> 1656711 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 6. SetNodeMetrics nodeset=#ANY&freedisk=1.5
[junit4] 2> 1656711 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario SetNodeMetrics nodeset=#ANY&freedisk=1.5
[junit4] 2> 1656711 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 7. RunSolrRequest path=/admin/collection&action=SPLITSHARD&collection=testCollection&shard=shard1&splitMethod=${method}
[junit4] 2> 1656711 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collection&action=SPLITSHARD&collection=testCollection&shard=shard1&splitMethod=LINK
[junit4] 2> 1656730 DEBUG (ScheduledTrigger-11910-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656750 DEBUG (ScheduledTrigger-11910-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656770 DEBUG (ScheduledTrigger-11910-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656795 DEBUG (ScheduledTrigger-11910-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656812 INFO (simCloudManagerPool-11909-thread-6) [ ] o.a.s.c.a.c.SplitShardCmd numSubShards set at: 2
[junit4] 2> 1656815 DEBUG (ScheduledTrigger-11910-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656836 DEBUG (ScheduledTrigger-11910-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656856 DEBUG (ScheduledTrigger-11910-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656858 DEBUG (simCloudManagerPool-11909-thread-9) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1_1)
[junit4] 2> 1656858 DEBUG (simCloudManagerPool-11909-thread-6) [ ] o.a.s.c.a.s.SimClusterStateProvider ** no leader in testCollection / shard1_0:{
[junit4] 2> "parent":"shard1",
[junit4] 2> "stateTimestamp":"1592037749820827700",
[junit4] 2> "range":"80000000-bfffffff",
[junit4] 2> "state":"construction",
[junit4] 2> "replicas":{
[junit4] 2> "core_node10":{
[junit4] 2> "core":"testCollection_shard1_0_replica_n9",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":20480,
[junit4] 2> "node_name":"127.0.0.1:10103_solr",
[junit4] 2> "base_url":"http://127.0.0.1:10103/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":1.9073486328125E-5,
[junit4] 2> "SEARCHER.searcher.numDocs":0},
[junit4] 2> "core_node8":{
[junit4] 2> "core":"testCollection_shard1_0_replica_n7",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":20480,
[junit4] 2> "node_name":"127.0.0.1:10102_solr",
[junit4] 2> "base_url":"http://127.0.0.1:10102/solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInGB":1.9073486328125E-5,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}}
[junit4] 2> 1656858 DEBUG (simCloudManagerPool-11909-thread-9) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1_1 (currentVersion=9): {"core_node12":{
[junit4] 2> "core":"testCollection_shard1_1_replica_n11",
[junit4] 2> "shard":"shard1_1",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10102_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "base_url":"http://127.0.0.1:10102/solr",
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}
[junit4] 2> 1656858 DEBUG (simCloudManagerPool-11909-thread-10) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1_0)
[junit4] 2> 1656858 DEBUG (simCloudManagerPool-11909-thread-10) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1_0 (currentVersion=10): {"core_node10":{
[junit4] 2> "core":"testCollection_shard1_0_replica_n9",
[junit4] 2> "shard":"shard1_0",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10103_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":20480,
[junit4] 2> "base_url":"http://127.0.0.1:10103/solr",
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":1.9073486328125E-5,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}
[junit4] 2> 1656860 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 8. WaitCollection collection=testCollection&shards=4&withInactive=true&replicas=2&requireLeaders=true
[junit4] 2> 1656860 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario WaitCollection collection=testCollection&shards=4&withInactive=true&replicas=2&requireLeaders=true
[junit4] 2> 1656861 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 1656862 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 1656862 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 1656862 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 1656862 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 1656862 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 1656862 DEBUG (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 1656863 INFO (TEST-TestSimScenario.testSplitShard-seed#[D06D8A8D933578A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testSplitShard
[junit4] 2> 1656865 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testSuggestions
[junit4] 2> 1656867 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 1. CreateCluster numNodes=2
[junit4] 2> 1656867 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario CreateCluster numNodes=2
[junit4] 2> 1656869 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10104_solr
[junit4] 2> 1656869 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 1656869 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 1656869 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 2. LoadAutoscaling json={'cluster-policy':[]}
[junit4] 2> 1656869 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario LoadAutoscaling json={'cluster-policy':[]}
[junit4] 2> 1656869 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 1656869 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 1656869 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 1656869 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 1656872 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10104_solr, 127.0.0.1:10105_solr]
[junit4] 2> 1656872 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 1656872 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 1
[junit4] 2> 1656872 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 2
[junit4] 2> 1656872 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 1656872 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 2
[junit4] 2> 1656873 DEBUG (ScheduledTrigger-11916-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656877 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 3. RunSolrRequest path=/admin/collections&action=CREATE&autoAddReplicas=true&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=2
[junit4] 2> 1656877 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collections&action=CREATE&autoAddReplicas=true&name=testCollection&numShards=2&replicationFactor=2&maxShardsPerNode=2
[junit4] 2> 1656879 DEBUG (simCloudManagerPool-11915-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- simCreateCollection testCollection
[junit4] 2> 1656893 DEBUG (ScheduledTrigger-11916-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656900 DEBUG (simCloudManagerPool-11915-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard1)
[junit4] 2> 1656900 DEBUG (simCloudManagerPool-11915-thread-3) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard1 (currentVersion=2): {"core_node2":{
[junit4] 2> "core":"testCollection_shard1_replica_n2",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10105_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}
[junit4] 2> 1656913 DEBUG (ScheduledTrigger-11916-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656921 DEBUG (simCloudManagerPool-11915-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider Running leader election (testCollection / shard2)
[junit4] 2> 1656921 DEBUG (simCloudManagerPool-11915-thread-4) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testCollection / shard2 (currentVersion=4): {"core_node3":{
[junit4] 2> "core":"testCollection_shard2_replica_n3",
[junit4] 2> "shard":"shard2",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10104_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "leader":"true",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "state":"active",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}
[junit4] 2> 1656921 DEBUG (simCloudManagerPool-11915-thread-1) [ ] o.a.s.c.a.s.SimClusterStateProvider -- finished createCollection testCollection
[junit4] 2> 1656921 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 4. WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 1656921 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 1656932 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 5. CtxSet key=myNode&value=${_random_node_}
[junit4] 2> 1656932 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario CtxSet key=myNode&value=127.0.0.1:10104_solr
[junit4] 2> 1656932 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 6. RunSolrRequest path=/admin/collections&action=ADDREPLICA&collection=testCollection&shard=shard1&node=${myNode}
[junit4] 2> 1656932 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collections&action=ADDREPLICA&collection=testCollection&shard=shard1&node=127.0.0.1:10104_solr
[junit4] 2> 1656932 INFO (simCloudManagerPool-11915-thread-6) [ ] o.a.s.c.a.c.AddReplicaCmd Node Identified 127.0.0.1:10104_solr for creating new replica of shard shard1 for collection testCollection
[junit4] 2> 1656932 INFO (simCloudManagerPool-11915-thread-6) [ ] o.a.s.c.a.c.AddReplicaCmd Returning CreateReplica command.
[junit4] 2> 1656933 DEBUG (ScheduledTrigger-11916-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656943 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 7. RunSolrRequest path=/admin/collections&action=ADDREPLICA&collection=testCollection&shard=shard1&node=${myNode}
[junit4] 2> 1656943 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario RunSolrRequest path=/admin/collections&action=ADDREPLICA&collection=testCollection&shard=shard1&node=127.0.0.1:10104_solr
[junit4] 2> 1656944 INFO (simCloudManagerPool-11915-thread-7) [ ] o.a.s.c.a.c.AddReplicaCmd Node Identified 127.0.0.1:10104_solr for creating new replica of shard shard1 for collection testCollection
[junit4] 2> 1656944 INFO (simCloudManagerPool-11915-thread-7) [ ] o.a.s.c.a.c.AddReplicaCmd Returning CreateReplica command.
[junit4] 2> 1656953 DEBUG (ScheduledTrigger-11916-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656954 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 8. LoopOp iterations=${iterative}
[junit4] 2> 1656954 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario LoopOp iterations=0
[junit4] 2> 1656954 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 9. LoopOp iterations=${justCalc}
[junit4] 2> 1656954 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario LoopOp iterations=1
[junit4] 2> 1656954 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario * iter 1 :
[junit4] 2> 1656954 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario - CalculateSuggestions )
[junit4] 2> 1656963 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario - 1 suggestions
[junit4] 2> 1656963 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario - SaveSnapshot path=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.autoscaling.sim.TestSimScenario_D06D8A8D933578A8-001/tempDir-001/snapshot/0)
[junit4] 2> 1656968 WARN (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimUtils V2 action SET_CLUSTER_PROPERTY_OBJ has no equivalent V1 action
[junit4] 2> 1656968 WARN (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimUtils V2 action GET_NODES has no equivalent V1 action
[junit4] 2> 1656971 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SnapshotDistribStateManager - copying 22 resources from SimDistribStateManager
[junit4] 2> 1656973 DEBUG (ScheduledTrigger-11916-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1656983 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 10. Dump redact=true
[junit4] 2> 1656983 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario Dump redact=true
[junit4] 2> 1656984 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SnapshotDistribStateManager - copying 22 resources from SimDistribStateManager
[junit4] 2> 1656987 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Interrupted
[junit4] 2> => java.lang.InterruptedException
[junit4] 2> at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2056)
[junit4] 2> java.lang.InterruptedException: null
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2056) ~[?:?]
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2090) ~[?:?]
[junit4] 2> at org.apache.solr.cloud.autoscaling.OverseerTriggerThread.run(OverseerTriggerThread.java:206) ~[java/:?]
[junit4] 2> at java.lang.Thread.run(Thread.java:834) [?:?]
[junit4] 2> 1656987 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 1656988 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 1656988 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 1656988 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 1656988 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 1656988 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 1656988 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 1. CreateCluster numNodes=2
[junit4] 2> 1656988 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario CreateCluster numNodes=2
[junit4] 2> 1656990 DEBUG (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimClusterStateProvider --- new Overseer leader: 127.0.0.1:10106_solr
[junit4] 2> 1656991 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 1656991 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .auto_add_replicas and .scheduled_maintenance triggers
[junit4] 2> 1656991 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 2. LoadAutoscaling json={'cluster-policy':[]}
[junit4] 2> 1656991 INFO (TEST-TestSimScenario.testSuggestions-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario LoadAutoscaling json={'cluster-policy':[]}
[junit4] 2> 1656991 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 1656992 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 0
[junit4] 2> 1656992 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 1656993 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger .auto_add_replicas - Initial livenodes: [127.0.0.1:10106_solr, 127.0.0.1:10107_solr]
[junit4] 2> 1656993 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- deactivating old nodeLost / nodeAdded markers
[junit4] 2> 1656993 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 1656993 DEBUG (ScheduledTrigger-11922-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657013 DEBUG (ScheduledTrigger-11922-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657034 DEBUG (ScheduledTrigger-11922-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657054 DEBUG (ScheduledTrigger-11922-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657074 DEBUG (ScheduledTrigger-11922-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657094 DEBUG (ScheduledTrigger-11922-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657114 DEBUG (ScheduledTrigger-11922-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657134 DEBUG (ScheduledTrigger-11922-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657154 DEBUG (ScheduledTrigger-11922-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657175 DEBUG (ScheduledTrigger-11922-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657195 DEBUG (ScheduledTrigger-11922-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657215 DEBUG (ScheduledTrigger-11922-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657235 DEBUG (ScheduledTrigger-11922-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657255 DEBUG (ScheduledTrigger-11922-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657275 DEBUG (ScheduledTrigger-11922-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657296 DEBUG (ScheduledTrigger-11922-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657316 DEBUG (ScheduledTrigger-11922-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657336 DEBUG (ScheduledTrigger-11922-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657356 DEBUG (ScheduledTrigger-11922-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657376 DEBUG (ScheduledTrigger-11922-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657396 DEBUG (ScheduledTrigger-11922-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657417 DEBUG (ScheduledTrigger-11922-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2 and last live nodes: 2
[junit4] 2> 1657437 DEBUG (ScheduledTrigger-11922-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes:
[...truncated too long message...]
[junit4] 2> "params.inPlaceMove":"true",
[junit4] 2> "params.replica":"core_node4"}], AFTER_ACTION=[auto_add_replicas_plan], BEFORE_ACTION=[auto_add_replicas_plan, execute_plan]}
[junit4] 2> 1657894 DEBUG (AutoscalingActionExecutor-11929-thread-1) [ ] o.a.s.c.a.ExecutePlanAction Executing operation: action=MOVEREPLICA&collection=testCollection&targetNode=127.0.0.1:10109_solr&inPlaceMove=true&replica=core_node1
[junit4] 2> 1657996 DEBUG (simCloudManagerPool-11927-thread-8) [ ] o.a.s.c.a.s.SimClusterStateProvider -- new replica: {"core_node6":{
[junit4] 2> "core":"testCollection_shard1_replica_n5",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10109_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "state":"down",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}
[junit4] 2> 1658108 DEBUG (AutoscalingActionExecutor-11929-thread-1) [ ] o.a.s.c.a.ExecutePlanAction Executing operation: action=MOVEREPLICA&collection=testCollection&targetNode=127.0.0.1:10109_solr&inPlaceMove=true&replica=core_node4
[junit4] 2> 1658209 DEBUG (simCloudManagerPool-11927-thread-11) [ ] o.a.s.c.a.s.SimClusterStateProvider -- new replica: {"core_node8":{
[junit4] 2> "core":"testCollection_shard2_replica_n7",
[junit4] 2> "shard":"shard2",
[junit4] 2> "collection":"testCollection",
[junit4] 2> "node_name":"127.0.0.1:10109_solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "SEARCHER.searcher.maxDoc":0,
[junit4] 2> "SEARCHER.searcher.deletedDocs":0,
[junit4] 2> "INDEX.sizeInBytes":10240,
[junit4] 2> "state":"down",
[junit4] 2> "INDEX.sizeInGB":9.5367431640625E-6,
[junit4] 2> "SEARCHER.searcher.numDocs":0}}
[junit4] 2> 1658321 DEBUG (AutoscalingActionExecutor-11929-thread-1) [ ] o.a.s.c.a.SystemLogListener Collection .system missing, skip sending event {
[junit4] 2> "id":"651ba9652f4c10Taif7atyj9nm0abbq1u5m2orlt",
[junit4] 2> "source":".auto_add_replicas",
[junit4] 2> "eventTime":28459387008797712,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[28459387008797712],
[junit4] 2> "preferredOperation":"movereplica",
[junit4] 2> "_enqueue_time_":28459397107690662,
[junit4] 2> "nodeNames":["127.0.0.1:10108_solr"]}}
[junit4] 2> 1658321 DEBUG (AutoscalingActionExecutor-11929-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: .scheduled_maintenance after 100ms
[junit4] 2> 1658321 DEBUG (AutoscalingActionExecutor-11929-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: .auto_add_replicas after 100ms
[junit4] 2> 1658321 DEBUG (AutoscalingActionExecutor-11929-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 21368 ms for event id=651ba9652f4c10Taif7atyj9nm0abbq1u5m2orlt
[junit4] 2> 1658321 INFO (TEST-TestSimScenario.testAutoAddReplicas-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 8. WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 1658321 INFO (TEST-TestSimScenario.testAutoAddReplicas-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario WaitCollection collection=testCollection&shards=2&replicas=2
[junit4] 2> 1658321 INFO (TEST-TestSimScenario.testAutoAddReplicas-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario 9. SaveSnapshot path=${snapshotPath}
[junit4] 2> 1658321 INFO (TEST-TestSimScenario.testAutoAddReplicas-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SimScenario SaveSnapshot path=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.autoscaling.sim.TestSimScenario_D06D8A8D933578A8-001/tempDir-002/snapshot
[junit4] 2> 1658321 DEBUG (TEST-TestSimScenario.testAutoAddReplicas-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SnapshotDistribStateManager - copying 23 resources from SimDistribStateManager
[junit4] 2> 1658324 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Interrupted
[junit4] 2> => java.lang.InterruptedException
[junit4] 2> at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2056)
[junit4] 2> java.lang.InterruptedException: null
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2056) ~[?:?]
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2090) ~[?:?]
[junit4] 2> at org.apache.solr.cloud.autoscaling.OverseerTriggerThread.run(OverseerTriggerThread.java:206) ~[java/:?]
[junit4] 2> at java.lang.Thread.run(Thread.java:834) [?:?]
[junit4] 2> 1658324 DEBUG (TEST-TestSimScenario.testAutoAddReplicas-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down scheduled thread pool executor now
[junit4] 2> 1658325 DEBUG (TEST-TestSimScenario.testAutoAddReplicas-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Shutting down action executor now
[junit4] 2> 1658325 DEBUG (TEST-TestSimScenario.testAutoAddReplicas-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for action executor
[junit4] 2> 1658325 DEBUG (TEST-TestSimScenario.testAutoAddReplicas-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers Awaiting termination for scheduled thread pool executor
[junit4] 2> 1658325 DEBUG (TEST-TestSimScenario.testAutoAddReplicas-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.ScheduledTriggers ScheduledTriggers closed completely
[junit4] 2> 1658325 DEBUG (TEST-TestSimScenario.testAutoAddReplicas-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 1658328 DEBUG (TEST-TestSimScenario.testAutoAddReplicas-seed#[D06D8A8D933578A8]) [ ] o.a.s.c.a.s.SnapshotDistribStateManager - loaded snapshot of 23 resources
[junit4] 2> 1658329 INFO (TEST-TestSimScenario.testAutoAddReplicas-seed#[D06D8A8D933578A8]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testAutoAddReplicas
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J0/temp/solr.cloud.autoscaling.sim.TestSimScenario_D06D8A8D933578A8-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene86): {}, docValues:{}, maxPointsInLeafNode=1311, maxMBSortInHeap=6.402965818804641, sim=Asserting(org.apache.lucene.search.similarities.AssertingSimilarity@264e75d7), locale=ta-MY, timezone=America/Kentucky/Monticello
[junit4] 2> NOTE: Linux 4.15.0-54-generic amd64/Oracle Corporation 11.0.4 (64-bit)/cpus=4,threads=1,free=317997416,total=536870912
[junit4] 2> NOTE: All tests run in this JVM: [TestAuthorizationFramework, TestExclusionRuleCollectionAccess, UpdateRequestProcessorFactoryTest, TestMaxTokenLenTokenizer, TestCloudConsistency, TestConfigReload, TestLogWatcher, SystemCollectionCompatTest, SchemaVersionSpecificBehaviorTest, TestSolrCloudWithKerberosAlt, TestSolrJ, TestWriterPerf, HdfsChaosMonkeyNothingIsSafeTest, CheckHdfsIndexTest, CollectionReloadTest, CustomTermsComponentTest, SparseHLLTest, TestSizeLimitedDistributedMap, SplitHandlerTest, IgnoreCommitOptimizeUpdateProcessorFactoryTest, OutOfBoxZkACLAndCredentialsProvidersTest, QueryElevationComponentTest, TestCrossCoreJoin, SegmentsInfoRequestHandlerTest, SimpleCollectionCreateDeleteTest, TestUseDocValuesAsStored, DeleteInactiveReplicaTest, SpellingQueryConverterTest, HdfsSyncSliceTest, BasicAuthStandaloneTest, ChaosMonkeySafeLeaderWithPullReplicasTest, TestTlogReplica, CdcrBootstrapTest, TestDistributedMissingSort, TestSSLRandomization, TestGraphMLResponseWriter, SliceStateTest, SuggesterWFSTTest, TestSearchPerf, TestRTGBase, SynonymTokenizerTest, TestTrie, RulesTest, TestFuzzyAnalyzedSuggestions, AutoAddReplicasPlanActionTest, CdcrRequestHandlerTest, TestSurroundQueryParser, CursorPagingTest, AnalyticsMergeStrategyTest, TestFieldCacheWithThreads, TestCoreAdminApis, TestStandardQParsers, DirectoryFactoryTest, NodeMarkersRegistrationTest, LeaderFailoverAfterPartitionTest, TestStressReorder, TestConfigSetsAPIZkFailure, BadComponentTest, TestIndexingPerformance, ZkSolrClientTest, TestLegacyNumericRangeQueryBuilder, DocValuesMissingTest, LeaderElectionContextKeyTest, ZkStateWriterTest, TestManagedSchemaAPI, Tagger2Test, BlobRepositoryCloudTest, CursorMarkTest, TestPostingsSolrHighlighter, TestReloadAndDeleteDocs, TestBadConfig, TestSafeXMLParsing, SolrIndexSearcherTest, TestDistributedStatsComponentCardinality, DirectSolrSpellCheckerTest, TestGroupingSearch, ExecutePlanActionTest, TestUniqueKeyFieldResource, TestExceedMaxTermLength, TestSolrCloudWithHadoopAuthPlugin, MoveReplicaHDFSTest, TestCollectionsAPIViaSolrCloudCluster, HLLSerializationTest, ForceLeaderTest, CurrencyFieldTypeTest, TestStressThreadBackup, CircularListTest, ClassificationUpdateProcessorFactoryTest, RoutingToNodesWithPropertiesTest, SolrShardReporterTest, TestCorePropertiesReload, SearchRateTriggerTest, EchoParamsTest, TestCopyFieldCollectionResource, ZkFailoverTest, IndexSchemaTest, AnalysisAfterCoreReloadTest, TestAddFieldRealTimeGet, SampleTest, TestComplexPhraseLeadingWildcard, V2StandaloneTest, TestNestedDocsSort, TlogReplayBufferedWhileIndexingTest, TestSimScenario]
[junit4] Completed [227/910 (1!)] on J0 in 3.13s, 4 tests, 1 error <<< FAILURES!
[...truncated 54261 lines...]