TestMergeSchedulerExternal failure [LUCENE-7945]

I hit the following test failure:
```
[junit4] Suite: org.apache.lucene.TestMergeSchedulerExternal
[junit4] 1> TEST FAILED; IW infoStream output:
[junit4] 1> IFD 0 [2017-08-29T20:07:58.366Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: init: current segments file is "segments"; deletionPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy@147f4499
[junit4] 1> IFD 0 [2017-08-29T20:07:58.403Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 1> IFD 0 [2017-08-29T20:07:58.403Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to checkpoint
[junit4] 1> IW 0 [2017-08-29T20:07:58.403Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: init: create=true
[junit4] 1> IW 0 [2017-08-29T20:07:58.403Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]:
[junit4] 1> dir=MockDirectoryWrapper(RAMDirectory@1ed52170 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@76c21fb3)
[junit4] 1> index=
[junit4] 1> version=8.0.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=CheapBastard
[junit4] 1> infoStream=org.apache.lucene.util.PrintStreamInfoStream
[junit4] 1> mergePolicy=[LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=13, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.810681051478346]
[junit4] 1> indexerThreadPool=org.apache.lucene.index.DocumentsWriterPerThreadPool@39b33696
[junit4] 1> readerPooling=false
[junit4] 1> perThreadHardLimitMB=1945
[junit4] 1> useCompoundFile=true
[junit4] 1> commitOnClose=true
[junit4] 1> indexSort=null
[junit4] 1> writer=org.apache.lucene.index.IndexWriter@14082bc1
[junit4] 1>
[junit4] 1> IW 0 [2017-08-29T20:07:58.403Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: MMapDirectory.UNMAP_SUPPORTED=true
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.409Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush postings as segment _0 numDocs=2
[junit4] 1> IW 0 [2017-08-29T20:07:58.409Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write norms
[junit4] 1> IW 0 [2017-08-29T20:07:58.409Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write docValues
[junit4] 1> IW 0 [2017-08-29T20:07:58.409Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write points
[junit4] 1> IW 0 [2017-08-29T20:07:58.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 13 msec to finish stored fields
[junit4] 1> IW 0 [2017-08-29T20:07:58.448Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 25 msec to write postings and finish vectors
[junit4] 1> IW 0 [2017-08-29T20:07:58.456Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 8 msec to write fieldInfos
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.456Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has 0 deleted docs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.456Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.456Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushedFiles=[_0.tip, _0.fdx, _0.doc, _0.tim, _0.fdt, _0.fnm]
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.456Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed codec=CheapBastard
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.464Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed: segment=_0 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,603.354
[junit4] 1> IW 0 [2017-08-29T20:07:58.465Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: create compound file
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.552Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush time 143.37104 msec
[junit4] 1> DW 0 [2017-08-29T20:07:58.553Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 0 [2017-08-29T20:07:58.553Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment _0(8.0.0):c2
[junit4] 1> BD 0 [2017-08-29T20:07:58.553Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: finished packet delGen=1 now completedDelGen=1
[junit4] 1> IW 0 [2017-08-29T20:07:58.553Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publish sets newSegment delGen=1 seg=_0(8.0.0):c2
[junit4] 1> IFD 0 [2017-08-29T20:07:58.553Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now checkpoint "_0(8.0.0):c2" [1 segments ; isCommit = false]
[junit4] 1> IFD 0 [2017-08-29T20:07:58.553Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to checkpoint
[junit4] 1> IFD 0 [2017-08-29T20:07:58.553Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_0.tip"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.553Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_0.fdx"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.553Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_0.doc"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.553Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_0.tim"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.553Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_0.fdt"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.553Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_0.fnm"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.553Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: delete [_0.tip, _0.fdx, _0.doc, _0.tim, _0.fdt, _0.fnm]
[junit4] 1> LMP 0 [2017-08-29T20:07:58.554Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: findMerges: 1 segments
[junit4] 1> LMP 0 [2017-08-29T20:07:58.554Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_0(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.554Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: level -1.0 to 3.0891984: 1 segments
[junit4] 1> MS 0 [2017-08-29T20:07:58.554Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: initDynamicDefaults spins=true maxThreadCount=1 maxMergeCount=6
[junit4] 1> MS 0 [2017-08-29T20:07:58.554Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now merge
[junit4] 1> MS 0 [2017-08-29T20:07:58.554Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: index: _0(8.0.0):c2
[junit4] 1> MS 0 [2017-08-29T20:07:58.554Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: no more merges pending; now return
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.559Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush postings as segment _1 numDocs=2
[junit4] 1> IW 0 [2017-08-29T20:07:58.559Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write norms
[junit4] 1> IW 0 [2017-08-29T20:07:58.559Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write docValues
[junit4] 1> IW 0 [2017-08-29T20:07:58.559Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write points
[junit4] 1> IW 0 [2017-08-29T20:07:58.563Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 3 msec to finish stored fields
[junit4] 1> IW 0 [2017-08-29T20:07:58.576Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 12 msec to write postings and finish vectors
[junit4] 1> IW 0 [2017-08-29T20:07:58.578Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 2 msec to write fieldInfos
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.578Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has 0 deleted docs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.578Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.578Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushedFiles=[_1.doc, _1.tim, _1.tip, _1.fdx, _1.fnm, _1.fdt]
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.578Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed codec=CheapBastard
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.578Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed: segment=_1 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,603.354
[junit4] 1> IW 0 [2017-08-29T20:07:58.579Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: create compound file
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.603Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush time 44.222471 msec
[junit4] 1> DW 0 [2017-08-29T20:07:58.603Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 0 [2017-08-29T20:07:58.603Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment _1(8.0.0):c2
[junit4] 1> BD 0 [2017-08-29T20:07:58.603Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: finished packet delGen=2 now completedDelGen=2
[junit4] 1> IW 0 [2017-08-29T20:07:58.603Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publish sets newSegment delGen=2 seg=_1(8.0.0):c2
[junit4] 1> IFD 0 [2017-08-29T20:07:58.603Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now checkpoint "_0(8.0.0):c2 _1(8.0.0):c2" [2 segments ; isCommit = false]
[junit4] 1> IFD 0 [2017-08-29T20:07:58.603Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to checkpoint
[junit4] 1> IFD 0 [2017-08-29T20:07:58.603Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_1.doc"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.603Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_1.tim"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.603Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_1.tip"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.603Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_1.fdx"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.603Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_1.fnm"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.603Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_1.fdt"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.603Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: delete [_1.doc, _1.tim, _1.tip, _1.fdx, _1.fnm, _1.fdt]
[junit4] 1> LMP 0 [2017-08-29T20:07:58.604Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: findMerges: 2 segments
[junit4] 1> LMP 0 [2017-08-29T20:07:58.604Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_0(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.604Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_1(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.604Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: level -1.0 to 3.0891984: 2 segments
[junit4] 1> MS 0 [2017-08-29T20:07:58.604Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now merge
[junit4] 1> MS 0 [2017-08-29T20:07:58.604Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: index: _0(8.0.0):c2 _1(8.0.0):c2
[junit4] 1> MS 0 [2017-08-29T20:07:58.604Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: no more merges pending; now return
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.608Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush postings as segment _2 numDocs=2
[junit4] 1> IW 0 [2017-08-29T20:07:58.608Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write norms
[junit4] 1> IW 0 [2017-08-29T20:07:58.608Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write docValues
[junit4] 1> IW 0 [2017-08-29T20:07:58.608Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write points
[junit4] 1> IW 0 [2017-08-29T20:07:58.614Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 5 msec to finish stored fields
[junit4] 1> IW 0 [2017-08-29T20:07:58.635Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 20 msec to write postings and finish vectors
[junit4] 1> IW 0 [2017-08-29T20:07:58.637Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 2 msec to write fieldInfos
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.637Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has 0 deleted docs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.638Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.638Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushedFiles=[_2.tip, _2.fdt, _2.fnm, _2.fdx, _2.doc, _2.tim]
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.638Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed codec=CheapBastard
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.638Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed: segment=_2 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,603.354
[junit4] 1> IW 0 [2017-08-29T20:07:58.638Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: create compound file
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.663Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush time 54.878877 msec
[junit4] 1> DW 0 [2017-08-29T20:07:58.663Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 0 [2017-08-29T20:07:58.663Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment _2(8.0.0):c2
[junit4] 1> BD 0 [2017-08-29T20:07:58.663Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: finished packet delGen=3 now completedDelGen=3
[junit4] 1> IW 0 [2017-08-29T20:07:58.663Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publish sets newSegment delGen=3 seg=_2(8.0.0):c2
[junit4] 1> IFD 0 [2017-08-29T20:07:58.663Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now checkpoint "_0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2" [3 segments ; isCommit = false]
[junit4] 1> IFD 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to checkpoint
[junit4] 1> IFD 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_2.tip"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_2.fdt"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_2.fnm"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_2.fdx"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_2.doc"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_2.tim"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: delete [_2.tip, _2.fdt, _2.fnm, _2.fdx, _2.doc, _2.tim]
[junit4] 1> LMP 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: findMerges: 3 segments
[junit4] 1> LMP 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_0(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_1(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_2(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: level -1.0 to 3.0891984: 3 segments
[junit4] 1> MS 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now merge
[junit4] 1> MS 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: index: _0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2
[junit4] 1> MS 0 [2017-08-29T20:07:58.664Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: no more merges pending; now return
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.666Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush postings as segment _3 numDocs=2
[junit4] 1> IW 0 [2017-08-29T20:07:58.666Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write norms
[junit4] 1> IW 0 [2017-08-29T20:07:58.666Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write docValues
[junit4] 1> IW 0 [2017-08-29T20:07:58.666Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write points
[junit4] 1> IW 0 [2017-08-29T20:07:58.671Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 4 msec to finish stored fields
[junit4] 1> IW 0 [2017-08-29T20:07:58.681Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 10 msec to write postings and finish vectors
[junit4] 1> IW 0 [2017-08-29T20:07:58.686Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 4 msec to write fieldInfos
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.686Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has 0 deleted docs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.686Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.686Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushedFiles=[_3.tip, _3.fdx, _3.fnm, _3.fdt, _3.doc, _3.tim]
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.686Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed codec=CheapBastard
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.686Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed: segment=_3 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,603.354
[junit4] 1> IW 0 [2017-08-29T20:07:58.687Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: create compound file
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.720Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush time 53.831698 msec
[junit4] 1> DW 0 [2017-08-29T20:07:58.720Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 0 [2017-08-29T20:07:58.720Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment _3(8.0.0):c2
[junit4] 1> BD 0 [2017-08-29T20:07:58.720Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: finished packet delGen=4 now completedDelGen=4
[junit4] 1> IW 0 [2017-08-29T20:07:58.720Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publish sets newSegment delGen=4 seg=_3(8.0.0):c2
[junit4] 1> IFD 0 [2017-08-29T20:07:58.720Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now checkpoint "_0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2" [4 segments ; isCommit = false]
[junit4] 1> IFD 0 [2017-08-29T20:07:58.721Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to checkpoint
[junit4] 1> IFD 0 [2017-08-29T20:07:58.721Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_3.tip"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.721Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_3.fdx"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.721Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_3.fnm"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.721Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_3.fdt"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.721Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_3.doc"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.721Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_3.tim"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.721Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: delete [_3.tip, _3.fdx, _3.fnm, _3.fdt, _3.doc, _3.tim]
[junit4] 1> LMP 0 [2017-08-29T20:07:58.721Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: findMerges: 4 segments
[junit4] 1> LMP 0 [2017-08-29T20:07:58.722Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_0(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.722Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_1(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.722Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_2(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.722Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_3(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.722Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: level -1.0 to 3.0891984: 4 segments
[junit4] 1> MS 0 [2017-08-29T20:07:58.722Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now merge
[junit4] 1> MS 0 [2017-08-29T20:07:58.722Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: index: _0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2
[junit4] 1> MS 0 [2017-08-29T20:07:58.722Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: no more merges pending; now return
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.724Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush postings as segment _4 numDocs=2
[junit4] 1> IW 0 [2017-08-29T20:07:58.724Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write norms
[junit4] 1> IW 0 [2017-08-29T20:07:58.724Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write docValues
[junit4] 1> IW 0 [2017-08-29T20:07:58.724Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write points
[junit4] 1> IW 0 [2017-08-29T20:07:58.727Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 2 msec to finish stored fields
[junit4] 1> IW 0 [2017-08-29T20:07:58.738Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 10 msec to write postings and finish vectors
[junit4] 1> IW 0 [2017-08-29T20:07:58.740Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 2 msec to write fieldInfos
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.740Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has 0 deleted docs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.740Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.740Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushedFiles=[_4.doc, _4.tim, _4.fdt, _4.fnm, _4.tip, _4.fdx]
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.740Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed codec=CheapBastard
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.740Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed: segment=_4 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,603.354
[junit4] 1> IW 0 [2017-08-29T20:07:58.740Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: create compound file
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush time 40.689396 msec
[junit4] 1> DW 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment _4(8.0.0):c2
[junit4] 1> BD 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: finished packet delGen=5 now completedDelGen=5
[junit4] 1> IW 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publish sets newSegment delGen=5 seg=_4(8.0.0):c2
[junit4] 1> IFD 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now checkpoint "_0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2" [5 segments ; isCommit = false]
[junit4] 1> IFD 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to checkpoint
[junit4] 1> IFD 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_4.doc"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_4.tim"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_4.fdt"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_4.fnm"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_4.tip"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_4.fdx"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: delete [_4.doc, _4.tim, _4.fdt, _4.fnm, _4.tip, _4.fdx]
[junit4] 1> LMP 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: findMerges: 5 segments
[junit4] 1> LMP 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_0(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_1(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_2(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.765Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_3(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.766Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_4(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.766Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: level -1.0 to 3.0891984: 5 segments
[junit4] 1> MS 0 [2017-08-29T20:07:58.766Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now merge
[junit4] 1> MS 0 [2017-08-29T20:07:58.766Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: index: _0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2
[junit4] 1> MS 0 [2017-08-29T20:07:58.766Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: no more merges pending; now return
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.770Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush postings as segment _5 numDocs=2
[junit4] 1> IW 0 [2017-08-29T20:07:58.770Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write norms
[junit4] 1> IW 0 [2017-08-29T20:07:58.770Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write docValues
[junit4] 1> IW 0 [2017-08-29T20:07:58.770Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write points
[junit4] 1> IW 0 [2017-08-29T20:07:58.776Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 5 msec to finish stored fields
[junit4] 1> IW 0 [2017-08-29T20:07:58.793Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 17 msec to write postings and finish vectors
[junit4] 1> IW 0 [2017-08-29T20:07:58.795Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 2 msec to write fieldInfos
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.795Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has 0 deleted docs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.795Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.795Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushedFiles=[_5.fnm, _5.fdt, _5.doc, _5.tim, _5.tip, _5.fdx]
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.795Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed codec=CheapBastard
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.796Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed: segment=_5 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,603.354
[junit4] 1> IW 0 [2017-08-29T20:07:58.796Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: create compound file
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.822Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush time 52.410376 msec
[junit4] 1> DW 0 [2017-08-29T20:07:58.822Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 0 [2017-08-29T20:07:58.822Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment _5(8.0.0):c2
[junit4] 1> BD 0 [2017-08-29T20:07:58.822Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: finished packet delGen=6 now completedDelGen=6
[junit4] 1> IW 0 [2017-08-29T20:07:58.822Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publish sets newSegment delGen=6 seg=_5(8.0.0):c2
[junit4] 1> IFD 0 [2017-08-29T20:07:58.822Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now checkpoint "_0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2" [6 segments ; isCommit = false]
[junit4] 1> IFD 0 [2017-08-29T20:07:58.822Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to checkpoint
[junit4] 1> IFD 0 [2017-08-29T20:07:58.822Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_5.fnm"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.822Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_5.fdt"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.822Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_5.doc"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.822Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_5.tim"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.822Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_5.tip"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.822Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_5.fdx"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.822Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: delete [_5.fnm, _5.fdt, _5.doc, _5.tim, _5.tip, _5.fdx]
[junit4] 1> LMP 0 [2017-08-29T20:07:58.823Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: findMerges: 6 segments
[junit4] 1> LMP 0 [2017-08-29T20:07:58.823Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_0(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.823Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_1(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.823Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_2(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.823Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_3(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.823Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_4(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.823Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_5(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.823Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: level -1.0 to 3.0891984: 6 segments
[junit4] 1> MS 0 [2017-08-29T20:07:58.823Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now merge
[junit4] 1> MS 0 [2017-08-29T20:07:58.823Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: index: _0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2
[junit4] 1> MS 0 [2017-08-29T20:07:58.823Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: no more merges pending; now return
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.825Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush postings as segment _6 numDocs=2
[junit4] 1> IW 0 [2017-08-29T20:07:58.825Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write norms
[junit4] 1> IW 0 [2017-08-29T20:07:58.825Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write docValues
[junit4] 1> IW 0 [2017-08-29T20:07:58.825Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write points
[junit4] 1> IW 0 [2017-08-29T20:07:58.828Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 2 msec to finish stored fields
[junit4] 1> IW 0 [2017-08-29T20:07:58.839Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 10 msec to write postings and finish vectors
[junit4] 1> IW 0 [2017-08-29T20:07:58.841Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 2 msec to write fieldInfos
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.841Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has 0 deleted docs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.841Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.841Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushedFiles=[_6.fdt, _6.fnm, _6.fdx, _6.tip, _6.doc, _6.tim]
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.841Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed codec=CheapBastard
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.841Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed: segment=_6 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,603.354
[junit4] 1> IW 0 [2017-08-29T20:07:58.842Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: create compound file
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.867Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush time 41.908027 msec
[junit4] 1> DW 0 [2017-08-29T20:07:58.867Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 0 [2017-08-29T20:07:58.867Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment _6(8.0.0):c2
[junit4] 1> BD 0 [2017-08-29T20:07:58.867Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: finished packet delGen=7 now completedDelGen=7
[junit4] 1> IW 0 [2017-08-29T20:07:58.867Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publish sets newSegment delGen=7 seg=_6(8.0.0):c2
[junit4] 1> IFD 0 [2017-08-29T20:07:58.867Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now checkpoint "_0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2" [7 segments ; isCommit = false]
[junit4] 1> IFD 0 [2017-08-29T20:07:58.867Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to checkpoint
[junit4] 1> IFD 0 [2017-08-29T20:07:58.867Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_6.fdt"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.867Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_6.fnm"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.867Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_6.fdx"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.867Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_6.tip"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.867Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_6.doc"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.867Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_6.tim"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.867Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: delete [_6.fdt, _6.fnm, _6.fdx, _6.tip, _6.doc, _6.tim]
[junit4] 1> LMP 0 [2017-08-29T20:07:58.868Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: findMerges: 7 segments
[junit4] 1> LMP 0 [2017-08-29T20:07:58.868Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_0(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.868Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_1(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.868Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_2(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.868Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_3(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.868Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_4(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.868Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_5(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.868Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_6(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.868Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: level -1.0 to 3.0891984: 7 segments
[junit4] 1> MS 0 [2017-08-29T20:07:58.868Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now merge
[junit4] 1> MS 0 [2017-08-29T20:07:58.868Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: index: _0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2
[junit4] 1> MS 0 [2017-08-29T20:07:58.868Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: no more merges pending; now return
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.870Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush postings as segment _7 numDocs=2
[junit4] 1> IW 0 [2017-08-29T20:07:58.871Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write norms
[junit4] 1> IW 0 [2017-08-29T20:07:58.871Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write docValues
[junit4] 1> IW 0 [2017-08-29T20:07:58.871Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write points
[junit4] 1> IW 0 [2017-08-29T20:07:58.873Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 2 msec to finish stored fields
[junit4] 1> IW 0 [2017-08-29T20:07:58.884Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 10 msec to write postings and finish vectors
[junit4] 1> IW 0 [2017-08-29T20:07:58.887Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 2 msec to write fieldInfos
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.887Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has 0 deleted docs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.887Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.887Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushedFiles=[_7.fnm, _7.tim, _7.fdt, _7.doc, _7.fdx, _7.tip]
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.887Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed codec=CheapBastard
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.887Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed: segment=_7 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,603.354
[junit4] 1> IW 0 [2017-08-29T20:07:58.887Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: create compound file
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.911Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush time 40.917889 msec
[junit4] 1> DW 0 [2017-08-29T20:07:58.911Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 0 [2017-08-29T20:07:58.911Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment _7(8.0.0):c2
[junit4] 1> BD 0 [2017-08-29T20:07:58.911Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: finished packet delGen=8 now completedDelGen=8
[junit4] 1> IW 0 [2017-08-29T20:07:58.911Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publish sets newSegment delGen=8 seg=_7(8.0.0):c2
[junit4] 1> IFD 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now checkpoint "_0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2 _7(8.0.0):c2" [8 segments ; isCommit = false]
[junit4] 1> IFD 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to checkpoint
[junit4] 1> IFD 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_7.fnm"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_7.tim"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_7.fdt"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_7.doc"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_7.fdx"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_7.tip"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: delete [_7.fnm, _7.tim, _7.fdt, _7.doc, _7.fdx, _7.tip]
[junit4] 1> LMP 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: findMerges: 8 segments
[junit4] 1> LMP 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_0(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_1(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_2(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_3(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_4(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_5(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_6(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_7(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: level -1.0 to 3.0891984: 8 segments
[junit4] 1> MS 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now merge
[junit4] 1> MS 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: index: _0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2 _7(8.0.0):c2
[junit4] 1> MS 0 [2017-08-29T20:07:58.912Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: no more merges pending; now return
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.916Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush postings as segment _8 numDocs=2
[junit4] 1> IW 0 [2017-08-29T20:07:58.916Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write norms
[junit4] 1> IW 0 [2017-08-29T20:07:58.917Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write docValues
[junit4] 1> IW 0 [2017-08-29T20:07:58.917Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write points
[junit4] 1> IW 0 [2017-08-29T20:07:58.922Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 5 msec to finish stored fields
[junit4] 1> IW 0 [2017-08-29T20:07:58.940Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 17 msec to write postings and finish vectors
[junit4] 1> IW 0 [2017-08-29T20:07:58.945Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 5 msec to write fieldInfos
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.945Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has 0 deleted docs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.945Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.945Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushedFiles=[_8.fdx, _8.doc, _8.fdt, _8.fnm, _8.tim, _8.tip]
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.945Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed codec=CheapBastard
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.945Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed: segment=_8 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,603.354
[junit4] 1> IW 0 [2017-08-29T20:07:58.945Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: create compound file
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush time 54.30704 msec
[junit4] 1> DW 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment _8(8.0.0):c2
[junit4] 1> BD 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: finished packet delGen=9 now completedDelGen=9
[junit4] 1> IW 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publish sets newSegment delGen=9 seg=_8(8.0.0):c2
[junit4] 1> IFD 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now checkpoint "_0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2 _7(8.0.0):c2 _8(8.0.0):c2" [9 segments ; isCommit = false]
[junit4] 1> IFD 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to checkpoint
[junit4] 1> IFD 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_8.fdx"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_8.doc"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_8.fdt"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_8.fnm"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_8.tim"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_8.tip"
[junit4] 1> IFD 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: delete [_8.fdx, _8.doc, _8.fdt, _8.fnm, _8.tim, _8.tip]
[junit4] 1> LMP 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: findMerges: 9 segments
[junit4] 1> LMP 0 [2017-08-29T20:07:58.971Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_0(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.972Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_1(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.972Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_2(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.972Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_3(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.972Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_4(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.972Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_5(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.972Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_6(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.972Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_7(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.972Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_8(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:58.972Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: level -1.0 to 3.0891984: 9 segments
[junit4] 1> MS 0 [2017-08-29T20:07:58.972Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now merge
[junit4] 1> MS 0 [2017-08-29T20:07:58.972Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: index: _0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2 _7(8.0.0):c2 _8(8.0.0):c2
[junit4] 1> MS 0 [2017-08-29T20:07:58.972Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: no more merges pending; now return
[junit4] 1> DWPT 0 [2017-08-29T20:07:58.974Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush postings as segment _9 numDocs=2
[junit4] 1> IW 0 [2017-08-29T20:07:58.974Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write norms
[junit4] 1> IW 0 [2017-08-29T20:07:58.974Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write docValues
[junit4] 1> IW 0 [2017-08-29T20:07:58.974Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to write points
[junit4] 1> IW 0 [2017-08-29T20:07:58.980Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 5 msec to finish stored fields
[junit4] 1> IW 0 [2017-08-29T20:07:58.999Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 18 msec to write postings and finish vectors
[junit4] 1> IW 0 [2017-08-29T20:07:59.001Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 2 msec to write fieldInfos
[junit4] 1> DWPT 0 [2017-08-29T20:07:59.001Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has 0 deleted docs
[junit4] 1> DWPT 0 [2017-08-29T20:07:59.001Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 0 [2017-08-29T20:07:59.001Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushedFiles=[_9.fdx, _9.tip, _9.doc, _9.tim, _9.fdt, _9.fnm]
[junit4] 1> DWPT 0 [2017-08-29T20:07:59.001Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed codec=CheapBastard
[junit4] 1> DWPT 0 [2017-08-29T20:07:59.001Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flushed: segment=_9 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,603.354
[junit4] 1> IW 0 [2017-08-29T20:07:59.002Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: create compound file
[junit4] 1> DWPT 0 [2017-08-29T20:07:59.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: flush time 51.474967 msec
[junit4] 1> DW 0 [2017-08-29T20:07:59.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 0 [2017-08-29T20:07:59.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publishFlushedSegment _9(8.0.0):c2
[junit4] 1> BD 0 [2017-08-29T20:07:59.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: finished packet delGen=10 now completedDelGen=10
[junit4] 1> IW 0 [2017-08-29T20:07:59.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: publish sets newSegment delGen=10 seg=_9(8.0.0):c2
[junit4] 1> IFD 0 [2017-08-29T20:07:59.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now checkpoint "_0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2 _7(8.0.0):c2 _8(8.0.0):c2 _9(8.0.0):c2" [10 segments ; isCommit = false]
[junit4] 1> IFD 0 [2017-08-29T20:07:59.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 0 msec to checkpoint
[junit4] 1> IFD 0 [2017-08-29T20:07:59.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_9.fdx"
[junit4] 1> IFD 0 [2017-08-29T20:07:59.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_9.tip"
[junit4] 1> IFD 0 [2017-08-29T20:07:59.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_9.doc"
[junit4] 1> IFD 0 [2017-08-29T20:07:59.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_9.tim"
[junit4] 1> IFD 0 [2017-08-29T20:07:59.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_9.fdt"
[junit4] 1> IFD 0 [2017-08-29T20:07:59.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: will delete new file "_9.fnm"
[junit4] 1> IFD 0 [2017-08-29T20:07:59.026Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: delete [_9.fdx, _9.tip, _9.doc, _9.tim, _9.fdt, _9.fnm]
[junit4] 1> LMP 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: findMerges: 10 segments
[junit4] 1> LMP 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_0(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_1(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_2(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_3(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_4(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_5(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_6(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_7(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_8(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: seg=_9(8.0.0):c2 level=3.0891984 size=0.001 MB
[junit4] 1> LMP 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: level -1.0 to 3.0891984: 10 segments
[junit4] 1> LMP 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: add merge=_0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2 _7(8.0.0):c2 _8(8.0.0):c2 _9(8.0.0):c2 start=0 end=10
[junit4] 1> IW 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: add merge to pendingMerges: _0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2 _7(8.0.0):c2 _8(8.0.0):c2 _9(8.0.0):c2 [total 1 pending]
[junit4] 1> IW 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: registerMerge merging= []
[junit4] 1> IW 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: registerMerge info=_0(8.0.0):c2
[junit4] 1> IW 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: registerMerge info=_1(8.0.0):c2
[junit4] 1> IW 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: registerMerge info=_2(8.0.0):c2
[junit4] 1> IW 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: registerMerge info=_3(8.0.0):c2
[junit4] 1> IW 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: registerMerge info=_4(8.0.0):c2
[junit4] 1> IW 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: registerMerge info=_5(8.0.0):c2
[junit4] 1> IW 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: registerMerge info=_6(8.0.0):c2
[junit4] 1> IW 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: registerMerge info=_7(8.0.0):c2
[junit4] 1> IW 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: registerMerge info=_8(8.0.0):c2
[junit4] 1> IW 0 [2017-08-29T20:07:59.027Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: registerMerge info=_9(8.0.0):c2
[junit4] 1> MS 0 [2017-08-29T20:07:59.028Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: now merge
[junit4] 1> MS 0 [2017-08-29T20:07:59.028Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: index: _0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2 _7(8.0.0):c2 _8(8.0.0):c2 _9(8.0.0):c2
[junit4] 1> MS 0 [2017-08-29T20:07:59.028Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: consider merge _0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2 _7(8.0.0):c2 _8(8.0.0):c2 _9(8.0.0):c2
[junit4] 1> MS 0 [2017-08-29T20:07:59.028Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: launch new thread [MyMergeThread]
[junit4] 1> MS 0 [2017-08-29T20:07:59.072Z; MyMergeThread]: merge thread: start
[junit4] 1> BD 0 [2017-08-29T20:07:59.086Z; MyMergeThread]: waitApplyForMerge: 0 packets, 10 merging segments
[junit4] 1> BD 0 [2017-08-29T20:07:59.086Z; MyMergeThread]: waitApply: no deletes to apply
[junit4] 1> IW 0 [2017-08-29T20:07:59.086Z; MyMergeThread]: now apply deletes for 10 merging segments
[junit4] 1> IW 0 [2017-08-29T20:07:59.086Z; MyMergeThread]: merge seg=_a _0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2 _7(8.0.0):c2 _8(8.0.0):c2 _9(8.0.0):c2
[junit4] 1> IW 0 [2017-08-29T20:07:59.086Z; MyMergeThread]: now merge
[junit4] 1> merge=_0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2 _7(8.0.0):c2 _8(8.0.0):c2 _9(8.0.0):c2
[junit4] 1> index=_0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2 _7(8.0.0):c2 _8(8.0.0):c2 _9(8.0.0):c2
[junit4] 1> IW 0 [2017-08-29T20:07:59.086Z; MyMergeThread]: merging _0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2 _7(8.0.0):c2 _8(8.0.0):c2 _9(8.0.0):c2
[junit4] 1> IW 0 [2017-08-29T20:07:59.087Z; 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.lucene50.Lucene50CompoundReader.readEntries(Lucene50CompoundReader.java:105)
[junit4] 1> at org.apache.lucene.codecs.lucene50.Lucene50CompoundReader.(Lucene50CompoundReader.java:69)
[junit4] 1> at org.apache.lucene.codecs.lucene50.Lucene50CompoundFormat.getCompoundReader(Lucene50CompoundFormat.java:71)
[junit4] 1> at org.apache.lucene.index.SegmentCoreReaders.(SegmentCoreReaders.java:99)
[junit4] 1> at org.apache.lucene.index.SegmentReader.(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:4360)
[junit4] 1> at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:4030)
[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-08-29T20:07:59.087Z; MyMergeThread]: handleMergeException: merge=_0(8.0.0):c2 _1(8.0.0):c2 _2(8.0.0):c2 _3(8.0.0):c2 _4(8.0.0):c2 _5(8.0.0):c2 _6(8.0.0):c2 _7(8.0.0):c2 _8(8.0.0):c2 _9(8.0.0):c2 exc=java.io.IOException: now failing during merge
[junit4] 1> IW 0 [2017-08-29T20:07:59.087Z; MyMergeThread]: hit exception during merge
[junit4] 1> IW 0 [2017-08-29T20:07:59.087Z; MyMergeThread]: hit tragic IOException inside merge
[junit4] 1> IW 0 [2017-08-29T20:07:59.087Z; MyMergeThread]: rollback
[junit4] 1> IW 0 [2017-08-29T20:07:59.087Z; MyMergeThread]: all running merges have aborted
[junit4] 1> IW 0 [2017-08-29T20:07:59.087Z; MyMergeThread]: rollback: done finish merges
[junit4] 1> MS 0 [2017-08-29T20:07:59.088Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: 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-08-29T20:07:59.088Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[B944333784A66276]]: no more merges pending; now return
[junit4] 1> DW 0 [2017-08-29T20:07:59.088Z; MyMergeThread]: abort
[junit4] 1> DW 0 [2017-08-29T20:07:59.088Z; MyMergeThread]: done abort success=true
[junit4] 1> IW 0 [2017-08-29T20:07:59.088Z; MyMergeThread]: rollback: infos=
[junit4] 1> IW 0 [2017-08-29T20:07:59.089Z; MyMergeThread]: TEST: now handleMergeException
[junit4] 1> MS 0 [2017-08-29T20:07:59.089Z; 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=B944333784A66276 -Dtests.slow=true -Dtests.locale=et-EE -Dtests.timezone=Etc/GMT+9 -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] FAILURE 0.75s J1 | TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler <<<
[junit4] > Throwable #1: java.lang.AssertionError
[junit4] > at __randomizedtesting.SeedInfo.seed([B944333784A66276:3EC58E9A80861872]: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=CheapBastard, sim=RandomSimilarity(queryNorm=true): {}, locale=et-EE, timezone=Etc/GMT+9
[junit4] 2> NOTE: Linux 2.6.32-696.6.3.el6.x86_64 amd64/Oracle Corporation 1.8.0_141 (64-bit)/cpus=4,threads=1,free=239361936,total=253755392
[junit4] 2> NOTE: All tests run in this JVM: [TestLucene50StoredFieldsFormat, TestCustomTermFreq, TestBooleanQuery, TestComplexExplanations, TestGraphTokenizers, TestOmitPositions, TestRecyclingIntBlockAllocator, TestLockFactory, TestMergeSchedulerExternal]
```

It does not reproduce and logs seem to indicate that handleMergeException was actually called so this might be a race condition, ie. we check the value of excCalled before it is set?

---
Migrated from [LUCENE-7945](https://issues.apache.org/jira/browse/LUCENE-7945) by Adrien Grand (@jpountz)

Start by reproducing the failure in org.apache.lucene.TestMergeSchedulerExternal, especially testSubclassConcurrentMergeScheduler, and inspect the full test output beyond the excerpt provided. Trace the merge-scheduler behavior involved in the failure; done means the named test passes reliably without masking the reported failure.

Written by the indexing model from the issue text.