lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Policeman Jenkins Server <jenk...@thetaphi.de>
Subject [JENKINS] Lucene-Solr-7.x-MacOSX (64bit/jdk1.8.0) - Build # 222 - Still Failing!
Date Mon, 02 Oct 2017 12:25:36 GMT
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-7.x-MacOSX/222/
Java: 64bit/jdk1.8.0 -XX:-UseCompressedOops -XX:+UseSerialGC

2 tests failed.
FAILED:  org.apache.lucene.TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler

Error Message:


Stack Trace:
java.lang.AssertionError
	at __randomizedtesting.SeedInfo.seed([D853AFC32C37680:8A04875136E30C84]:0)
	at org.junit.Assert.fail(Assert.java:92)
	at org.junit.Assert.assertTrue(Assert.java:43)
	at org.junit.Assert.assertTrue(Assert.java:54)
	at org.apache.lucene.TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler(TestMergeSchedulerExternal.java:147)
	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:1737)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:934)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:970)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:984)
	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:943)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890)
	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:748)


FAILED:  org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollectionsAPI

Error Message:
Error from server at http://127.0.0.1:53192/solr/awhollynewcollection_0_shard2_replica_n2: ClusterState says we are the leader (http://127.0.0.1:53192/solr/awhollynewcollection_0_shard2_replica_n2), but locally we don't think so. Request came from null

Stack Trace:
org.apache.solr.client.solrj.impl.CloudSolrClient$RouteException: Error from server at http://127.0.0.1:53192/solr/awhollynewcollection_0_shard2_replica_n2: ClusterState says we are the leader (http://127.0.0.1:53192/solr/awhollynewcollection_0_shard2_replica_n2), but locally we don't think so. Request came from null
	at __randomizedtesting.SeedInfo.seed([AC327EC2E4BDF7B2:E4470A76E28ED827]:0)
	at org.apache.solr.client.solrj.impl.CloudSolrClient.directUpdate(CloudSolrClient.java:539)
	at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(CloudSolrClient.java:993)
	at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:862)
	at org.apache.solr.client.solrj.impl.CloudSolrClient.request(CloudSolrClient.java:793)
	at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:178)
	at org.apache.solr.client.solrj.request.UpdateRequest.commit(UpdateRequest.java:233)
	at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollectionsAPI(CollectionsAPIDistributedZkTest.java:459)
	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:1737)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:934)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:970)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:984)
	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:943)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890)
	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:748)
Caused by: org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at http://127.0.0.1:53192/solr/awhollynewcollection_0_shard2_replica_n2: ClusterState says we are the leader (http://127.0.0.1:53192/solr/awhollynewcollection_0_shard2_replica_n2), but locally we don't think so. Request came from null
	at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:627)
	at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:253)
	at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:242)
	at org.apache.solr.client.solrj.impl.LBHttpSolrClient.doRequest(LBHttpSolrClient.java:483)
	at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:413)
	at org.apache.solr.client.solrj.impl.CloudSolrClient.lambda$directUpdate$0(CloudSolrClient.java:516)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	... 1 more




