lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Apache Jenkins Server <jenk...@builds.apache.org>
Subject [JENKINS] Lucene-Solr-NightlyTests-master - Build # 1318 - Failure
Date Thu, 08 Jun 2017 03:08:03 GMT
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-master/1318/

2 tests failed.
FAILED:  org.apache.lucene.index.TestIndexSorting.testRandom3

Error Message:
Java heap space

Stack Trace:
java.lang.OutOfMemoryError: Java heap space
	at __randomizedtesting.SeedInfo.seed([B1C4C4B25A7D350:A9C402914155FA56]:0)
	at org.apache.lucene.util.packed.Packed8ThreeBlocks.<init>(Packed8ThreeBlocks.java:41)
	at org.apache.lucene.util.packed.PackedInts.getMutable(PackedInts.java:963)
	at org.apache.lucene.util.packed.PackedInts.getMutable(PackedInts.java:939)
	at org.apache.lucene.util.packed.GrowableWriter.ensureCapacity(GrowableWriter.java:80)
	at org.apache.lucene.util.packed.GrowableWriter.set(GrowableWriter.java:88)
	at org.apache.lucene.util.packed.AbstractPagedMutable.set(AbstractPagedMutable.java:98)
	at org.apache.lucene.util.fst.NodeHash.addNew(NodeHash.java:152)
	at org.apache.lucene.util.fst.NodeHash.rehash(NodeHash.java:169)
	at org.apache.lucene.util.fst.NodeHash.add(NodeHash.java:133)
	at org.apache.lucene.util.fst.Builder.compileNode(Builder.java:200)
	at org.apache.lucene.util.fst.Builder.freezeTail(Builder.java:296)
	at org.apache.lucene.util.fst.Builder.add(Builder.java:400)
	at org.apache.lucene.codecs.memory.MemoryDocValuesConsumer.writeFST(MemoryDocValuesConsumer.java:373)
	at org.apache.lucene.codecs.memory.MemoryDocValuesConsumer.addSortedField(MemoryDocValuesConsumer.java:416)
	at org.apache.lucene.codecs.memory.MemoryDocValuesConsumer.addSortedField(MemoryDocValuesConsumer.java:406)
	at org.apache.lucene.codecs.DocValuesConsumer.mergeSortedField(DocValuesConsumer.java:527)
	at org.apache.lucene.codecs.DocValuesConsumer.merge(DocValuesConsumer.java:139)
	at org.apache.lucene.codecs.perfield.PerFieldDocValuesFormat$FieldsWriter.merge(PerFieldDocValuesFormat.java:151)
	at org.apache.lucene.index.SegmentMerger.mergeDocValues(SegmentMerger.java:181)
	at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:125)
	at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4361)
	at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3933)
	at org.apache.lucene.index.SerialMergeScheduler.merge(SerialMergeScheduler.java:40)
	at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:2082)
	at org.apache.lucene.index.IndexWriter.doAfterSegmentFlushed(IndexWriter.java:4992)
	at org.apache.lucene.index.DocumentsWriter$MergePendingEvent.process(DocumentsWriter.java:731)
	at org.apache.lucene.index.IndexWriter.processEvents(IndexWriter.java:5030)
	at org.apache.lucene.index.IndexWriter.processEvents(IndexWriter.java:5021)
	at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1573)
	at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1315)
	at org.apache.lucene.index.TestIndexSorting.testRandom3(TestIndexSorting.java:2301)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)


FAILED:  org.apache.solr.cloud.hdfs.HdfsRecoveryZkTest.test

Error Message:
Mismatch in counts between replicas

Stack Trace:
java.lang.AssertionError: Mismatch in counts between replicas
	at __randomizedtesting.SeedInfo.seed([19F448DC1133CDE:89CB7B576FEF5126]:0)
	at org.junit.Assert.fail(Assert.java:93)
	at org.apache.solr.cloud.RecoveryZkTest.assertShardConsistency(RecoveryZkTest.java:143)
	at org.apache.solr.cloud.RecoveryZkTest.test(RecoveryZkTest.java:126)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:907)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957)
	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:368)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
	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 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:368)
	at java.lang.Thread.run(Thread.java:745)




Build Log:
[...truncated 1535 lines...]
   [junit4] Suite: org.apache.lucene.index.TestIndexSorting
   [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=TestIndexSorting -Dtests.method=testRandom3 -Dtests.seed=B1C4C4B25A7D350 -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=id -Dtests.timezone=Africa/Bangui -Dtests.asserts=true -Dtests.file.encoding=UTF-8
   [junit4] ERROR    149s J1 | TestIndexSorting.testRandom3 <<<
   [junit4]    > Throwable #1: java.lang.OutOfMemoryError: Java heap space
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([B1C4C4B25A7D350:A9C402914155FA56]:0)
   [junit4]    > 	at org.apache.lucene.util.packed.Packed8ThreeBlocks.<init>(Packed8ThreeBlocks.java:41)
   [junit4]    > 	at org.apache.lucene.util.packed.PackedInts.getMutable(PackedInts.java:963)
   [junit4]    > 	at org.apache.lucene.util.packed.PackedInts.getMutable(PackedInts.java:939)
   [junit4]    > 	at org.apache.lucene.util.packed.GrowableWriter.ensureCapacity(GrowableWriter.java:80)
   [junit4]    > 	at org.apache.lucene.util.packed.GrowableWriter.set(GrowableWriter.java:88)
   [junit4]    > 	at org.apache.lucene.util.packed.AbstractPagedMutable.set(AbstractPagedMutable.java:98)
   [junit4]    > 	at org.apache.lucene.util.fst.NodeHash.addNew(NodeHash.java:152)
   [junit4]    > 	at org.apache.lucene.util.fst.NodeHash.rehash(NodeHash.java:169)
   [junit4]    > 	at org.apache.lucene.util.fst.NodeHash.add(NodeHash.java:133)
   [junit4]    > 	at org.apache.lucene.util.fst.Builder.compileNode(Builder.java:200)
   [junit4]    > 	at org.apache.lucene.util.fst.Builder.freezeTail(Builder.java:296)
   [junit4]    > 	at org.apache.lucene.util.fst.Builder.add(Builder.java:400)
   [junit4]    > 	at org.apache.lucene.codecs.memory.MemoryDocValuesConsumer.writeFST(MemoryDocValuesConsumer.java:373)
   [junit4]    > 	at org.apache.lucene.codecs.memory.MemoryDocValuesConsumer.addSortedField(MemoryDocValuesConsumer.java:416)
   [junit4]    > 	at org.apache.lucene.codecs.memory.MemoryDocValuesConsumer.addSortedField(MemoryDocValuesConsumer.java:406)
   [junit4]    > 	at org.apache.lucene.codecs.DocValuesConsumer.mergeSortedField(DocValuesConsumer.java:527)
   [junit4]    > 	at org.apache.lucene.codecs.DocValuesConsumer.merge(DocValuesConsumer.java:139)
   [junit4]    > 	at org.apache.lucene.codecs.perfield.PerFieldDocValuesFormat$FieldsWriter.merge(PerFieldDocValuesFormat.java:151)
   [junit4]    > 	at org.apache.lucene.index.SegmentMerger.mergeDocValues(SegmentMerger.java:181)
   [junit4]    > 	at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:125)
   [junit4]    > 	at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4361)
   [junit4]    > 	at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3933)
   [junit4]    > 	at org.apache.lucene.index.SerialMergeScheduler.merge(SerialMergeScheduler.java:40)
   [junit4]    > 	at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:2082)
   [junit4]    > 	at org.apache.lucene.index.IndexWriter.doAfterSegmentFlushed(IndexWriter.java:4992)
   [junit4]    > 	at org.apache.lucene.index.DocumentsWriter$MergePendingEvent.process(DocumentsWriter.java:731)
   [junit4]    > 	at org.apache.lucene.index.IndexWriter.processEvents(IndexWriter.java:5030)
   [junit4]    > 	at org.apache.lucene.index.IndexWriter.processEvents(IndexWriter.java:5021)
   [junit4]    > 	at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1573)
   [junit4]    > 	at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1315)
   [junit4]    > 	at org.apache.lucene.index.TestIndexSorting.testRandom3(TestIndexSorting.java:2301)
   [junit4]   2> NOTE: leaving temporary files on disk at: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/lucene/build/core/test/J1/temp/lucene.index.TestIndexSorting_B1C4C4B25A7D350-001
   [junit4]   2> NOTE: test params are: codec=Asserting(Lucene70): {sparse_text=PostingsFormat(name=LuceneVarGapFixedInterval), docs=BlockTreeOrds(blocksize=128), norms=BlockTreeOrds(blocksize=128), positions=PostingsFormat(name=Memory), id=BlockTreeOrds(blocksize=128), term_vectors=BlockTreeOrds(blocksize=128)}, docValues:{multi_valued_long=DocValuesFormat(name=Lucene70), foo=DocValuesFormat(name=Lucene70), numeric=DocValuesFormat(name=Memory), multi_valued_numeric=DocValuesFormat(name=Memory), float=DocValuesFormat(name=Direct), long=DocValuesFormat(name=Direct), points=DocValuesFormat(name=Lucene70), sparse_int=DocValuesFormat(name=Direct), bar=DocValuesFormat(name=Memory), multi_valued_double=DocValuesFormat(name=Memory), docs=DocValuesFormat(name=Memory), id=DocValuesFormat(name=Memory), multi_valued_int=DocValuesFormat(name=Lucene70), multi_valued_bytes=DocValuesFormat(name=Memory), sparse_text=DocValuesFormat(name=Direct), double=DocValuesFormat(name=Memory), sparse_binary=DocValuesFormat(name=Direct), positions=DocValuesFormat(name=Lucene70), int=DocValuesFormat(name=Memory), sorted=DocValuesFormat(name=Memory), sparse=DocValuesFormat(name=Direct), multi_valued_string=DocValuesFormat(name=Memory), norms=DocValuesFormat(name=Memory), bytes=DocValuesFormat(name=Memory), dense_int=DocValuesFormat(name=Memory), binary=DocValuesFormat(name=Memory), multi_valued_float=DocValuesFormat(name=Lucene70), term_vectors=DocValuesFormat(name=Memory)}, maxPointsInLeafNode=538, maxMBSortInHeap=6.188537060958199, sim=RandomSimilarity(queryNorm=true): {positions=DFR I(ne)BZ(0.3), id=IB SPL-DZ(0.3), term_vectors=LM Jelinek-Mercer(0.700000)}, locale=id, timezone=Africa/Bangui
   [junit4]   2> NOTE: Linux 3.13.0-88-generic amd64/Oracle Corporation 1.8.0_121 (64-bit)/cpus=4,threads=1,free=362264744,total=427819008
   [junit4]   2> NOTE: All tests run in this JVM: [TestMinimize, TestPositiveScoresOnlyCollector, TestDuelingCodecs, TestFSTs, TestOneMergeWrappingMergePolicy, TestDocumentsWriterDeleteQueue, TestPhrasePrefixQuery, TestTermdocPerf, TestTieredMergePolicy, TestOmitPositions, TestQueryRescorer, TestSpanFirstQuery, TestPhraseQuery, TestFieldInvertState, TestPrefixInBooleanQuery, TestLSBRadixSorter, TestAddIndexes, TestMinShouldMatch2, TestIndexSearcher, TestBooleanOr, TestGraphTokenizers, TestAllFilesDetectTruncation, TestSimpleFSDirectory, TestSearcherManager, TestElevationComparator, TestTermVectors, TestPositionIncrement, TestIndexWriterDelete, TestIndexWriterOnJRECrash, TestPriorityQueue, TestIndexWriterMaxDocs, Test2BBKDPoints, TestRollback, TestNoMergeScheduler, TestLucene50StoredFieldsFormat, TestDocInverterPerFieldErrorInfo, TestVirtualMethod, TestSpanTermQuery, TestMergePolicyWrapper, Test2BPostingsBytes, TestSpanExplanationsOfNonMatches, TestScoreCachingWrappingScorer, TestSleepingLockWrapper, TestCodecUtil, TestIndexWriterUnicode, TestFieldType, TestNorms, TestNumericUtils, TestRadixSelector, TestSortRescorer, TestCloseableThreadLocal, TestSizeBoundedForceMerge, TestPolygon, TestSpanBoostQuery, TestSameScoresWithThreads, TestLevenshteinAutomata, TestLogMergePolicy, TestFilterDirectoryReader, TestOmitTf, TestReusableStringReader, TestCheckIndex, TestDocumentsWriterStallControl, Test2BDocs, TestEarlyTerminatingSortingCollector, TestSortRandom, TestDuelingCodecsAtNight, TestParallelReaderEmptyIndex, TestLucene70DocValuesFormat, TestDirectMonotonic, TestIndexWriterDeleteByQuery, TestMultiTermConstantScore, TestDemo, TestRecyclingIntBlockAllocator, TestTryDelete, TestMultiDocValues, TestDocIDMerger, TestIndexSorting]
   [junit4] Completed [394/453 (1!)] on J1 in 178.96s, 50 tests, 1 error <<< FAILURES!

[...truncated 195 lines...]
   [junit4] JVM J1: stdout was not empty, see: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/lucene/build/core/test/temp/junit4-J1-20170607_223721_4833503895863574774592.sysout
   [junit4] >>> JVM J1 emitted unexpected output (verbatim) ----
   [junit4] java.lang.OutOfMemoryError: Java heap space
   [junit4] Dumping heap to /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/heapdumps/java_pid31990.hprof ...
   [junit4] Heap dump file created [454543972 bytes in 1.734 secs]
   [junit4] <<< JVM J1: EOF ----