Build Log:
[...truncated 249 lines...]
   [junit4] Suite: org.apache.lucene.TestMergeSchedulerExternal
   [junit4]   1> TEST FAILED; IW infoStream output:
   [junit4]   1> IFD 0 [2017-10-02T11:05:00.424Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: init: current segments file is "segments"; deletionPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy@6a5ba0f4
   [junit4]   1> IFD 0 [2017-10-02T11:05:00.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now checkpoint "" [0 segments ; isCommit = false]
   [junit4]   1> IFD 0 [2017-10-02T11:05:00.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to checkpoint
   [junit4]   1> IW 0 [2017-10-02T11:05:00.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: init: create=true
   [junit4]   1> IW 0 [2017-10-02T11:05:00.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 
   [junit4]   1> dir=MockDirectoryWrapper(RAMDirectory@659905c5 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@749590d1)
   [junit4]   1> index=
   [junit4]   1> version=7.1.0
   [junit4]   1> analyzer=org.apache.lucene.analysis.MockAnalyzer
   [junit4]   1> ramBufferSizeMB=-1.0
   [junit4]   1> maxBufferedDocs=2
   [junit4]   1> mergedSegmentWarmer=null
   [junit4]   1> delPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy
   [junit4]   1> commit=null
   [junit4]   1> openMode=CREATE_OR_APPEND
   [junit4]   1> similarity=org.apache.lucene.search.similarities.RandomSimilarity
   [junit4]   1> mergeScheduler=MyMergeScheduler: maxThreadCount=-1, maxMergeCount=-1, ioThrottle=true
   [junit4]   1> codec=Asserting(Lucene70): {}, docValues:{}, maxPointsInLeafNode=1073, maxMBSortInHeap=7.924571263640305
   [junit4]   1> infoStream=org.apache.lucene.util.PrintStreamInfoStream
   [junit4]   1> mergePolicy=[LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=42, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
   [junit4]   1> indexerThreadPool=org.apache.lucene.index.DocumentsWriterPerThreadPool@40128d59
   [junit4]   1> readerPooling=true
   [junit4]   1> perThreadHardLimitMB=1945
   [junit4]   1> useCompoundFile=false
   [junit4]   1> commitOnClose=true
   [junit4]   1> indexSort=null
   [junit4]   1> writer=org.apache.lucene.index.IndexWriter@13b29a56
   [junit4]   1> 
   [junit4]   1> IW 0 [2017-10-02T11:05:00.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: MMapDirectory.UNMAP_SUPPORTED=true
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.441Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush postings as segment _0 numDocs=2
   [junit4]   1> IW 0 [2017-10-02T11:05:00.441Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write norms
   [junit4]   1> IW 0 [2017-10-02T11:05:00.441Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write docValues
   [junit4]   1> IW 0 [2017-10-02T11:05:00.441Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write points
   [junit4]   1> IW 0 [2017-10-02T11:05:00.447Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 5 msec to finish stored fields
   [junit4]   1> IW 0 [2017-10-02T11:05:00.465Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 18 msec to write postings and finish vectors
   [junit4]   1> IW 0 [2017-10-02T11:05:00.490Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 24 msec to write fieldInfos
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.490Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has 0 deleted docs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.490Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.490Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushedFiles=[_0_LuceneVarGapDocFreqInterval_0.tiv, _0_LuceneVarGapDocFreqInterval_0.tib, _0.fdx, _0.fdt, _0_LuceneVarGapDocFreqInterval_0.doc, _0.fnm]
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.490Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed codec=Asserting(Lucene70): {id=PostingsFormat(name=LuceneVarGapDocFreqInterval)}, docValues:{}, maxPointsInLeafNode=1073, maxMBSortInHeap=7.924571263640305
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.531Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed: segment=_0 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=2,661.36
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.575Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush time 134.286437 msec
   [junit4]   1> DW 0 [2017-10-02T11:05:00.576Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment seg-private updates=null
   [junit4]   1> IW 0 [2017-10-02T11:05:00.576Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment _0(7.1.0):C2
   [junit4]   1> BD 0 [2017-10-02T11:05:00.576Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: finished packet delGen=1 now completedDelGen=1
   [junit4]   1> IW 0 [2017-10-02T11:05:00.576Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publish sets newSegment delGen=1 seg=_0(7.1.0):C2
   [junit4]   1> IFD 0 [2017-10-02T11:05:00.576Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now checkpoint "_0(7.1.0):C2" [1 segments ; isCommit = false]
   [junit4]   1> IFD 0 [2017-10-02T11:05:00.576Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to checkpoint
   [junit4]   1> LMP 0 [2017-10-02T11:05:00.576Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: findMerges: 1 segments
   [junit4]   1> LMP 0 [2017-10-02T11:05:00.642Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_0(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:00.642Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   level -1.0 to 3.1085649: 1 segments
   [junit4]   1> MS 0 [2017-10-02T11:05:00.643Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: initDynamicDefaults spins=false maxThreadCount=1 maxMergeCount=6
   [junit4]   1> MS 0 [2017-10-02T11:05:00.643Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now merge
   [junit4]   1> MS 0 [2017-10-02T11:05:00.643Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   index: _0(7.1.0):C2
   [junit4]   1> MS 0 [2017-10-02T11:05:00.643Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   no more merges pending; now return
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.649Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush postings as segment _1 numDocs=2
   [junit4]   1> IW 0 [2017-10-02T11:05:00.649Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write norms
   [junit4]   1> IW 0 [2017-10-02T11:05:00.649Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write docValues
   [junit4]   1> IW 0 [2017-10-02T11:05:00.649Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write points
   [junit4]   1> IW 0 [2017-10-02T11:05:00.654Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 4 msec to finish stored fields
   [junit4]   1> IW 0 [2017-10-02T11:05:00.681Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 27 msec to write postings and finish vectors
   [junit4]   1> IW 0 [2017-10-02T11:05:00.705Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 23 msec to write fieldInfos
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.705Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has 0 deleted docs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.705Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.705Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushedFiles=[_1_LuceneVarGapDocFreqInterval_0.tib, _1_LuceneVarGapDocFreqInterval_0.doc, _1.fdx, _1_LuceneVarGapDocFreqInterval_0.tiv, _1.fnm, _1.fdt]
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.705Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed codec=Asserting(Lucene70): {id=PostingsFormat(name=LuceneVarGapDocFreqInterval)}, docValues:{}, maxPointsInLeafNode=1073, maxMBSortInHeap=7.924571263640305
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.726Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed: segment=_1 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=2,661.36
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.733Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush time 83.845435 msec
   [junit4]   1> DW 0 [2017-10-02T11:05:00.733Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment seg-private updates=null
   [junit4]   1> IW 0 [2017-10-02T11:05:00.733Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment _1(7.1.0):C2
   [junit4]   1> BD 0 [2017-10-02T11:05:00.733Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: finished packet delGen=2 now completedDelGen=2
   [junit4]   1> IW 0 [2017-10-02T11:05:00.733Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publish sets newSegment delGen=2 seg=_1(7.1.0):C2
   [junit4]   1> IFD 0 [2017-10-02T11:05:00.733Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now checkpoint "_0(7.1.0):C2 _1(7.1.0):C2" [2 segments ; isCommit = false]
   [junit4]   1> IFD 0 [2017-10-02T11:05:00.733Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to checkpoint
   [junit4]   1> LMP 0 [2017-10-02T11:05:00.733Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: findMerges: 2 segments
   [junit4]   1> LMP 0 [2017-10-02T11:05:00.733Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_0(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:00.779Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_1(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:00.779Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   level -1.0 to 3.1085649: 2 segments
   [junit4]   1> MS 0 [2017-10-02T11:05:00.779Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now merge
   [junit4]   1> MS 0 [2017-10-02T11:05:00.779Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   index: _0(7.1.0):C2 _1(7.1.0):C2
   [junit4]   1> MS 0 [2017-10-02T11:05:00.779Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   no more merges pending; now return
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.793Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush postings as segment _2 numDocs=2
   [junit4]   1> IW 0 [2017-10-02T11:05:00.793Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write norms
   [junit4]   1> IW 0 [2017-10-02T11:05:00.793Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write docValues
   [junit4]   1> IW 0 [2017-10-02T11:05:00.793Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write points
   [junit4]   1> IW 0 [2017-10-02T11:05:00.797Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 4 msec to finish stored fields
   [junit4]   1> IW 0 [2017-10-02T11:05:00.848Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 50 msec to write postings and finish vectors
   [junit4]   1> IW 0 [2017-10-02T11:05:00.852Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 4 msec to write fieldInfos
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.852Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has 0 deleted docs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.852Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.852Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushedFiles=[_2_LuceneVarGapDocFreqInterval_0.tiv, _2_LuceneVarGapDocFreqInterval_0.tib, _2.fdt, _2.fnm, _2.fdx, _2_LuceneVarGapDocFreqInterval_0.doc]
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.852Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed codec=Asserting(Lucene70): {id=PostingsFormat(name=LuceneVarGapDocFreqInterval)}, docValues:{}, maxPointsInLeafNode=1073, maxMBSortInHeap=7.924571263640305
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.877Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed: segment=_2 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=2,661.36
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.925Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush time 132.096039 msec
   [junit4]   1> DW 0 [2017-10-02T11:05:00.925Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment seg-private updates=null
   [junit4]   1> IW 0 [2017-10-02T11:05:00.925Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment _2(7.1.0):C2
   [junit4]   1> BD 0 [2017-10-02T11:05:00.925Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: finished packet delGen=3 now completedDelGen=3
   [junit4]   1> IW 0 [2017-10-02T11:05:00.925Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publish sets newSegment delGen=3 seg=_2(7.1.0):C2
   [junit4]   1> IFD 0 [2017-10-02T11:05:00.925Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now checkpoint "_0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2" [3 segments ; isCommit = false]
   [junit4]   1> IFD 0 [2017-10-02T11:05:00.925Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to checkpoint
   [junit4]   1> LMP 0 [2017-10-02T11:05:00.925Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: findMerges: 3 segments
   [junit4]   1> LMP 0 [2017-10-02T11:05:00.925Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_0(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:00.925Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_1(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:00.947Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_2(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:00.947Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   level -1.0 to 3.1085649: 3 segments
   [junit4]   1> MS 0 [2017-10-02T11:05:00.947Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now merge
   [junit4]   1> MS 0 [2017-10-02T11:05:00.947Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   index: _0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2
   [junit4]   1> MS 0 [2017-10-02T11:05:00.947Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   no more merges pending; now return
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.953Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush postings as segment _3 numDocs=2
   [junit4]   1> IW 0 [2017-10-02T11:05:00.953Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write norms
   [junit4]   1> IW 0 [2017-10-02T11:05:00.953Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write docValues
   [junit4]   1> IW 0 [2017-10-02T11:05:00.953Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write points
   [junit4]   1> IW 0 [2017-10-02T11:05:00.957Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 4 msec to finish stored fields
   [junit4]   1> IW 0 [2017-10-02T11:05:00.981Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 23 msec to write postings and finish vectors
   [junit4]   1> IW 0 [2017-10-02T11:05:00.991Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 10 msec to write fieldInfos
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.991Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has 0 deleted docs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.991Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.991Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushedFiles=[_3.fdx, _3_LuceneVarGapDocFreqInterval_0.tib, _3_LuceneVarGapDocFreqInterval_0.tiv, _3.fnm, _3_LuceneVarGapDocFreqInterval_0.doc, _3.fdt]
   [junit4]   1> DWPT 0 [2017-10-02T11:05:00.991Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed codec=Asserting(Lucene70): {id=PostingsFormat(name=LuceneVarGapDocFreqInterval)}, docValues:{}, maxPointsInLeafNode=1073, maxMBSortInHeap=7.924571263640305
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.004Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed: segment=_3 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=2,661.36
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.009Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush time 56.830786 msec
   [junit4]   1> DW 0 [2017-10-02T11:05:01.009Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment seg-private updates=null
   [junit4]   1> IW 0 [2017-10-02T11:05:01.010Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment _3(7.1.0):C2
   [junit4]   1> BD 0 [2017-10-02T11:05:01.010Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: finished packet delGen=4 now completedDelGen=4
   [junit4]   1> IW 0 [2017-10-02T11:05:01.010Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publish sets newSegment delGen=4 seg=_3(7.1.0):C2
   [junit4]   1> IFD 0 [2017-10-02T11:05:01.010Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now checkpoint "_0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2" [4 segments ; isCommit = false]
   [junit4]   1> IFD 0 [2017-10-02T11:05:01.010Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to checkpoint
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.010Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: findMerges: 4 segments
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.010Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_0(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.010Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_1(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.010Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_2(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.013Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_3(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.013Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   level -1.0 to 3.1085649: 4 segments
   [junit4]   1> MS 0 [2017-10-02T11:05:01.013Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now merge
   [junit4]   1> MS 0 [2017-10-02T11:05:01.013Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   index: _0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2
   [junit4]   1> MS 0 [2017-10-02T11:05:01.013Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   no more merges pending; now return
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush postings as segment _4 numDocs=2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write norms
   [junit4]   1> IW 0 [2017-10-02T11:05:01.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write docValues
   [junit4]   1> IW 0 [2017-10-02T11:05:01.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write points
   [junit4]   1> IW 0 [2017-10-02T11:05:01.041Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 14 msec to finish stored fields
   [junit4]   1> IW 0 [2017-10-02T11:05:01.073Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 31 msec to write postings and finish vectors
   [junit4]   1> IW 0 [2017-10-02T11:05:01.081Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 7 msec to write fieldInfos
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.081Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has 0 deleted docs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.081Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.081Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushedFiles=[_4.fdt, _4.fnm, _4_LuceneVarGapDocFreqInterval_0.doc, _4_LuceneVarGapDocFreqInterval_0.tib, _4.fdx, _4_LuceneVarGapDocFreqInterval_0.tiv]
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.081Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed codec=Asserting(Lucene70): {id=PostingsFormat(name=LuceneVarGapDocFreqInterval)}, docValues:{}, maxPointsInLeafNode=1073, maxMBSortInHeap=7.924571263640305
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.081Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed: segment=_4 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=2,661.36
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.088Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush time 61.461512 msec
   [junit4]   1> DW 0 [2017-10-02T11:05:01.088Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment seg-private updates=null
   [junit4]   1> IW 0 [2017-10-02T11:05:01.088Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment _4(7.1.0):C2
   [junit4]   1> BD 0 [2017-10-02T11:05:01.088Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: finished packet delGen=5 now completedDelGen=5
   [junit4]   1> IW 0 [2017-10-02T11:05:01.088Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publish sets newSegment delGen=5 seg=_4(7.1.0):C2
   [junit4]   1> IFD 0 [2017-10-02T11:05:01.088Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now checkpoint "_0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2" [5 segments ; isCommit = false]
   [junit4]   1> IFD 0 [2017-10-02T11:05:01.088Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to checkpoint
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.088Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: findMerges: 5 segments
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.088Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_0(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.088Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_1(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.088Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_2(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.088Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_3(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.089Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_4(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.089Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   level -1.0 to 3.1085649: 5 segments
   [junit4]   1> MS 0 [2017-10-02T11:05:01.089Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now merge
   [junit4]   1> MS 0 [2017-10-02T11:05:01.089Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   index: _0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2
   [junit4]   1> MS 0 [2017-10-02T11:05:01.089Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   no more merges pending; now return
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.091Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush postings as segment _5 numDocs=2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.091Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write norms
   [junit4]   1> IW 0 [2017-10-02T11:05:01.091Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write docValues
   [junit4]   1> IW 0 [2017-10-02T11:05:01.091Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write points
   [junit4]   1> IW 0 [2017-10-02T11:05:01.094Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 2 msec to finish stored fields
   [junit4]   1> IW 0 [2017-10-02T11:05:01.122Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 27 msec to write postings and finish vectors
   [junit4]   1> IW 0 [2017-10-02T11:05:01.127Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 4 msec to write fieldInfos
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.127Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has 0 deleted docs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.127Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.127Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushedFiles=[_5.fnm, _5_LuceneVarGapDocFreqInterval_0.tib, _5.fdt, _5_LuceneVarGapDocFreqInterval_0.tiv, _5_LuceneVarGapDocFreqInterval_0.doc, _5.fdx]
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.127Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed codec=Asserting(Lucene70): {id=PostingsFormat(name=LuceneVarGapDocFreqInterval)}, docValues:{}, maxPointsInLeafNode=1073, maxMBSortInHeap=7.924571263640305
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.130Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed: segment=_5 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=2,661.36
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.138Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush time 46.314564 msec
   [junit4]   1> DW 0 [2017-10-02T11:05:01.138Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment seg-private updates=null
   [junit4]   1> IW 0 [2017-10-02T11:05:01.138Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment _5(7.1.0):C2
   [junit4]   1> BD 0 [2017-10-02T11:05:01.138Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: finished packet delGen=6 now completedDelGen=6
   [junit4]   1> IW 0 [2017-10-02T11:05:01.138Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publish sets newSegment delGen=6 seg=_5(7.1.0):C2
   [junit4]   1> IFD 0 [2017-10-02T11:05:01.138Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now checkpoint "_0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2" [6 segments ; isCommit = false]
   [junit4]   1> IFD 0 [2017-10-02T11:05:01.138Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to checkpoint
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.138Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: findMerges: 6 segments
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.138Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_0(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.138Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_1(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.138Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_2(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.138Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_3(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.138Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_4(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.140Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_5(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.140Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   level -1.0 to 3.1085649: 6 segments
   [junit4]   1> MS 0 [2017-10-02T11:05:01.140Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now merge
   [junit4]   1> MS 0 [2017-10-02T11:05:01.140Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   index: _0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2
   [junit4]   1> MS 0 [2017-10-02T11:05:01.140Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   no more merges pending; now return
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.143Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush postings as segment _6 numDocs=2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.143Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write norms
   [junit4]   1> IW 0 [2017-10-02T11:05:01.143Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write docValues
   [junit4]   1> IW 0 [2017-10-02T11:05:01.143Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write points
   [junit4]   1> IW 0 [2017-10-02T11:05:01.149Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 6 msec to finish stored fields
   [junit4]   1> IW 0 [2017-10-02T11:05:01.169Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 20 msec to write postings and finish vectors
   [junit4]   1> IW 0 [2017-10-02T11:05:01.174Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 5 msec to write fieldInfos
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.175Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has 0 deleted docs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.175Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.175Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushedFiles=[_6_LuceneVarGapDocFreqInterval_0.tiv, _6.fdt, _6_LuceneVarGapDocFreqInterval_0.doc, _6.fnm, _6.fdx, _6_LuceneVarGapDocFreqInterval_0.tib]
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.175Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed codec=Asserting(Lucene70): {id=PostingsFormat(name=LuceneVarGapDocFreqInterval)}, docValues:{}, maxPointsInLeafNode=1073, maxMBSortInHeap=7.924571263640305
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.189Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed: segment=_6 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=2,661.36
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.198Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush time 55.443249 msec
   [junit4]   1> DW 0 [2017-10-02T11:05:01.198Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment seg-private updates=null
   [junit4]   1> IW 0 [2017-10-02T11:05:01.198Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment _6(7.1.0):C2
   [junit4]   1> BD 0 [2017-10-02T11:05:01.198Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: finished packet delGen=7 now completedDelGen=7
   [junit4]   1> IW 0 [2017-10-02T11:05:01.199Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publish sets newSegment delGen=7 seg=_6(7.1.0):C2
   [junit4]   1> IFD 0 [2017-10-02T11:05:01.199Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now checkpoint "_0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2" [7 segments ; isCommit = false]
   [junit4]   1> IFD 0 [2017-10-02T11:05:01.199Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to checkpoint
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.199Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: findMerges: 7 segments
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.199Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_0(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.199Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_1(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.199Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_2(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.199Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_3(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.199Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_4(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.199Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_5(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_6(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   level -1.0 to 3.1085649: 7 segments
   [junit4]   1> MS 0 [2017-10-02T11:05:01.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now merge
   [junit4]   1> MS 0 [2017-10-02T11:05:01.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   index: _0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2
   [junit4]   1> MS 0 [2017-10-02T11:05:01.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   no more merges pending; now return
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.209Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush postings as segment _7 numDocs=2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.209Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write norms
   [junit4]   1> IW 0 [2017-10-02T11:05:01.209Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write docValues
   [junit4]   1> IW 0 [2017-10-02T11:05:01.209Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write points
   [junit4]   1> IW 0 [2017-10-02T11:05:01.213Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 4 msec to finish stored fields
   [junit4]   1> IW 0 [2017-10-02T11:05:01.232Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 18 msec to write postings and finish vectors
   [junit4]   1> IW 0 [2017-10-02T11:05:01.236Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 4 msec to write fieldInfos
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.236Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has 0 deleted docs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.236Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.236Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushedFiles=[_7_LuceneVarGapDocFreqInterval_0.doc, _7_LuceneVarGapDocFreqInterval_0.tib, _7.fnm, _7.fdt, _7_LuceneVarGapDocFreqInterval_0.tiv, _7.fdx]
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.236Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed codec=Asserting(Lucene70): {id=PostingsFormat(name=LuceneVarGapDocFreqInterval)}, docValues:{}, maxPointsInLeafNode=1073, maxMBSortInHeap=7.924571263640305
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.236Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed: segment=_7 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=2,661.36
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.245Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush time 36.610553 msec
   [junit4]   1> DW 0 [2017-10-02T11:05:01.245Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment seg-private updates=null
   [junit4]   1> IW 0 [2017-10-02T11:05:01.245Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment _7(7.1.0):C2
   [junit4]   1> BD 0 [2017-10-02T11:05:01.245Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: finished packet delGen=8 now completedDelGen=8
   [junit4]   1> IW 0 [2017-10-02T11:05:01.245Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publish sets newSegment delGen=8 seg=_7(7.1.0):C2
   [junit4]   1> IFD 0 [2017-10-02T11:05:01.246Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now checkpoint "_0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2 _7(7.1.0):C2" [8 segments ; isCommit = false]
   [junit4]   1> IFD 0 [2017-10-02T11:05:01.246Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to checkpoint
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.246Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: findMerges: 8 segments
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.246Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_0(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.246Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_1(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.246Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_2(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.246Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_3(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.246Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_4(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.246Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_5(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.246Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_6(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_7(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   level -1.0 to 3.1085649: 8 segments
   [junit4]   1> MS 0 [2017-10-02T11:05:01.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now merge
   [junit4]   1> MS 0 [2017-10-02T11:05:01.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   index: _0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2 _7(7.1.0):C2
   [junit4]   1> MS 0 [2017-10-02T11:05:01.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   no more merges pending; now return
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.257Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush postings as segment _8 numDocs=2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.257Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write norms
   [junit4]   1> IW 0 [2017-10-02T11:05:01.257Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write docValues
   [junit4]   1> IW 0 [2017-10-02T11:05:01.257Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write points
   [junit4]   1> IW 0 [2017-10-02T11:05:01.261Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 4 msec to finish stored fields
   [junit4]   1> IW 0 [2017-10-02T11:05:01.275Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 13 msec to write postings and finish vectors
   [junit4]   1> IW 0 [2017-10-02T11:05:01.280Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 4 msec to write fieldInfos
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.280Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has 0 deleted docs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.280Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.280Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushedFiles=[_8.fdx, _8.fdt, _8_LuceneVarGapDocFreqInterval_0.tiv, _8.fnm, _8_LuceneVarGapDocFreqInterval_0.tib, _8_LuceneVarGapDocFreqInterval_0.doc]
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.280Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed codec=Asserting(Lucene70): {id=PostingsFormat(name=LuceneVarGapDocFreqInterval)}, docValues:{}, maxPointsInLeafNode=1073, maxMBSortInHeap=7.924571263640305
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.280Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed: segment=_8 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=2,661.36
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush time 28.973195 msec
   [junit4]   1> DW 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment seg-private updates=null
   [junit4]   1> IW 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment _8(7.1.0):C2
   [junit4]   1> BD 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: finished packet delGen=9 now completedDelGen=9
   [junit4]   1> IW 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publish sets newSegment delGen=9 seg=_8(7.1.0):C2
   [junit4]   1> IFD 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now checkpoint "_0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2 _7(7.1.0):C2 _8(7.1.0):C2" [9 segments ; isCommit = false]
   [junit4]   1> IFD 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to checkpoint
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: findMerges: 9 segments
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_0(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_1(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_2(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_3(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_4(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_5(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_6(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.286Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_7(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.287Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_8(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.287Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   level -1.0 to 3.1085649: 9 segments
   [junit4]   1> MS 0 [2017-10-02T11:05:01.287Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now merge
   [junit4]   1> MS 0 [2017-10-02T11:05:01.288Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   index: _0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2 _7(7.1.0):C2 _8(7.1.0):C2
   [junit4]   1> MS 0 [2017-10-02T11:05:01.288Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   no more merges pending; now return
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.291Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush postings as segment _9 numDocs=2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.291Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write norms
   [junit4]   1> IW 0 [2017-10-02T11:05:01.291Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write docValues
   [junit4]   1> IW 0 [2017-10-02T11:05:01.291Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to write points
   [junit4]   1> IW 0 [2017-10-02T11:05:01.295Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 4 msec to finish stored fields
   [junit4]   1> IW 0 [2017-10-02T11:05:01.316Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 20 msec to write postings and finish vectors
   [junit4]   1> IW 0 [2017-10-02T11:05:01.321Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 5 msec to write fieldInfos
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.321Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has 0 deleted docs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.321Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.321Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushedFiles=[_9.fdx, _9_LuceneVarGapDocFreqInterval_0.tib, _9.fdt, _9_LuceneVarGapDocFreqInterval_0.doc, _9.fnm, _9_LuceneVarGapDocFreqInterval_0.tiv]
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.321Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed codec=Asserting(Lucene70): {id=PostingsFormat(name=LuceneVarGapDocFreqInterval)}, docValues:{}, maxPointsInLeafNode=1073, maxMBSortInHeap=7.924571263640305
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.324Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flushed: segment=_9 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=2,661.36
   [junit4]   1> DWPT 0 [2017-10-02T11:05:01.339Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: flush time 48.731388 msec
   [junit4]   1> DW 0 [2017-10-02T11:05:01.339Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment seg-private updates=null
   [junit4]   1> IW 0 [2017-10-02T11:05:01.339Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publishFlushedSegment _9(7.1.0):C2
   [junit4]   1> BD 0 [2017-10-02T11:05:01.339Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: finished packet delGen=10 now completedDelGen=10
   [junit4]   1> IW 0 [2017-10-02T11:05:01.339Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: publish sets newSegment delGen=10 seg=_9(7.1.0):C2
   [junit4]   1> IFD 0 [2017-10-02T11:05:01.339Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now checkpoint "_0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2 _7(7.1.0):C2 _8(7.1.0):C2 _9(7.1.0):C2" [10 segments ; isCommit = false]
   [junit4]   1> IFD 0 [2017-10-02T11:05:01.340Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: 0 msec to checkpoint
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.340Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: findMerges: 10 segments
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.340Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_0(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.340Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_1(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.340Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_2(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.340Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_3(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.340Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_4(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.340Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_5(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.340Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_6(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.340Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_7(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.340Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_8(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.343Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: seg=_9(7.1.0):C2 level=3.1085649 size=0.001 MB
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.343Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   level -1.0 to 3.1085649: 10 segments
   [junit4]   1> LMP 0 [2017-10-02T11:05:01.344Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   add merge=_0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2 _7(7.1.0):C2 _8(7.1.0):C2 _9(7.1.0):C2 start=0 end=10
   [junit4]   1> IW 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: add merge to pendingMerges: _0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2 _7(7.1.0):C2 _8(7.1.0):C2 _9(7.1.0):C2 [total 1 pending]
   [junit4]   1> IW 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: registerMerge merging= []
   [junit4]   1> IW 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: registerMerge info=_0(7.1.0):C2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: registerMerge info=_1(7.1.0):C2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: registerMerge info=_2(7.1.0):C2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: registerMerge info=_3(7.1.0):C2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: registerMerge info=_4(7.1.0):C2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: registerMerge info=_5(7.1.0):C2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: registerMerge info=_6(7.1.0):C2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: registerMerge info=_7(7.1.0):C2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: registerMerge info=_8(7.1.0):C2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: registerMerge info=_9(7.1.0):C2
   [junit4]   1> MS 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: now merge
   [junit4]   1> MS 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   index: _0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2 _7(7.1.0):C2 _8(7.1.0):C2 _9(7.1.0):C2
   [junit4]   1> MS 0 [2017-10-02T11:05:01.346Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   consider merge _0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2 _7(7.1.0):C2 _8(7.1.0):C2 _9(7.1.0):C2
   [junit4]   1> MS 0 [2017-10-02T11:05:01.348Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:     launch new thread [MyMergeThread]
   [junit4]   1> MS 0 [2017-10-02T11:05:01.348Z; MyMergeThread]:   merge thread: start
   [junit4]   1> BD 0 [2017-10-02T11:05:01.349Z; MyMergeThread]: waitApplyForMerge: 0 packets, 10 merging segments
   [junit4]   1> BD 0 [2017-10-02T11:05:01.349Z; MyMergeThread]: waitApply: no deletes to apply
   [junit4]   1> IW 0 [2017-10-02T11:05:01.349Z; MyMergeThread]: now apply deletes for 10 merging segments
   [junit4]   1> IW 0 [2017-10-02T11:05:01.350Z; MyMergeThread]: merge seg=_a _0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2 _7(7.1.0):C2 _8(7.1.0):C2 _9(7.1.0):C2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.350Z; MyMergeThread]: now merge
   [junit4]   1>   merge=_0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2 _7(7.1.0):C2 _8(7.1.0):C2 _9(7.1.0):C2
   [junit4]   1>   index=_0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2 _7(7.1.0):C2 _8(7.1.0):C2 _9(7.1.0):C2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.351Z; MyMergeThread]: merging _0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2 _7(7.1.0):C2 _8(7.1.0):C2 _9(7.1.0):C2
   [junit4]   1> IW 0 [2017-10-02T11:05:01.351Z; MyMergeThread]: TEST: now throw exc:
   [junit4]   1> java.io.IOException: now failing during merge
   [junit4]   1> 	at org.apache.lucene.TestMergeSchedulerExternal$FailOnlyOnMerge.eval(TestMergeSchedulerExternal.java:95)
   [junit4]   1> 	at org.apache.lucene.store.MockDirectoryWrapper.maybeThrowDeterministicException(MockDirectoryWrapper.java:1022)
   [junit4]   1> 	at org.apache.lucene.store.MockDirectoryWrapper.openInput(MockDirectoryWrapper.java:743)
   [junit4]   1> 	at org.apache.lucene.store.Directory.openChecksumInput(Directory.java:119)
   [junit4]   1> 	at org.apache.lucene.store.MockDirectoryWrapper.openChecksumInput(MockDirectoryWrapper.java:1072)
   [junit4]   1> 	at org.apache.lucene.codecs.lucene60.Lucene60FieldInfosFormat.read(Lucene60FieldInfosFormat.java:113)
   [junit4]   1> 	at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:107)
   [junit4]   1> 	at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:78)
   [junit4]   1> 	at org.apache.lucene.index.ReadersAndUpdates.getReader(ReadersAndUpdates.java:208)
   [junit4]   1> 	at org.apache.lucene.index.ReadersAndUpdates.getReaderForMerge(ReadersAndUpdates.java:836)
   [junit4]   1> 	at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4362)
   [junit4]   1> 	at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:4032)
   [junit4]   1> 	at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:624)
   [junit4]   1> 	at org.apache.lucene.TestMergeSchedulerExternal$MyMergeScheduler.doMerge(TestMergeSchedulerExternal.java:85)
   [junit4]   1> 	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:661)
   [junit4]   1> 
   [junit4]   1> IW 0 [2017-10-02T11:05:01.352Z; MyMergeThread]: handleMergeException: merge=_0(7.1.0):C2 _1(7.1.0):C2 _2(7.1.0):C2 _3(7.1.0):C2 _4(7.1.0):C2 _5(7.1.0):C2 _6(7.1.0):C2 _7(7.1.0):C2 _8(7.1.0):C2 _9(7.1.0):C2 exc=java.io.IOException: now failing during merge
   [junit4]   1> IW 0 [2017-10-02T11:05:01.352Z; MyMergeThread]: hit exception during merge
   [junit4]   1> IW 0 [2017-10-02T11:05:01.352Z; MyMergeThread]: hit tragic IOException inside merge
   [junit4]   1> IW 0 [2017-10-02T11:05:01.352Z; MyMergeThread]: rollback
   [junit4]   1> IW 0 [2017-10-02T11:05:01.352Z; MyMergeThread]: all running merges have aborted
   [junit4]   1> IW 0 [2017-10-02T11:05:01.352Z; MyMergeThread]: rollback: done finish merges
   [junit4]   1> MS 0 [2017-10-02T11:05:01.355Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]: updateMergeThreads ioThrottle=true targetMBPerSec=20.0 MB/sec
   [junit4]   1> merge thread MyMergeThread estSize=0.0 MB (written=0.0 MB) runTime=0.0s (stopped=0.0s, paused=0.0s) rate=unlimited
   [junit4]   1>   leave running at Infinity MB/sec
   [junit4]   1> MS 0 [2017-10-02T11:05:01.355Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[D853AFC32C37680]]:   no more merges pending; now return
   [junit4]   1> DW 0 [2017-10-02T11:05:01.355Z; MyMergeThread]: abort
   [junit4]   1> DW 0 [2017-10-02T11:05:01.355Z; MyMergeThread]: done abort success=true
   [junit4]   1> IW 0 [2017-10-02T11:05:01.355Z; MyMergeThread]: rollback: infos=
   [junit4]   1> IW 0 [2017-10-02T11:05:01.356Z; MyMergeThread]: TEST: now handleMergeException
   [junit4]   1> MS 0 [2017-10-02T11:05:01.356Z; MyMergeThread]: updateMergeThreads ioThrottle=true targetMBPerSec=20.0 MB/sec
   [junit4]   1> 
   [junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=TestMergeSchedulerExternal -Dtests.method=testSubclassConcurrentMergeScheduler -Dtests.seed=D853AFC32C37680 -Dtests.slow=true -Dtests.locale=zh-HK -Dtests.timezone=America/Buenos_Aires -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
   [junit4] FAILURE 1.01s J1 | TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler <<<
   [junit4]    > Throwable #1: java.lang.AssertionError
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([D853AFC32C37680:8A04875136E30C84]:0)
   [junit4]    > 	at org.apache.lucene.TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler(TestMergeSchedulerExternal.java:147)
   [junit4]    > 	at java.lang.Thread.run(Thread.java:748)
   [junit4]   2> NOTE: test params are: codec=Asserting(Lucene70): {id=PostingsFormat(name=LuceneVarGapDocFreqInterval)}, docValues:{}, maxPointsInLeafNode=1073, maxMBSortInHeap=7.924571263640305, sim=RandomSimilarity(queryNorm=false): {}, locale=zh-HK, timezone=America/Buenos_Aires
   [junit4]   2> NOTE: Mac OS X 10.11.6 x86_64/Oracle Corporation 1.8.0_144 (64-bit)/cpus=3,threads=1,free=42243016,total=54788096
   [junit4]   2> NOTE: All tests run in this JVM: [TestSpanMultiTermQueryWrapper, TestSimilarityBase, TestMergeSchedulerExternal]
   [junit4] Completed [9/454 (1!)] on J1 in 1.09s, 2 tests, 1 failure <<< FAILURES!

[...truncated 11806 lines...]
   [junit4] Suite: org.apache.solr.cloud.CollectionsAPIDistributedZkTest
   [junit4]   2> Creating dataDir: /Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_AC327EC2E4BDF7B2-001/init-core-data-001
   [junit4]   2> 481465 INFO  (SUITE-CollectionsAPIDistributedZkTest-seed#[AC327EC2E4BDF7B2]-worker) [    ] o.a.s.SolrTestCaseJ4 Using TrieFields (NUMERIC_POINTS_SYSPROP=false) w/NUMERIC_DOCVALUES_SYSPROP=false
   [junit4]   2> 481466 INFO  (SUITE-CollectionsAPIDistributedZkTest-seed#[AC327EC2E4BDF7B2]-worker) [    ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, value=NaN, ssl=NaN, clientAuth=NaN) w/ MAC_OS_X supressed clientAuth
   [junit4]   2> 481466 INFO  (SUITE-CollectionsAPIDistributedZkTest-seed#[AC327EC2E4BDF7B2]-worker) [    ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
   [junit4]   2> 481468 INFO  (SUITE-CollectionsAPIDistributedZkTest-seed#[AC327EC2E4BDF7B2]-worker) [    ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 4 servers in /Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_AC327EC2E4BDF7B2-001/tempDir-001
   [junit4]   2> 481468 INFO  (SUITE-CollectionsAPIDistributedZkTest-seed#[AC327EC2E4BDF7B2]-worker) [    ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
   [junit4]   2> 481469 INFO  (Thread-1432) [    ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
   [junit4]   2> 481469 INFO  (Thread-1432) [    ] o.a.s.c.ZkTestServer Starting server
   [junit4]   2> 481475 ERROR (Thread-1432) [    ] 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> 481579 INFO  (SUITE-CollectionsAPIDistributedZkTest-seed#[AC327EC2E4BDF7B2]-worker) [    ] o.a.s.c.ZkTestServer start zk server on port:53187
   [junit4]   2> 481614 INFO  (jetty-launcher-908-thread-1) [    ] o.e.j.s.Server jetty-9.3.20.v20170531
   [junit4]   2> 481615 INFO  (jetty-launcher-908-thread-2) [    ] o.e.j.s.Server jetty-9.3.20.v20170531
   [junit4]   2> 481619 INFO  (jetty-launcher-908-thread-1) [    ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@225d159a{/solr,null,AVAILABLE}
   [junit4]   2> 481621 INFO  (jetty-launcher-908-thread-2) [    ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@6faa5c79{/solr,null,AVAILABLE}
   [junit4]   2> 481623 INFO  (jetty-launcher-908-thread-2) [    ] o.e.j.s.AbstractConnector Started ServerConnector@69231d33{HTTP/1.1,[http/1.1]}{127.0.0.1:53190}
   [junit4]   2> 481623 INFO  (jetty-launcher-908-thread-2) [    ] o.e.j.s.Server Started @484820ms
   [junit4]   2> 481623 INFO  (jetty-launcher-908-thread-2) [    ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=53190}
   [junit4]   2> 481623 ERROR (jetty-launcher-908-thread-2) [    ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
   [junit4]   2> 481623 INFO  (jetty-launcher-908-thread-2) [    ] o.a.s.s.SolrDispatchFilter  ___      _       Welcome to Apache Solr? version 7.1.0
   [junit4]   2> 481623 INFO  (jetty-launcher-908-thread-2) [    ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _   Starting in cloud mode on port null
   [junit4]   2> 481623 INFO  (jetty-launcher-908-thread-2) [    ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_|  Install dir: null, Default config dir: null
   [junit4]   2> 481623 INFO  (jetty-launcher-908-thread-2) [    ] o.a.s.s.SolrDispatchFilter |___/\___/_|_|    Start time: 2017-10-02T11:29:09.681Z
   [junit4]   2> 481624 INFO  (jetty-launcher-908-thread-3) [    ] o.e.j.s.Server jetty-9.3.20.v20170531
   [junit4]   2> 481625 INFO  (jetty-launcher-908-thread-4) [    ] o.e.j.s.Server jetty-9.3.20.v20170531
   [junit4]   2> 481626 INFO  (jetty-launcher-908-thread-1) [    ] o.e.j.s.AbstractConnector Started ServerConnector@1276359a{HTTP/1.1,[http/1.1]}{127.0.0.1:53189}
   [junit4]   2> 481626 INFO  (jetty-launcher-908-thread-1) [    ] o.e.j.s.Server Started @484823ms
   [junit4]   2> 481626 INFO  (jetty-launcher-908-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=53189}
   [junit4]   2> 481626 ERROR (jetty-launcher-908-thread-1) [    ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
   [junit4]   2> 481626 INFO  (jetty-launcher-908-thread-1) [    ] o.a.s.s.SolrDispatchFilter  ___      _       Welcome to Apache Solr? version 7.1.0
   [junit4]   2> 481628 INFO  (jetty-launcher-908-thread-4) [    ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@d13a587{/solr,null,AVAILABLE}
   [junit4]   2> 481628 INFO  (jetty-launcher-908-thread-1) [    ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _   Starting in cloud mode on port null
   [junit4]   2> 481629 INFO  (jetty-launcher-908-thread-1) [    ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_|  Install dir: null, Default config dir: null
   [junit4]   2> 481629 INFO  (jetty-launcher-908-thread-1) [    ] o.a.s.s.SolrDispatchFilter |___/\___/_|_|    Start time: 2017-10-02T11:29:09.687Z
   [junit4]   2> 481629 INFO  (jetty-launcher-908-thread-4) [    ] o.e.j.s.AbstractConnector Started ServerConnector@7241fba5{HTTP/1.1,[http/1.1]}{127.0.0.1:53192}
   [junit4]   2> 481629 INFO  (jetty-launcher-908-thread-4) [    ] o.e.j.s.Server Started @484826ms
   [junit4]   2> 481629 INFO  (jetty-launcher-908-thread-4) [    ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=53192}
   [junit4]   2> 481629 ERROR (jetty-launcher-908-thread-4) [    ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
   [junit4]   2> 481629 INFO  (jetty-launcher-908-thread-4) [    ] o.a.s.s.SolrDispatchFilter  ___      _       Welcome to Apache Solr? version 7.1.0
   [junit4]   2> 481629 INFO  (jetty-launcher-908-thread-4) [    ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _   Starting in cloud mode on port null
   [junit4]   2> 481629 INFO  (jetty-launcher-908-thread-4) [    ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_|  Install dir: null, Default config dir: null
   [junit4]   2> 481629 INFO  (jetty-launcher-908-thread-4) [    ] o.a.s.s.SolrDispatchFilter |___/\___/_|_|    Start time: 2017-10-02T11:29:09.687Z
   [junit4]   2> 481629 INFO  (jetty-launcher-908-thread-3) [    ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@538b75f0{/solr,null,AVAILABLE}
   [junit4]   2> 481630 INFO  (jetty-launcher-908-thread-3) [    ] o.e.j.s.AbstractConnector Started ServerConnector@267e8b0d{HTTP/1.1,[http/1.1]}{127.0.0.1:53193}
   [junit4]   2> 481630 INFO  (jetty-launcher-908-thread-3) [    ] o.e.j.s.Server Started @484826ms
   [junit4]   2> 481630 INFO  (jetty-launcher-908-thread-3) [    ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=53193}
   [junit4]   2> 481630 ERROR (jetty-launcher-908-thread-3) [    ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
   [junit4]   2> 481630 INFO  (jetty-launcher-908-thread-3) [    ] o.a.s.s.SolrDispatchFilter  ___      _       Welcome to Apache Solr? version 7.1.0
   [junit4]   2> 481630 INFO  (jetty-launcher-908-thread-3) [    ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _   Starting in cloud mode on port null
   [junit4]   2> 481630 INFO  (jetty-launcher-908-thread-3) [    ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_|  Install dir: null, Default config dir: null
   [junit4]   2> 481630 INFO  (jetty-launcher-908-thread-3) [    ] o.a.s.s.SolrDispatchFilter |___/\___/_|_|    Start time: 2017-10-02T11:29:09.688Z
   [junit4]   2> 481631 INFO  (jetty-launcher-908-thread-2) [    ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
   [junit4]   2> 481634 INFO  (jetty-launcher-908-thread-4) [    ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
   [junit4]   2> 481634 INFO  (jetty-launcher-908-thread-1) [    ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
   [junit4]   2> 481634 INFO  (jetty-launcher-908-thread-3) [    ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
   [junit4]   2> 481658 INFO  (jetty-launcher-908-thread-2) [    ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:53187/solr
   [junit4]   2> 481658 INFO  (jetty-launcher-908-thread-3) [    ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:53187/solr
   [junit4]   2> 481659 INFO  (jetty-launcher-908-thread-4) [    ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:53187/solr
   [junit4]   2> 481660 INFO  (jetty-launcher-908-thread-1) [    ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:53187/solr
   [junit4]   2> 481834 INFO  (jetty-launcher-908-thread-1) [n:127.0.0.1:53189_solr    ] o.a.s.c.Overseer Overseer (id=null) closing
   [junit4]   2> 481834 INFO  (jetty-launcher-908-thread-2) [n:127.0.0.1:53190_solr    ] o.a.s.c.Overseer Overseer (id=null) closing
   [junit4]   2> 481834 INFO  (jetty-launcher-908-thread-4) [n:127.0.0.1:53192_solr    ] o.a.s.c.Overseer Overseer (id=null) closing
   [junit4]   2> 481834 INFO  (jetty-launcher-908-thread-3) [n:127.0.0.1:53193_solr    ] o.a.s.c.Overseer Overseer (id=null) closing
   [junit4]   2> 481835 INFO  (jetty-launcher-908-thread-4) [n:127.0.0.1:53192_solr    ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:53192_solr
   [junit4]   2> 481835 INFO  (jetty-launcher-908-thread-1) [n:127.0.0.1:53189_solr    ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53189_solr
   [junit4]   2> 481835 INFO  (jetty-launcher-908-thread-2) [n:127.0.0.1:53190_solr    ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53190_solr
   [junit4]   2> 481836 INFO  (jetty-launcher-908-thread-3) [n:127.0.0.1:53193_solr    ] o.a

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

lrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
   [junit4]   2> 564259 INFO  (jetty-closer-909-thread-4) [    ] o.a.s.c.Overseer Overseer (id=98759065569198092-127.0.0.1:53189_solr-n_0000000001) closing
   [junit4]   2> 564259 INFO  (OverseerStateUpdate-98759065569198092-127.0.0.1:53189_solr-n_0000000001) [n:127.0.0.1:53189_solr    ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:53189_solr
   [junit4]   2> 564259 INFO  (jetty-closer-909-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
   [junit4]   2> 564260 INFO  (jetty-closer-909-thread-2) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
   [junit4]   2> 564263 INFO  (zkCallback-929-thread-5-processing-n:127.0.0.1:53193_solr) [n:127.0.0.1:53193_solr    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (2)
   [junit4]   2> 564263 INFO  (zkCallback-930-thread-5-processing-n:127.0.0.1:53189_solr) [n:127.0.0.1:53189_solr    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (2)
   [junit4]   2> 564266 INFO  (zkCallback-929-thread-2-processing-n:127.0.0.1:53193_solr) [n:127.0.0.1:53193_solr    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
   [junit4]   2> 564266 INFO  (zkCallback-929-thread-5-processing-n:127.0.0.1:53193_solr) [n:127.0.0.1:53193_solr    ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:53193_solr
   [junit4]   2> 564267 WARN  (zkCallback-929-thread-2-processing-n:127.0.0.1:53193_solr) [n:127.0.0.1:53193_solr    ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
   [junit4]   2> 565766 WARN  (zkCallback-944-thread-2-processing-n:127.0.0.1:53192_solr) [n:127.0.0.1:53192_solr    ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
   [junit4]   2> 565766 WARN  (zkCallback-927-thread-4-processing-n:127.0.0.1:53190_solr) [n:127.0.0.1:53190_solr    ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
   [junit4]   2> 565766 WARN  (zkCallback-930-thread-5-processing-n:127.0.0.1:53189_solr) [n:127.0.0.1:53189_solr    ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
   [junit4]   2> 565766 INFO  (jetty-closer-909-thread-2) [    ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@48b7342b{/solr,null,UNAVAILABLE}
   [junit4]   2> 565766 INFO  (jetty-closer-909-thread-3) [    ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@6faa5c79{/solr,null,UNAVAILABLE}
   [junit4]   2> 565767 INFO  (jetty-closer-909-thread-4) [    ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@225d159a{/solr,null,UNAVAILABLE}
   [junit4]   2> 565776 INFO  (jetty-closer-909-thread-1) [    ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@538b75f0{/solr,null,UNAVAILABLE}
   [junit4]   2> 565778 ERROR (SUITE-CollectionsAPIDistributedZkTest-seed#[AC327EC2E4BDF7B2]-worker) [    ] 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> 565778 INFO  (SUITE-CollectionsAPIDistributedZkTest-seed#[AC327EC2E4BDF7B2]-worker) [    ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:53187 53187
   [junit4]   2> 565779 INFO  (Thread-1478) [    ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:53187 53187
   [junit4]   2> 565894 WARN  (Thread-1478) [    ] o.a.s.c.ZkTestServer Watch limit violations: 
   [junit4]   2> Maximum concurrent create/delete watches above limit:
   [junit4]   2> 
   [junit4]   2> 	22	/solr/configs/conf
   [junit4]   2> 	18	/solr/aliases.json
   [junit4]   2> 	18	/solr/clusterprops.json
   [junit4]   2> 
   [junit4]   2> Maximum concurrent data watches above limit:
   [junit4]   2> 
   [junit4]   2> 	52	/solr/collections/addReplicaColl/state.json
   [junit4]   2> 	24	/solr/collections/nodes_used_collection/state.json
   [junit4]   2> 	24	/solr/collections/reloaded_collection/state.json
   [junit4]   2> 	18	/solr/clusterstate.json
   [junit4]   2> 	15	/solr/collections/acollectionafterbaddelete/state.json
   [junit4]   2> 	14	/solr/collections/halfdeletedcollection/state.json
   [junit4]   2> 	10	/solr/collections/onlyinzk/state.json
   [junit4]   2> 	6	/solr/collections/awhollynewcollection_0/state.json
   [junit4]   2> 	5	/solr/collections/halfcollectionblocker/state.json
   [junit4]   2> 	5	/solr/collections/created_and_deleted/state.json
   [junit4]   2> 	5	/solr/collections/halfcollectionblocker2/state.json
   [junit4]   2> 	5	/solr/collections/withconfigset2/state.json
   [junit4]   2> 	4	/solr/collections/halfcollection/state.json
   [junit4]   2> 	2	/solr/collections/addReplicaColl/leader_elect/shard1/election/98759065569198089-core_node10-n_0000000002
   [junit4]   2> 
   [junit4]   2> Maximum concurrent children watches above limit:
   [junit4]   2> 
   [junit4]   2> 	358	/solr/collections
   [junit4]   2> 	18	/solr/live_nodes
   [junit4]   2> 
   [junit4]   2> NOTE: leaving temporary files on disk at: /Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest_AC327EC2E4BDF7B2-001
   [junit4]   2> Oct 02, 2017 11:30:33 AM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
   [junit4]   2> WARNING: Will linger awaiting termination of 1 leaked thread(s).
   [junit4]   2> NOTE: test params are: codec=CheapBastard, sim=RandomSimilarity(queryNorm=true): {}, locale=lt-LT, timezone=Asia/Sakhalin
   [junit4]   2> NOTE: Mac OS X 10.11.6 x86_64/Oracle Corporation 1.8.0_144 (64-bit)/cpus=3,threads=1,free=288788872,total=429363200
   [junit4]   2> NOTE: All tests run in this JVM: [OverseerRolesTest, TestCoreDiscovery, MoreLikeThisHandlerTest, CoreMergeIndexesAdminHandlerTest, TestLegacyTerms, JavabinLoaderTest, TestZkChroot, TestJoin, SimpleMLTQParserTest, TestSQLHandlerNonCloud, DataDrivenBlockJoinTest, CoreAdminCreateDiscoverTest, MultiThreadedOCPTest, TestTrie, BigEndianAscendingWordDeserializerTest, StatelessScriptUpdateProcessorFactoryTest, TestChildDocTransformer, TemplateUpdateProcessorTest, ShardRoutingCustomTest, BasicFunctionalityTest, TestCopyFieldCollectionResource, TestSolrCLIRunExample, DeleteNodeTest, ImplicitSnitchTest, LeaderInitiatedRecoveryOnShardRestartTest, SampleTest, TestRandomCollapseQParserPlugin, TestRestoreCore, SharedFSAutoReplicaFailoverUtilsTest, SolrCoreCheckLockOnStartupTest, TestStressUserVersions, TestConfigReload, TestAuthorizationFramework, ZkNodePropsTest, TermVectorComponentDistributedTest, FieldMutatingUpdateProcessorTest, SolrCmdDistributorTest, TestPostingsSolrHighlighter, ChangedSchemaMergeTest, TestSimpleTrackingShardHandler, TestCoreAdminApis, TestReload, OutOfBoxZkACLAndCredentialsProvidersTest, TestCharFilters, TestManagedSchemaThreadSafety, TestLegacyFieldReuse, HdfsCollectionsAPIDistributedZkTest, SpatialHeatmapFacetsTest, HdfsUnloadDistributedZkTest, MBeansHandlerTest, TestSolrJ, TestCollationField, TestCollationFieldDocValues, TestRandomFaceting, SearchHandlerTest, TestPartialUpdateDeduplication, TestFieldCacheWithThreads, TestRecovery, TestPivotHelperCode, DistributedQueryElevationComponentTest, BasicZkTest, TestFileDictionaryLookup, TestOverriddenPrefixQueryForCustomFieldType, TestConfigSetImmutable, TestLeaderElectionZkExpiry, DateRangeFieldTest, DistributedFacetPivotWhiteBoxTest, CursorMarkTest, DistributedFacetPivotSmallAdvancedTest, TestCloudManagedSchema, TestCollapseQParserPlugin, SolrIndexMetricsTest, TestCloudPseudoReturnFields, TestCollectionAPIs, SolrRequestParserTest, TermsComponentTest, TestPayloadScoreQParserPlugin, TestLMJelinekMercerSimilarityFactory, TestFieldTypeResource, TestJsonRequest, AutoCommitTest, OverseerCollectionConfigSetProcessorTest, CollectionsAPIDistributedZkTest]
   [junit4] Completed [161/733 (1!)] on J1 in 84.70s, 19 tests, 1 error <<< FAILURES!

[...truncated 39115 lines...]
-documentation-lint:
     [echo] checking for broken html...
    [jtidy] Checking for broken html (such as invalid tags)...
   [delete] Deleting directory /Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/lucene/build/jtidy_tmp
     [echo] Checking for broken links...
     [exec] 
     [exec] Crawl/parse...
     [exec] 
     [exec] Verify...
     [exec] 
     [exec] file:///build/docs/sandbox/org/apache/lucene/document/FloatPointNearestNeighbor.html
     [exec]   BROKEN LINK: file:///build/docs/core/org/apache/lucene/document/FloatPointNearestNeighbor.NearestHit.html
     [exec]   BROKEN LINK: file:///build/docs/core/org/apache/lucene/document/FloatPointNearestNeighbor.NearestHit.html
     [exec] 
     [exec] Broken javadocs links were found! Common root causes:
     [exec] * A typo of some sort for manually created links.
     [exec] * Public methods referencing non-public classes in their signature.

BUILD FAILED
/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/build.xml:826: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/build.xml:101: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/lucene/build.xml:142: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/lucene/build.xml:155: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/lucene/common-build.xml:2570: exec returned: 1

Total time: 80 minutes 56 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
[WARNINGS] Skipping publisher since build result is FAILURE
Recording test results
Email was triggered for: Failure - Any
Sending email for trigger: Failure - Any

Mime
View raw message