[...truncated 11471 lines...]
   [junit4] Suite: org.apache.solr.cloud.hdfs.HdfsRecoveryZkTest
   [junit4]   2> Creating dataDir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_19F448DC1133CDE-001/init-core-data-001
   [junit4]   2> 3394314 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.a.s.SolrTestCaseJ4 Using TrieFields
   [junit4]   2> 3394322 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN)
   [junit4]   2> 3394322 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 2 servers in /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_19F448DC1133CDE-001/tempDir-001
   [junit4]   2> 3394322 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
   [junit4]   2> 3394323 INFO  (Thread-14473) [    ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
   [junit4]   2> 3394323 INFO  (Thread-14473) [    ] o.a.s.c.ZkTestServer Starting server
   [junit4]   2> 3394325 ERROR (Thread-14473) [    ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
   [junit4]   2> 3394423 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.a.s.c.ZkTestServer start zk server on port:39024
   [junit4]   2> 3394445 INFO  (jetty-launcher-3606-thread-1) [    ] o.e.j.s.Server jetty-9.3.14.v20161028
   [junit4]   2> 3394445 INFO  (jetty-launcher-3606-thread-2) [    ] o.e.j.s.Server jetty-9.3.14.v20161028
   [junit4]   2> 3394446 INFO  (jetty-launcher-3606-thread-1) [    ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@2e8d383e{/solr,null,AVAILABLE}
   [junit4]   2> 3394448 INFO  (jetty-launcher-3606-thread-2) [    ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@6ff6afc1{/solr,null,AVAILABLE}
   [junit4]   2> 3394448 INFO  (jetty-launcher-3606-thread-1) [    ] o.e.j.s.AbstractConnector Started ServerConnector@48764c05{HTTP/1.1,[http/1.1]}{127.0.0.1:34679}
   [junit4]   2> 3394449 INFO  (jetty-launcher-3606-thread-2) [    ] o.e.j.s.AbstractConnector Started ServerConnector@1b1eba3a{HTTP/1.1,[http/1.1]}{127.0.0.1:34068}
   [junit4]   2> 3394449 INFO  (jetty-launcher-3606-thread-2) [    ] o.e.j.s.Server Started @3397233ms
   [junit4]   2> 3394449 INFO  (jetty-launcher-3606-thread-2) [    ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=34068}
   [junit4]   2> 3394449 INFO  (jetty-launcher-3606-thread-1) [    ] o.e.j.s.Server Started @3397233ms
   [junit4]   2> 3394449 INFO  (jetty-launcher-3606-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=34679}
   [junit4]   2> 3394449 ERROR (jetty-launcher-3606-thread-2) [    ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
   [junit4]   2> 3394449 ERROR (jetty-launcher-3606-thread-1) [    ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
   [junit4]   2> 3394449 INFO  (jetty-launcher-3606-thread-2) [    ] o.a.s.s.SolrDispatchFilter  ___      _       Welcome to Apache Solr™ version 7.0.0
   [junit4]   2> 3394449 INFO  (jetty-launcher-3606-thread-1) [    ] o.a.s.s.SolrDispatchFilter  ___      _       Welcome to Apache Solr™ version 7.0.0
   [junit4]   2> 3394449 INFO  (jetty-launcher-3606-thread-2) [    ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _   Starting in cloud mode on port null
   [junit4]   2> 3394449 INFO  (jetty-launcher-3606-thread-1) [    ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _   Starting in cloud mode on port null
   [junit4]   2> 3394449 INFO  (jetty-launcher-3606-thread-2) [    ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_|  Install dir: null
   [junit4]   2> 3394449 INFO  (jetty-launcher-3606-thread-1) [    ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_|  Install dir: null
   [junit4]   2> 3394450 INFO  (jetty-launcher-3606-thread-2) [    ] o.a.s.s.SolrDispatchFilter |___/\___/_|_|    Start time: 2017-06-08T02:45:04.198Z
   [junit4]   2> 3394450 INFO  (jetty-launcher-3606-thread-1) [    ] o.a.s.s.SolrDispatchFilter |___/\___/_|_|    Start time: 2017-06-08T02:45:04.198Z
   [junit4]   2> 3394462 INFO  (jetty-launcher-3606-thread-2) [    ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
   [junit4]   2> 3394462 INFO  (jetty-launcher-3606-thread-1) [    ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
   [junit4]   2> 3394476 INFO  (jetty-launcher-3606-thread-2) [    ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:39024/solr
   [junit4]   2> 3394479 INFO  (jetty-launcher-3606-thread-1) [    ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:39024/solr
   [junit4]   2> 3394521 INFO  (jetty-launcher-3606-thread-1) [n:127.0.0.1:34679_solr    ] o.a.s.c.Overseer Overseer (id=null) closing
   [junit4]   2> 3394521 INFO  (jetty-launcher-3606-thread-2) [n:127.0.0.1:34068_solr    ] o.a.s.c.Overseer Overseer (id=null) closing
   [junit4]   2> 3394522 INFO  (jetty-launcher-3606-thread-1) [n:127.0.0.1:34679_solr    ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:34679_solr
   [junit4]   2> 3394523 INFO  (jetty-launcher-3606-thread-2) [n:127.0.0.1:34068_solr    ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34068_solr
   [junit4]   2> 3394525 INFO  (jetty-launcher-3606-thread-1) [n:127.0.0.1:34679_solr    ] o.a.s.c.Overseer Overseer (id=98100176753262598-127.0.0.1:34679_solr-n_0000000000) starting
   [junit4]   2> 3394531 INFO  (zkCallback-3618-thread-1-processing-n:127.0.0.1:34679_solr) [n:127.0.0.1:34679_solr    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
   [junit4]   2> 3394532 INFO  (zkCallback-3617-thread-1-processing-n:127.0.0.1:34068_solr) [n:127.0.0.1:34068_solr    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
   [junit4]   2> 3394569 INFO  (jetty-launcher-3606-thread-1) [n:127.0.0.1:34679_solr    ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34679_solr
   [junit4]   2> 3394579 INFO  (zkCallback-3618-thread-1-processing-n:127.0.0.1:34679_solr) [n:127.0.0.1:34679_solr    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
   [junit4]   2> 3394579 INFO  (zkCallback-3617-thread-1-processing-n:127.0.0.1:34068_solr) [n:127.0.0.1:34068_solr    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
   [junit4]   2> 3394693 INFO  (jetty-launcher-3606-thread-1) [n:127.0.0.1:34679_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34679.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74421fac
   [junit4]   2> 3394697 INFO  (jetty-launcher-3606-thread-1) [n:127.0.0.1:34679_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34679.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74421fac
   [junit4]   2> 3394698 INFO  (jetty-launcher-3606-thread-1) [n:127.0.0.1:34679_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34679.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74421fac
   [junit4]   2> 3394699 INFO  (jetty-launcher-3606-thread-1) [n:127.0.0.1:34679_solr    ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_19F448DC1133CDE-001/tempDir-001/node2/.
   [junit4]   2> 3394740 INFO  (jetty-launcher-3606-thread-2) [n:127.0.0.1:34068_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34068.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74421fac
   [junit4]   2> 3394746 INFO  (jetty-launcher-3606-thread-2) [n:127.0.0.1:34068_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34068.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74421fac
   [junit4]   2> 3394746 INFO  (jetty-launcher-3606-thread-2) [n:127.0.0.1:34068_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34068.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74421fac
   [junit4]   2> 3394747 INFO  (jetty-launcher-3606-thread-2) [n:127.0.0.1:34068_solr    ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_19F448DC1133CDE-001/tempDir-001/node1/.
   [junit4]   2> 3394788 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
   [junit4]   2> 3394790 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:39024/solr ready
   [junit4]   1> Formatting using clusterid: testClusterID
   [junit4]   2> 3394848 WARN  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.a.h.m.i.MetricsConfig Cannot locate configuration: tried hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
   [junit4]   2> 3394872 WARN  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
   [junit4]   2> 3394874 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.m.log jetty-6.1.26
   [junit4]   2> 3394903 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.m.log Extract jar:file:/x1/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.2-tests.jar!/webapps/hdfs to ./temp/Jetty_localhost_57247_hdfs____.dxx14z/webapp
   [junit4]   2> 3395436 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:57247
   [junit4]   2> 3395630 WARN  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
   [junit4]   2> 3395632 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.m.log jetty-6.1.26
   [junit4]   2> 3395674 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.m.log Extract jar:file:/x1/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.2-tests.jar!/webapps/datanode to ./temp/Jetty_localhost_42684_datanode____.bhdbj9/webapp
   [junit4]   2> 3396123 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:42684
   [junit4]   2> 3396255 WARN  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
   [junit4]   2> 3396256 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.m.log jetty-6.1.26
   [junit4]   2> 3396288 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.m.log Extract jar:file:/x1/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.2-tests.jar!/webapps/datanode to ./temp/Jetty_localhost_47580_datanode____bt4ne9/webapp
   [junit4]   2> 3396374 INFO  (IPC Server handler 4 on 52272) [    ] BlockStateChange BLOCK* processReport: from storage DS-850c8b69-51e8-42d5-934d-63fadfd5ac8a node DatanodeRegistration(127.0.0.1:43451, datanodeUuid=2715034c-acfe-4a52-9fcc-cecf0bfbc8d9, infoPort=34779, infoSecurePort=0, ipcPort=56637, storageInfo=lv=-56;cid=testClusterID;nsid=1651850002;c=0), blocks: 0, hasStaleStorage: true, processing time: 0 msecs
   [junit4]   2> 3396374 INFO  (IPC Server handler 4 on 52272) [    ] BlockStateChange BLOCK* processReport: from storage DS-c913d72d-e2f6-4028-8911-ae86baca4f96 node DatanodeRegistration(127.0.0.1:43451, datanodeUuid=2715034c-acfe-4a52-9fcc-cecf0bfbc8d9, infoPort=34779, infoSecurePort=0, ipcPort=56637, storageInfo=lv=-56;cid=testClusterID;nsid=1651850002;c=0), blocks: 0, hasStaleStorage: false, processing time: 0 msecs
   [junit4]   2> 3396818 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:47580
   [junit4]   2> 3397073 INFO  (IPC Server handler 7 on 52272) [    ] BlockStateChange BLOCK* processReport: from storage DS-457882e2-9a3c-4f09-9d8f-fe49dc41e407 node DatanodeRegistration(127.0.0.1:60661, datanodeUuid=e515b5aa-3e86-4682-a357-9fd352bff9d7, infoPort=40849, infoSecurePort=0, ipcPort=46032, storageInfo=lv=-56;cid=testClusterID;nsid=1651850002;c=0), blocks: 0, hasStaleStorage: true, processing time: 1 msecs
   [junit4]   2> 3397073 INFO  (IPC Server handler 7 on 52272) [    ] BlockStateChange BLOCK* processReport: from storage DS-691c7a32-7c0b-4b27-8670-e0a995751ca5 node DatanodeRegistration(127.0.0.1:60661, datanodeUuid=e515b5aa-3e86-4682-a357-9fd352bff9d7, infoPort=40849, infoSecurePort=0, ipcPort=46032, storageInfo=lv=-56;cid=testClusterID;nsid=1651850002;c=0), blocks: 0, hasStaleStorage: false, processing time: 0 msecs
   [junit4]   2> 3397454 INFO  (TEST-HdfsRecoveryZkTest.test-seed#[19F448DC1133CDE]) [    ] o.a.s.SolrTestCaseJ4 ###Starting test
   [junit4]   2> 3397456 INFO  (qtp1324117838-32435) [n:127.0.0.1:34068_solr    ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=2&collection.configName=conf&maxShardsPerNode=1&name=recoverytest&nrtReplicas=2&action=CREATE&numShards=1&wt=javabin&version=2 and sendToOCPQueue=true
   [junit4]   2> 3397461 INFO  (OverseerThreadFactory-8151-thread-1-processing-n:127.0.0.1:34679_solr) [n:127.0.0.1:34679_solr    ] o.a.s.c.CreateCollectionCmd Create collection recoverytest
   [junit4]   2> 3397581 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr    ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=recoverytest_shard1_replica_n1&action=CREATE&numShards=1&collection=recoverytest&shard=shard1&wt=javabin&version=2&replicaType=NRT
   [junit4]   2> 3397582 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr    ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
   [junit4]   2> 3397583 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr    ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=recoverytest_shard1_replica_n2&action=CREATE&numShards=1&collection=recoverytest&shard=shard1&wt=javabin&version=2&replicaType=NRT
   [junit4]   2> 3397583 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr    ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
   [junit4]   2> 3397687 INFO  (zkCallback-3617-thread-1-processing-n:127.0.0.1:34068_solr) [n:127.0.0.1:34068_solr    ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/recoverytest/state.json] for collection [recoverytest] has occurred - updating... (live nodes size: [2])
   [junit4]   2> 3397688 INFO  (zkCallback-3618-thread-2-processing-n:127.0.0.1:34679_solr) [n:127.0.0.1:34679_solr    ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/recoverytest/state.json] for collection [recoverytest] has occurred - updating... (live nodes size: [2])
   [junit4]   2> 3398630 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
   [junit4]   2> 3398630 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
   [junit4]   2> 3398644 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.s.IndexSchema [recoverytest_shard1_replica_n1] Schema name=minimal
   [junit4]   2> 3398647 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
   [junit4]   2> 3398647 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.CoreContainer Creating SolrCore 'recoverytest_shard1_replica_n1' using configuration from collection recoverytest, trusted=true
   [junit4]   2> 3398648 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34068.solr.core.recoverytest.shard1.replica_n1' (registry 'solr.core.recoverytest.shard1.replica_n1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74421fac
   [junit4]   2> 3398648 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.s.IndexSchema [recoverytest_shard1_replica_n2] Schema name=minimal
   [junit4]   2> 3398666 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
   [junit4]   2> 3398666 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.CoreContainer Creating SolrCore 'recoverytest_shard1_replica_n2' using configuration from collection recoverytest, trusted=true
   [junit4]   2> 3398666 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34679.solr.core.recoverytest.shard1.replica_n2' (registry 'solr.core.recoverytest.shard1.replica_n2') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74421fac
   [junit4]   2> 3398667 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory solr.hdfs.home=hdfs://localhost:52272/data
   [junit4]   2> 3398667 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory Solr Kerberos Authentication disabled
   [junit4]   2> 3398668 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
   [junit4]   2> 3398668 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.SolrCore [[recoverytest_shard1_replica_n1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_19F448DC1133CDE-001/tempDir-001/node1/recoverytest_shard1_replica_n1], dataDir=[hdfs://localhost:52272/data/recoverytest/core_node1/data/]
   [junit4]   2> 3398670 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost:52272/data/recoverytest/core_node1/data/snapshot_metadata
   [junit4]   2> 3398670 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.HdfsDirectoryFactory solr.hdfs.home=hdfs://localhost:52272/data
   [junit4]   2> 3398670 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.HdfsDirectoryFactory Solr Kerberos Authentication disabled
   [junit4]   2> 3398670 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
   [junit4]   2> 3398670 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.SolrCore [[recoverytest_shard1_replica_n2] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_19F448DC1133CDE-001/tempDir-001/node2/recoverytest_shard1_replica_n2], dataDir=[hdfs://localhost:52272/data/recoverytest/core_node2/data/]
   [junit4]   2> 3398681 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost:52272/data/recoverytest/core_node2/data/snapshot_metadata
   [junit4]   2> 3398684 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
   [junit4]   2> 3398684 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [16777216] will allocate [1] slabs and use ~[16777216] bytes
   [junit4]   2> 3398684 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory Creating new single instance HDFS BlockCache
   [junit4]   2> 3398725 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.s.b.BlockDirectory Block cache on write is disabled
   [junit4]   2> 3398726 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost:52272/data/recoverytest/core_node1/data
   [junit4]   2> 3398727 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
   [junit4]   2> 3398727 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [16777216] will allocate [1] slabs and use ~[16777216] bytes
   [junit4]   2> 3398727 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.HdfsDirectoryFactory Creating new single instance HDFS BlockCache
   [junit4]   2> 3398743 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.s.b.BlockDirectory Block cache on write is disabled
   [junit4]   2> 3398744 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost:52272/data/recoverytest/core_node2/data
   [junit4]   2> 3398772 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost:52272/data/recoverytest/core_node2/data/index
   [junit4]   2> 3398779 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost:52272/data/recoverytest/core_node1/data/index
   [junit4]   2> 3398788 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
   [junit4]   2> 3398788 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [16777216] will allocate [1] slabs and use ~[16777216] bytes
   [junit4]   2> 3398788 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory Creating new single instance HDFS BlockCache
   [junit4]   2> 3398790 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
   [junit4]   2> 3398790 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [16777216] will allocate [1] slabs and use ~[16777216] bytes
   [junit4]   2> 3398790 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.HdfsDirectoryFactory Creating new single instance HDFS BlockCache
   [junit4]   2> 3398815 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.s.b.BlockDirectory Block cache on write is disabled
   [junit4]   2> 3398819 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.s.b.BlockDirectory Block cache on write is disabled
   [junit4]   2> 3398908 INFO  (IPC Server handler 9 on 52272) [    ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43451 is added to blk_1073741825_1001{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-457882e2-9a3c-4f09-9d8f-fe49dc41e407:NORMAL:127.0.0.1:60661|RBW], ReplicaUC[[DISK]DS-c913d72d-e2f6-4028-8911-ae86baca4f96:NORMAL:127.0.0.1:43451|FINALIZED]]} size 0
   [junit4]   2> 3398909 INFO  (IPC Server handler 8 on 52272) [    ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43451 is added to blk_1073741826_1002{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-457882e2-9a3c-4f09-9d8f-fe49dc41e407:NORMAL:127.0.0.1:60661|RBW], ReplicaUC[[DISK]DS-850c8b69-51e8-42d5-934d-63fadfd5ac8a:NORMAL:127.0.0.1:43451|RBW]]} size 0
   [junit4]   2> 3398912 INFO  (IPC Server handler 6 on 52272) [    ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:60661 is added to blk_1073741825_1001{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-c913d72d-e2f6-4028-8911-ae86baca4f96:NORMAL:127.0.0.1:43451|FINALIZED], ReplicaUC[[DISK]DS-691c7a32-7c0b-4b27-8670-e0a995751ca5:NORMAL:127.0.0.1:60661|FINALIZED]]} size 0
   [junit4]   2> 3398913 INFO  (IPC Server handler 2 on 52272) [    ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:60661 is added to blk_1073741826_1002{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-457882e2-9a3c-4f09-9d8f-fe49dc41e407:NORMAL:127.0.0.1:60661|RBW], ReplicaUC[[DISK]DS-850c8b69-51e8-42d5-934d-63fadfd5ac8a:NORMAL:127.0.0.1:43451|RBW]]} size 0
   [junit4]   2> 3399079 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.HdfsUpdateLog
   [junit4]   2> 3399079 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.HdfsUpdateLog
   [junit4]   2> 3399079 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
   [junit4]   2> 3399079 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
   [junit4]   2> 3399079 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.u.HdfsUpdateLog Initializing HdfsUpdateLog: tlogDfsReplication=3
   [junit4]   2> 3399079 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.u.HdfsUpdateLog Initializing HdfsUpdateLog: tlogDfsReplication=3
   [junit4]   2> 3399101 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.u.CommitTracker Hard AutoCommit: disabled
   [junit4]   2> 3399101 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.u.CommitTracker Soft AutoCommit: disabled
   [junit4]   2> 3399108 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
   [junit4]   2> 3399108 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
   [junit4]   2> 3399127 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.s.SolrIndexSearcher Opening [Searcher@56a8a76d[recoverytest_shard1_replica_n2] main]
   [junit4]   2> 3399130 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
   [junit4]   2> 3399131 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
   [junit4]   2> 3399131 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.h.ReplicationHandler Commits will be reserved for  10000
   [junit4]   2> 3399134 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1569602833095852032
   [junit4]   2> 3399136 INFO  (searcherExecutor-8157-thread-1-processing-n:127.0.0.1:34679_solr x:recoverytest_shard1_replica_n2 s:shard1 c:recoverytest) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.SolrCore [recoverytest_shard1_replica_n2] Registered new searcher Searcher@56a8a76d[recoverytest_shard1_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
   [junit4]   2> 3399139 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@39a409b9[recoverytest_shard1_replica_n1] main]
   [junit4]   2> 3399142 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
   [junit4]   2> 3399143 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
   [junit4]   2> 3399144 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.h.ReplicationHandler Commits will be reserved for  10000
   [junit4]   2> 3399145 INFO  (searcherExecutor-8156-thread-1-processing-n:127.0.0.1:34068_solr x:recoverytest_shard1_replica_n1 s:shard1 c:recoverytest) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.c.SolrCore [recoverytest_shard1_replica_n1] Registered new searcher Searcher@39a409b9[recoverytest_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
   [junit4]   2> 3399147 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1569602833109483520
   [junit4]   2> 3399150 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.ShardLeaderElectionContext Waiting until we see more replicas up for shard shard1: total=2 found=1 timeoutin=9999ms
   [junit4]   2> 3399255 INFO  (zkCallback-3617-thread-1-processing-n:127.0.0.1:34068_solr) [n:127.0.0.1:34068_solr    ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/recoverytest/state.json] for collection [recoverytest] has occurred - updating... (live nodes size: [2])
   [junit4]   2> 3399255 INFO  (zkCallback-3618-thread-2-processing-n:127.0.0.1:34679_solr) [n:127.0.0.1:34679_solr    ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/recoverytest/state.json] for collection [recoverytest] has occurred - updating... (live nodes size: [2])
   [junit4]   2> 3399651 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
   [junit4]   2> 3399651 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
   [junit4]   2> 3399651 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/
   [junit4]   2> 3399652 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.u.PeerSync PeerSync: core=recoverytest_shard1_replica_n2 url=http://127.0.0.1:34679/solr START replicas=[http://127.0.0.1:34068/solr/recoverytest_shard1_replica_n1/] nUpdates=100
   [junit4]   2> 3399652 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.u.PeerSync PeerSync: core=recoverytest_shard1_replica_n2 url=http://127.0.0.1:34679/solr DONE.  We have no versions.  sync failed.
   [junit4]   2> 3399655 INFO  (qtp1324117838-32441) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.c.S.Request [recoverytest_shard1_replica_n1]  webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=1
   [junit4]   2> 3399655 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate
   [junit4]   2> 3399655 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.ShardLeaderElectionContext We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
   [junit4]   2> 3399656 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
   [junit4]   2> 3399660 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/ shard1
   [junit4]   2> 3399765 INFO  (zkCallback-3617-thread-1-processing-n:127.0.0.1:34068_solr) [n:127.0.0.1:34068_solr    ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/recoverytest/state.json] for collection [recoverytest] has occurred - updating... (live nodes size: [2])
   [junit4]   2> 3399765 INFO  (zkCallback-3618-thread-2-processing-n:127.0.0.1:34679_solr) [n:127.0.0.1:34679_solr    ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/recoverytest/state.json] for collection [recoverytest] has occurred - updating... (live nodes size: [2])
   [junit4]   2> 3399811 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.c.ZkController I am the leader, no recovery necessary
   [junit4]   2> 3399814 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n2] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=recoverytest_shard1_replica_n2&action=CREATE&numShards=1&collection=recoverytest&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=2230
   [junit4]   2> 3399917 INFO  (zkCallback-3617-thread-1-processing-n:127.0.0.1:34068_solr) [n:127.0.0.1:34068_solr    ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/recoverytest/state.json] for collection [recoverytest] has occurred - updating... (live nodes size: [2])
   [junit4]   2> 3399917 INFO  (zkCallback-3618-thread-2-processing-n:127.0.0.1:34679_solr) [n:127.0.0.1:34679_solr    ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/recoverytest/state.json] for collection [recoverytest] has occurred - updating... (live nodes size: [2])
   [junit4]   2> 3400159 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1  x:recoverytest_shard1_replica_n1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=recoverytest_shard1_replica_n1&action=CREATE&numShards=1&collection=recoverytest&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=2577
   [junit4]   2> 3400166 INFO  (qtp1324117838-32435) [n:127.0.0.1:34068_solr    ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas
   [junit4]   2> 3400268 INFO  (zkCallback-3618-thread-2-processing-n:127.0.0.1:34679_solr) [n:127.0.0.1:34679_solr    ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/recoverytest/state.json] for collection [recoverytest] has occurred - updating... (live nodes size: [2])
   [junit4]   2> 3400268 INFO  (zkCallback-3617-thread-1-processing-n:127.0.0.1:34068_solr) [n:127.0.0.1:34068_solr    ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/recoverytest/state.json] for collection [recoverytest] has occurred - updating... (live nodes size: [2])
   [junit4]   2> 3401166 INFO  (qtp1324117838-32435) [n:127.0.0.1:34068_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=2&collection.configName=conf&maxShardsPerNode=1&name=recoverytest&nrtReplicas=2&action=CREATE&numShards=1&wt=javabin&version=2} status=0 QTime=3710
   [junit4]   2> 3401168 INFO  (TEST-HdfsRecoveryZkTest.test-seed#[19F448DC1133CDE]) [    ] o.a.s.c.RecoveryZkTest Indexing 30000 documents
   [junit4]   2> 3401211 DEBUG (qtp837932411-32438) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.HdfsTransactionLog Opening new tlog hdfs tlog{file=hdfs://localhost:52272/data/recoverytest/core_node2/data/tlog/tlog.0000000000000000000 refcount=1}
   [junit4]   2> 3401246 DEBUG (qtp1324117838-32443) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.HdfsTransactionLog Opening new tlog hdfs tlog{file=hdfs://localhost:52272/data/recoverytest/core_node1/data/tlog/tlog.0000000000000000000 refcount=1}
   [junit4]   2> 3401263 INFO  (qtp1324117838-32429) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-0 (1569602835244384256)]} 0 30
   [junit4]   2> 3401263 INFO  (qtp837932411-32442) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-0 (1569602835244384256)]} 0 80
   [junit4]   2> 3401264 INFO  (qtp1324117838-32443) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-0 (1569602835241238528)]} 0 31
   [junit4]   2> 3401264 INFO  (qtp837932411-32438) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-0 (1569602835241238528)]} 0 83
   [junit4]   2> 3401266 INFO  (qtp1324117838-32441) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-1 (1569602835329318912)]} 0 0
   [junit4]   2> 3401266 INFO  (qtp837932411-32428) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-1 (1569602835329318912)]} 0 2
   [junit4]   2> 3401267 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-1 (1569602835330367488)]} 0 1
   [junit4]   2> 3401269 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-1 (1569602835330367488)]} 0 4
   [junit4]   2> 3401276 INFO  (qtp1324117838-32435) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{delete=[2-1 (-1569602835333513216)]} 0 5
   [junit4]   2> 3401277 INFO  (qtp837932411-32430) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{delete=[2-1 (-1569602835333513216)]} 0 9
   [junit4]   2> 3401283 INFO  (qtp1324117838-32431) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-2 (1569602835342950400)]} 0 5
   [junit4]   2> 3401284 INFO  (qtp837932411-32440) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-2 (1569602835342950400)]} 0 6
   [junit4]   2> 3401287 INFO  (qtp1324117838-32429) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{delete=[1-1 (-1569602835345047552)]} 0 7
   [junit4]   2> 3401287 INFO  (qtp837932411-32442) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-1 (-1569602835345047552)]} 0 8
   [junit4]   2> 3401289 INFO  (qtp1324117838-32443) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-3 (1569602835351339008)]} 0 3
   [junit4]   2> 3401290 INFO  (qtp837932411-32438) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-3 (1569602835351339008)]} 0 4
   [junit4]   2> 3401291 INFO  (qtp1324117838-32441) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-2 (1569602835354484736)]} 0 2
   [junit4]   2> 3401291 INFO  (qtp837932411-32428) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-2 (1569602835354484736)]} 0 3
   [junit4]   2> 3401295 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-4 (1569602835357630464)]} 0 1
   [junit4]   2> 3401295 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-4 (1569602835357630464)]} 0 3
   [junit4]   2> 3401295 INFO  (qtp1324117838-32435) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-3 (1569602835360776192)]} 0 0
   [junit4]   2> 3401295 INFO  (qtp837932411-32430) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-3 (1569602835360776192)]} 0 1
   [junit4]   2> 3401297 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-5 (1569602835361824768)]} 0 0
   [junit4]   2> 3401297 INFO  (qtp837932411-32440) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-5 (1569602835361824768)]} 0 1
   [junit4]   2> 3401297 INFO  (qtp1324117838-32429) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-4 (1569602835362873344)]} 0 0
   [junit4]   2> 3401297 INFO  (qtp837932411-32442) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-4 (1569602835362873344)]} 0 1
   [junit4]   2> 3401299 INFO  (qtp1324117838-32443) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-6 (1569602835363921920)]} 0 1
   [junit4]   2> 3401300 INFO  (qtp837932411-32438) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-6 (1569602835363921920)]} 0 2
   [junit4]   2> 3401301 INFO  (qtp1324117838-32441) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-5 (1569602835366019072)]} 0 1
   [junit4]   2> 3401301 INFO  (qtp837932411-32428) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-5 (1569602835366019072)]} 0 2
   [junit4]   2> 3401304 INFO  (qtp1324117838-32443) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{delete=[2-6 (-1569602835368116224)]} 0 1
   [junit4]   2> 3401304 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{delete=[2-6 (-1569602835368116224)]} 0 3
   [junit4]   2> 3401304 INFO  (qtp1324117838-32435) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-6 (1569602835369164800)]} 0 1
   [junit4]   2> 3401305 INFO  (qtp837932411-32430) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-6 (1569602835369164800)]} 0 3
   [junit4]   2> 3401309 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{delete=[1-6 (-1569602835372310529)]} 0 2
   [junit4]   2> 3401310 INFO  (qtp837932411-32442) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-6 (-1569602835372310529)]} 0 4
   [junit4]   2> 3401310 INFO  (qtp1324117838-32429) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-7 (1569602835372310528)]} 0 3
   [junit4]   2> 3401311 INFO  (qtp837932411-32440) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-7 (1569602835372310528)]} 0 5
   [junit4]   2> 3401313 INFO  (qtp1324117838-32431) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-7 (1569602835377553408)]} 0 1
   [junit4]   2> 3401313 INFO  (qtp837932411-32438) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-7 (1569602835377553408)]} 0 2
   [junit4]   2> 3401314 INFO  (qtp1324117838-32441) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-8 (1569602835378601984)]} 0 1
   [junit4]   2> 3401314 INFO  (qtp837932411-32428) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-8 (1569602835378601984)]} 0 2
   [junit4]   2> 3401315 INFO  (qtp1324117838-32443) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-8 (1569602835380699136)]} 0 1
   [junit4]   2> 3401315 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-8 (1569602835380699136)]} 0 2
   [junit4]   2> 3401315 INFO  (qtp1324117838-32435) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-9 (1569602835381747712)]} 0 0
   [junit4]   2> 3401316 INFO  (qtp837932411-32430) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-9 (1569602835381747712)]} 0 1
   [junit4]   2> 3401317 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-9 (1569602835383844864)]} 0 1
   [junit4]   2> 3401318 INFO  (qtp837932411-32442) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-9 (1569602835383844864)]} 0 1
   [junit4]   2> 3401318 INFO  (qtp1324117838-32429) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-10 (1569602835383844865)]} 0 0
   [junit4]   2> 3401318 INFO  (qtp837932411-32440) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-10 (1569602835383844865)]} 0 1
   [junit4]   2> 3401321 INFO  (qtp1324117838-32431) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-10 (1569602835385942016)]} 0 2
   [junit4]   2> 3401322 INFO  (qtp837932411-32438) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-10 (1569602835385942016)]} 0 3
   [junit4]   2> 3401322 INFO  (qtp1324117838-32441) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{delete=[2-8 (-1569602835386990592)]} 0 1
   [junit4]   2> 3401323 INFO  (qtp837932411-32440) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{delete=[2-8 (-1569602835386990592)]} 0 4
   [junit4]   2> 3401324 INFO  (qtp1324117838-32443) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{delete=[1-8 (-1569602835391184896)]} 0 0
   [junit4]   2> 3401324 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-8 (-1569602835391184896)]} 0 1
   [junit4]   2> 3401325 INFO  (qtp1324117838-32435) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-11 (1569602835391184897)]} 0 0
   [junit4]   2> 3401325 INFO  (qtp837932411-32430) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-11 (1569602835391184897)]} 0 1
   [junit4]   2> 3401326 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-11 (1569602835393282048)]} 0 1
   [junit4]   2> 3401326 INFO  (qtp837932411-32442) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-11 (1569602835393282048)]} 0 1
   [junit4]   2> 3401326 INFO  (qtp1324117838-32429) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{delete=[2-10 (-1569602835393282049)]} 0 0
   [junit4]   2> 3401327 INFO  (qtp837932411-32428) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{delete=[2-10 (-1569602835393282049)]} 0 1
   [junit4]   2> 3401328 INFO  (qtp1324117838-32431) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{delete=[1-10 (-1569602835395379200)]} 0 0
   [junit4]   2> 3401328 INFO  (qtp837932411-32438) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-10 (-1569602835395379200)]} 0 1
   [junit4]   2> 3401329 INFO  (qtp1324117838-32441) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-12 (1569602835395379201)]} 0 1
   [junit4]   2> 3401329 INFO  (qtp837932411-32440) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-12 (1569602835395379201)]} 0 1
   [junit4]   2> 3401331 INFO  (qtp1324117838-32443) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-12 (1569602835397476352)]} 0 1
   [junit4]   2> 3401331 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-12 (1569602835397476352)]} 0 1
   [junit4]   2> 3401331 INFO  (qtp1324117838-32435) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-13 (1569602835398524928)]} 0 0
   [junit4]   2> 3401331 INFO  (qtp837932411-32430) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-13 (1569602835398524928)]} 0 1
   [junit4]   2> 3401335 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-13 (1569602835399573504)]} 0 2
   [junit4]   2> 3401335 INFO  (qtp837932411-32442) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-13 (1569602835399573504)]} 0 3
   [junit4]   2> 3401335 INFO  (qtp1324117838-32429) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{delete=[2-11 (-1569602835400622080)]} 0 2
   [junit4]   2> 3401335 INFO  (qtp837932411-32428) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{delete=[2-11 (-1569602835400622080)]} 0 3
   [junit4]   2> 3401336 INFO  (qtp1324117838-32431) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{delete=[1-11 (-1569602835403767808)]} 0 0
   [junit4]   2> 3401337 INFO  (qtp837932411-32438) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-11 (-1569602835403767808)]} 0 1
   [junit4]   2> 3401337 INFO  (qtp1324117838-32441) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-14 (1569602835404816384)]} 0 0
   [junit4]   2> 3401338 INFO  (qtp837932411-32440) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-14 (1569602835404816384)]} 0 1
   [junit4]   2> 3401342 INFO  (qtp1324117838-32443) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-14 (1569602835405864960)]} 0 4
   [junit4]   2> 3401343 INFO  (qtp1324117838-32435) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{delete=[2-12 (-1569602835406913536)]} 0 4
   [junit4]   2> 3401343 INFO  (qtp837932411-32430) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{delete=[2-12 (-1569602835406913536)]} 0 5
   [junit4]   2> 3401345 INFO  (qtp837932411-32434) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-14 (1569602835405864960)]} 0 7
   [junit4]   2> 3401346 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-15 (1569602835414253568)]} 0 0
   [junit4]   2> 3401347 INFO  (qtp837932411-32442) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-15 (1569602835414253568)]} 0 1
   [junit4]   2> 3401348 INFO  (qtp1324117838-32429) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{delete=[1-12 (-1569602835415302144)]} 0 1
   [junit4]   2> 3401348 INFO  (qtp837932411-32428) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-12 (-1569602835415302144)]} 0 2
   [junit4]   2> 3401348 INFO  (qtp1324117838-32439) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[2-16 (1569602835416350720)]} 0 0
   [junit4]   2> 3401349 INFO  (qtp837932411-32438) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-16 (1569602835416350720)]} 0 1
   [junit4]   2> 3401350 INFO  (qtp1324117838-32441) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-15 (1569602835418447872)]} 0 0
   [junit4]   2> 3401351 INFO  (qtp837932411-32440) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-15 (1569602835418447872)]} 0 2
   [junit4]   2> 3401353 INFO  (qtp1324117838-32443) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{delete=[2-13 (-1569602835418447873)]} 0 3
   [junit4]   2> 3401353 INFO  (qtp1324117838-32435) [n:127.0.0.1:34068_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n1]  webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:34679/solr/recoverytest_shard1_replica_n2/&wt=javabin&version=2}{add=[1-16 (1569602835420545024)]} 0 1
   [junit4]   2> 3401353 INFO  (qtp837932411-32438) [n:127.0.0.1:34679_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica_n2] o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica_n2]  webapp=/solr path=/update params={wt=javabin&version=

[...truncated too long message...]

at org.apache.hadoop.hdfs.MiniDFSCluster.shutdown(MiniDFSCluster.java:1705)
   [junit4]   2> 	at org.apache.solr.cloud.hdfs.HdfsTestUtil.teardownClass(HdfsTestUtil.java:204)
   [junit4]   2> 	at org.apache.solr.cloud.hdfs.HdfsRecoveryZkTest.teardownClass(HdfsRecoveryZkTest.java:53)
   [junit4]   2> 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   [junit4]   2> 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
   [junit4]   2> 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
   [junit4]   2> 	at java.lang.reflect.Method.invoke(Method.java:498)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:870)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
   [junit4]   2> 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
   [junit4]   2> 	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
   [junit4]   2> 	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
   [junit4]   2> 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
   [junit4]   2> 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
   [junit4]   2> 	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
   [junit4]   2> 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
   [junit4]   2> 	at java.lang.Thread.run(Thread.java:745)
   [junit4]   2> Caused by: java.lang.NullPointerException
   [junit4]   2> 	at org.apache.hadoop.hdfs.server.blockmanagement.BlocksMap.size(BlocksMap.java:203)
   [junit4]   2> 	at org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.getTotalBlocks(BlockManager.java:3370)
   [junit4]   2> 	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getBlocksTotal(FSNamesystem.java:5729)
   [junit4]   2> 	... 54 more
   [junit4]   2> 3419795 INFO  (SUITE-HdfsRecoveryZkTest-seed#[19F448DC1133CDE]-worker) [    ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:39024 39024
   [junit4]   2> NOTE: leaving temporary files on disk at: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_19F448DC1133CDE-001
   [junit4]   2> Jun 08, 2017 2:45:29 AM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
   [junit4]   2> WARNING: Will linger awaiting termination of 35 leaked thread(s).
   [junit4]   2> NOTE: test params are: codec=Asserting(Lucene70): {rnd_b=PostingsFormat(name=Direct), _version_=PostingsFormat(name=Asserting), a_t=FSTOrd50, a_i=PostingsFormat(name=Direct), id=PostingsFormat(name=Direct)}, docValues:{}, maxPointsInLeafNode=38, maxMBSortInHeap=5.620767783290915, sim=RandomSimilarity(queryNorm=false): {}, locale=sl-SI, timezone=Europe/Astrakhan
   [junit4]   2> NOTE: Linux 3.13.0-88-generic amd64/Oracle Corporation 1.8.0_121 (64-bit)/cpus=4,threads=2,free=183574208,total=522715136
   [junit4]   2> NOTE: All tests run in this JVM: [TestSystemIdResolver, CdcrUpdateLogTest, MoreLikeThisHandlerTest, ClusterStateUpdateTest, JvmMetricsTest, MigrateRouteKeyTest, DirectSolrConnectionTest, TestFieldCache, BigEndianAscendingWordDeserializerTest, DocumentBuilderTest, TestQueryTypes, TestDistribDocBasedVersion, TestFiltering, TestDelegationWithHadoopAuth, OverseerRolesTest, OverriddenZkACLAndCredentialsProvidersTest, DistributedFacetPivotLargeTest, TestLegacyTerms, PreAnalyzedUpdateProcessorTest, ZkControllerTest, TestLegacyField, DistanceFunctionTest, TestAddFieldRealTimeGet, SolrMetricManagerTest, TestFieldCacheSortRandom, ReplaceNodeTest, TestUseDocValuesAsStored, DistanceUnitsTest, TestOnReconnectListenerSupport, DocExpirationUpdateProcessorFactoryTest, TestSweetSpotSimilarityFactory, TestJavabinTupleStreamParser, SOLR749Test, TestReRankQParserPlugin, HttpSolrCallGetCoreTest, TestExportWriter, TestBulkSchemaAPI, SpellCheckCollatorTest, TestRawTransformer, VMParamsZkACLAndCredentialsProvidersTest, TestSolrJ, TestOverriddenPrefixQueryForCustomFieldType, WordBreakSolrSpellCheckerTest, BadCopyFieldTest, AssignTest, BasicAuthStandaloneTest, TestSSLRandomization, TestRandomFlRTGCloud, DistributedIntervalFacetingTest, TestStressVersions, TestHdfsCloudBackupRestore, SchemaVersionSpecificBehaviorTest, IndexSchemaTest, TestUninvertingReader, TestCloudSchemaless, TestNonDefinedSimilarityFactory, SimpleMLTQParserTest, SpellCheckComponentTest, TestComplexPhraseQParserPlugin, UpdateRequestProcessorFactoryTest, QueryParsingTest, InfixSuggestersTest, SampleTest, AlternateDirectoryTest, ZkCLITest, CollectionsAPIDistributedZkTest, MergeStrategyTest, CdcrBootstrapTest, BlockCacheTest, SolrGangliaReporterTest, ResourceLoaderTest, UninvertDocValuesMergePolicyTest, TestInfoStreamLogging, TestCharFilters, SolrSlf4jReporterTest, TermVectorComponentTest, TestSchemaVersionResource, ChaosMonkeySafeLeaderWithPullReplicasTest, DistributedVersionInfoTest, HttpPartitionTest, DistributedDebugComponentTest, TestConfigSetProperties, CSVRequestHandlerTest, DistribDocExpirationUpdateProcessorTest, DateRangeFieldTest, TestElisionMultitermQuery, TermsComponentTest, BadComponentTest, TestCursorMarkWithoutUniqueKey, TestSortByMinMaxFunction, ChaosMonkeySafeLeaderTest, TestLegacyFieldCache, TestExactStatsCache, TestSolrCoreSnapshots, TestCloudNestedDocsSort, TestSolrCloudWithSecureImpersonation, TestJsonFacets, TestHdfsUpdateLog, TestFilteredDocIdSet, TestPostingsSolrHighlighter, TestManagedResource, DistributedTermsComponentTest, TestFieldResource, TestTestInjection, TestReplicaProperties, ConvertedLegacyTest, TestWordDelimiterFilterFactory, CdcrRequestHandlerTest, TestNumericRangeQuery64, SolrIndexSplitterTest, TestSimpleTrackingShardHandler, SystemInfoHandlerTest, SimplePostToolTest, TestPartialUpdateDeduplication, CreateCollectionCleanupTest, TestUpdate, UpdateLogTest, AtomicUpdateProcessorFactoryTest, TestSolr4Spatial2, IndexBasedSpellCheckerTest, MetricsHandlerTest, BasicDistributedZkTest, UnloadDistributedZkTest, OpenCloseCoreStressTest, TestRandomFaceting, ZkSolrClientTest, TestZkChroot, ShardRoutingCustomTest, TestDistributedGrouping, TestFaceting, TestHashPartitioner, DistributedSpellCheckComponentTest, TestRealTimeGet, TestStressReorder, TestJoin, SolrCmdDistributorTest, BadIndexSchemaTest, TestSort, BasicFunctionalityTest, TestIndexSearcher, HighlighterTest, SoftAutoCommitTest, XsltUpdateRequestHandlerTest, CacheHeaderTest, TestQueryUtils, TestWriterPerf, TestOmitPositions, TestValueSourceCache, FieldAnalysisRequestHandlerTest, IndexSchemaRuntimeFieldTest, RegexBoostProcessorTest, ReturnFieldsTest, TestCSVResponseWriter, UniqFieldsUpdateProcessorFactoryTest, PingRequestHandlerTest, HighlighterConfigTest, TestSolrIndexConfig, TestQuerySenderNoQuery, ResponseLogComponentTest, TestStressRecovery, TestEmbeddedSolrServerConstructors, TestEmbeddedSolrServerSchemaAPI, ConnectionReuseTest, CdcrVersionReplicationTest, CleanupOldIndexTest, CloudExitableDirectoryReaderTest, CollectionStateFormat2Test, CollectionTooManyReplicasTest, CollectionsAPIAsyncDistributedZkTest, DeleteReplicaTest, DistribCursorPagingTest, LeaderInitiatedRecoveryOnShardRestartTest, MissingSegmentRecoveryTest, MoveReplicaTest, OverseerCollectionConfigSetProcessorTest, PeerSyncReplicationTest, RecoveryAfterSoftCommitTest, RollingRestartTest, SharedFSAutoReplicaFailoverUtilsTest, SimpleCollectionCreateDeleteTest, SolrCloudExampleTest, SolrXmlInZkTest, TestAuthenticationFramework, TestCloudInspectUtil, TestCloudPseudoReturnFields, TestCloudRecovery, TestClusterProperties, TestCollectionAPI, TestLeaderElectionWithEmptyReplica, TestMiniSolrCloudCluster, TestSegmentSorting, TestSizeLimitedDistributedMap, TestSolrCloudWithDelegationTokens, TestSolrCloudWithKerberosAlt, TestStressCloudBlindAtomicUpdates, HdfsBasicDistributedZk2Test, HdfsNNFailoverTest, HdfsRecoverLeaseTest, HdfsRecoveryZkTest]
   [junit4] Completed [568/726 (1!)] on J1 in 35.20s, 1 test, 1 failure <<< FAILURES!

[...truncated 7964 lines...]
BUILD FAILED
/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/build.xml:783: The following error occurred while executing this line:
/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-master/checkout/build.xml:727: Some of the tests produced a heap dump, but did not fail. Maybe a suppressed OutOfMemoryError? Dumps created:
* java_pid31990.hprof

Total time: 269 minutes 10 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

Mime
View raw message