You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2016/02/18 09:46:51 UTC
[JENKINS] Lucene-Solr-5.x-MacOSX (64bit/jdk1.8.0) - Build # 3039 -
Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-5.x-MacOSX/3039/
Java: 64bit/jdk1.8.0 -XX:-UseCompressedOops -XX:+UseParallelGC
1 tests failed.
FAILED: org.apache.lucene.TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler
Error Message:
Stack Trace:
java.lang.AssertionError
at __randomizedtesting.SeedInfo.seed([BE14B687580DC301:39950B2A5C2DB905]: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:126)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1764)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:871)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:907)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:921)
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:367)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:809)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:460)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:880)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:781)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:816)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:827)
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:367)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 513 lines...]
[junit4] Suite: org.apache.lucene.TestMergeSchedulerExternal
[junit4] 1> TEST FAILED; IW infoStream output:
[junit4] 1> IFD 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: init: current segments file is "segments"; deletionPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy@4fd483a5
[junit4] 1> IFD 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 1> IFD 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
[junit4] 1> IW 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: init: create=true
[junit4] 1> IW 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]:
[junit4] 1> dir=MockDirectoryWrapper(RAMDirectory@6f9049f8 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@785f410e)
[junit4] 1> index=
[junit4] 1> version=5.6.0
[junit4] 1> analyzer=org.apache.lucene.analysis.MockAnalyzer
[junit4] 1> ramBufferSizeMB=-1.0
[junit4] 1> maxBufferedDocs=2
[junit4] 1> maxBufferedDeleteTerms=-1
[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.ClassicSimilarity
[junit4] 1> mergeScheduler=MyMergeScheduler: maxThreadCount=-1, maxMergeCount=-1, ioThrottle=true
[junit4] 1> default WRITE_LOCK_TIMEOUT=0
[junit4] 1> writeLockTimeout=0
[junit4] 1> codec=Asserting(Lucene54): {}, docValues:{}
[junit4] 1> infoStream=org.apache.lucene.util.PrintStreamInfoStream
[junit4] 1> mergePolicy=[LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=29, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
[junit4] 1> indexerThreadPool=org.apache.lucene.index.DocumentsWriterPerThreadPool@28a76779
[junit4] 1> readerPooling=false
[junit4] 1> perThreadHardLimitMB=1945
[junit4] 1> useCompoundFile=false
[junit4] 1> commitOnClose=true
[junit4] 1> writer=org.apache.lucene.index.IndexWriter@4515341c
[junit4] 1>
[junit4] 1> IW 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: MMapDirectory.UNMAP_SUPPORTED=true
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.12Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _0 numDocs=2
[junit4] 1> IW 100 [2016-02-18T08:41:26.12Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
[junit4] 1> IW 100 [2016-02-18T08:41:26.12Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
[junit4] 1> IW 100 [2016-02-18T08:41:26.124Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
[junit4] 1> IW 100 [2016-02-18T08:41:26.153Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 28 msec to write postings and finish vectors
[junit4] 1> IW 100 [2016-02-18T08:41:26.157Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.157Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.157Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.157Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_0.fdx, _0_Asserting_0.doc, _0_Asserting_0.tim, _0.fdt, _0_Asserting_0.tip, _0.fnm]
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.158Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.158Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_0 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
[junit4] 1> DW 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
[junit4] 1> IW 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=1 seg=_0(5.6.0):C2
[junit4] 1> IFD 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2" [1 segments ; isCommit = false]
[junit4] 1> IFD 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
[junit4] 1> LMP 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 1 segments
[junit4] 1> LMP 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 1 segments
[junit4] 1> MS 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: initDynamicDefaults spins=false maxThreadCount=1 maxMergeCount=6
[junit4] 1> MS 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
[junit4] 1> MS 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2
[junit4] 1> MS 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.167Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _1 numDocs=2
[junit4] 1> IW 100 [2016-02-18T08:41:26.168Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
[junit4] 1> IW 100 [2016-02-18T08:41:26.168Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
[junit4] 1> IW 100 [2016-02-18T08:41:26.172Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
[junit4] 1> IW 100 [2016-02-18T08:41:26.192Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 20 msec to write postings and finish vectors
[junit4] 1> IW 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_1_Asserting_0.tip, _1_Asserting_0.doc, _1_Asserting_0.tim, _1.fdx, _1.fnm, _1.fdt]
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.197Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_1 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
[junit4] 1> DW 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
[junit4] 1> IW 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=2 seg=_1(5.6.0):C2
[junit4] 1> IFD 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2" [2 segments ; isCommit = false]
[junit4] 1> IFD 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
[junit4] 1> LMP 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 2 segments
[junit4] 1> LMP 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 2 segments
[junit4] 1> MS 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
[junit4] 1> MS 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2
[junit4] 1> MS 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.208Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _2 numDocs=2
[junit4] 1> IW 100 [2016-02-18T08:41:26.208Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
[junit4] 1> IW 100 [2016-02-18T08:41:26.208Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
[junit4] 1> IW 100 [2016-02-18T08:41:26.211Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
[junit4] 1> IW 100 [2016-02-18T08:41:26.248Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 36 msec to write postings and finish vectors
[junit4] 1> IW 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_2.fdt, _2_Asserting_0.tip, _2.fnm, _2.fdx, _2_Asserting_0.doc, _2_Asserting_0.tim]
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.275Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_2 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
[junit4] 1> DW 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
[junit4] 1> IW 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=3 seg=_2(5.6.0):C2
[junit4] 1> IFD 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2" [3 segments ; isCommit = false]
[junit4] 1> IFD 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
[junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 3 segments
[junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 3 segments
[junit4] 1> MS 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
[junit4] 1> MS 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2
[junit4] 1> MS 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.285Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _3 numDocs=2
[junit4] 1> IW 100 [2016-02-18T08:41:26.285Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
[junit4] 1> IW 100 [2016-02-18T08:41:26.285Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
[junit4] 1> IW 100 [2016-02-18T08:41:26.289Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
[junit4] 1> IW 100 [2016-02-18T08:41:26.313Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 23 msec to write postings and finish vectors
[junit4] 1> IW 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 12 msec to write fieldInfos
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_3.fdx, _3_Asserting_0.doc, _3.fnm, _3_Asserting_0.tim, _3.fdt, _3_Asserting_0.tip]
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_3 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
[junit4] 1> DW 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
[junit4] 1> IW 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=4 seg=_3(5.6.0):C2
[junit4] 1> IFD 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2" [4 segments ; isCommit = false]
[junit4] 1> IFD 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
[junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 4 segments
[junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 4 segments
[junit4] 1> MS 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
[junit4] 1> MS 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2
[junit4] 1> MS 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.336Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _4 numDocs=2
[junit4] 1> IW 100 [2016-02-18T08:41:26.336Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
[junit4] 1> IW 100 [2016-02-18T08:41:26.336Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
[junit4] 1> IW 100 [2016-02-18T08:41:26.339Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
[junit4] 1> IW 100 [2016-02-18T08:41:26.354Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 15 msec to write postings and finish vectors
[junit4] 1> IW 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_4.fdt, _4.fnm, _4_Asserting_0.doc, _4_Asserting_0.tim, _4_Asserting_0.tip, _4.fdx]
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_4 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
[junit4] 1> DW 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
[junit4] 1> IW 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=5 seg=_4(5.6.0):C2
[junit4] 1> IFD 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2" [5 segments ; isCommit = false]
[junit4] 1> IFD 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
[junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 5 segments
[junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 5 segments
[junit4] 1> MS 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
[junit4] 1> MS 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2
[junit4] 1> MS 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.368Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _5 numDocs=2
[junit4] 1> IW 100 [2016-02-18T08:41:26.368Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
[junit4] 1> IW 100 [2016-02-18T08:41:26.368Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
[junit4] 1> IW 100 [2016-02-18T08:41:26.372Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
[junit4] 1> IW 100 [2016-02-18T08:41:26.401Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 28 msec to write postings and finish vectors
[junit4] 1> IW 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_5.fnm, _5_Asserting_0.tip, _5.fdt, _5_Asserting_0.doc, _5_Asserting_0.tim, _5.fdx]
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_5 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
[junit4] 1> DW 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
[junit4] 1> IW 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=6 seg=_5(5.6.0):C2
[junit4] 1> IFD 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2" [6 segments ; isCommit = false]
[junit4] 1> IFD 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
[junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 6 segments
[junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 6 segments
[junit4] 1> MS 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
[junit4] 1> MS 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2
[junit4] 1> MS 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.44Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _6 numDocs=2
[junit4] 1> IW 100 [2016-02-18T08:41:26.44Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
[junit4] 1> IW 100 [2016-02-18T08:41:26.44Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
[junit4] 1> IW 100 [2016-02-18T08:41:26.444Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
[junit4] 1> IW 100 [2016-02-18T08:41:26.459Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 15 msec to write postings and finish vectors
[junit4] 1> IW 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_6_Asserting_0.doc, _6_Asserting_0.tim, _6.fdt, _6.fnm, _6.fdx, _6_Asserting_0.tip]
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_6 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
[junit4] 1> DW 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
[junit4] 1> IW 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=7 seg=_6(5.6.0):C2
[junit4] 1> IFD 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2" [7 segments ; isCommit = false]
[junit4] 1> IFD 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
[junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 7 segments
[junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_6(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 7 segments
[junit4] 1> MS 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
[junit4] 1> MS 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2
[junit4] 1> MS 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.49Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _7 numDocs=2
[junit4] 1> IW 100 [2016-02-18T08:41:26.49Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
[junit4] 1> IW 100 [2016-02-18T08:41:26.49Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
[junit4] 1> IW 100 [2016-02-18T08:41:26.495Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
[junit4] 1> IW 100 [2016-02-18T08:41:26.51Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 15 msec to write postings and finish vectors
[junit4] 1> IW 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to write fieldInfos
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_7_Asserting_0.tip, _7.fnm, _7_Asserting_0.doc, _7_Asserting_0.tim, _7.fdt, _7.fdx]
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_7 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
[junit4] 1> DW 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
[junit4] 1> IW 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=8 seg=_7(5.6.0):C2
[junit4] 1> IFD 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2" [8 segments ; isCommit = false]
[junit4] 1> IFD 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
[junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 8 segments
[junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_6(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_7(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 8 segments
[junit4] 1> MS 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
[junit4] 1> MS 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2
[junit4] 1> MS 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.525Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _8 numDocs=2
[junit4] 1> IW 100 [2016-02-18T08:41:26.525Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
[junit4] 1> IW 100 [2016-02-18T08:41:26.525Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
[junit4] 1> IW 100 [2016-02-18T08:41:26.529Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
[junit4] 1> IW 100 [2016-02-18T08:41:26.544Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 14 msec to write postings and finish vectors
[junit4] 1> IW 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to write fieldInfos
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_8_Asserting_0.doc, _8_Asserting_0.tim, _8.fdx, _8_Asserting_0.tip, _8.fdt, _8.fnm]
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_8 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
[junit4] 1> DW 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
[junit4] 1> IW 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=9 seg=_8(5.6.0):C2
[junit4] 1> IFD 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2" [9 segments ; isCommit = false]
[junit4] 1> IFD 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
[junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 9 segments
[junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_6(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_7(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_8(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 9 segments
[junit4] 1> MS 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
[junit4] 1> MS 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2
[junit4] 1> MS 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.557Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _9 numDocs=2
[junit4] 1> IW 100 [2016-02-18T08:41:26.557Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
[junit4] 1> IW 100 [2016-02-18T08:41:26.557Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
[junit4] 1> IW 100 [2016-02-18T08:41:26.562Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
[junit4] 1> IW 100 [2016-02-18T08:41:26.577Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 15 msec to write postings and finish vectors
[junit4] 1> IW 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_9.fdx, _9.fdt, _9.fnm, _9_Asserting_0.doc, _9_Asserting_0.tim, _9_Asserting_0.tip]
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
[junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_9 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
[junit4] 1> DW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
[junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
[junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=10 seg=_9(5.6.0):C2
[junit4] 1> IFD 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2" [10 segments ; isCommit = false]
[junit4] 1> IFD 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
[junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 10 segments
[junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_6(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_7(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_8(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_9(5.6.0):C2 level=3.0503798 size=0.001 MB
[junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 10 segments
[junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: add merge=_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2 start=0 end=10
[junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: add merge to pendingMerges: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2 [total 1 pending]
[junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge merging= []
[junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_0(5.6.0):C2
[junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_1(5.6.0):C2
[junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_2(5.6.0):C2
[junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_3(5.6.0):C2
[junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_4(5.6.0):C2
[junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_5(5.6.0):C2
[junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_6(5.6.0):C2
[junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_7(5.6.0):C2
[junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_8(5.6.0):C2
[junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_9(5.6.0):C2
[junit4] 1> MS 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
[junit4] 1> MS 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
[junit4] 1> MS 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: consider merge _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
[junit4] 1> MS 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: launch new thread [MyMergeThread]
[junit4] 1> MS 100 [2016-02-18T08:41:26.59Z; MyMergeThread]: merge thread: start
[junit4] 1> IW 100 [2016-02-18T08:41:26.591Z; MyMergeThread]: now apply deletes for 10 merging segments
[junit4] 1> MS 100 [2016-02-18T08:41:26.591Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 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> BD 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: applyDeletes: open segment readers took 0 msec
[junit4] 1> BD 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: applyDeletes: no segments; skipping
[junit4] 1> BD 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: prune sis=segments: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2 minGen=1 packetCount=0
[junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: merge seg=_a _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
[junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: now merge
[junit4] 1> merge=_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
[junit4] 1> index=_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
[junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: merging _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
[junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: handleMergeException: merge=_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2 exc=java.io.IOException: now failing during merge
[junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: hit exception during merge
[junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: hit tragic IOException inside merge
[junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: rollback
[junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: all running merges have aborted
[junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: rollback: done finish merges
[junit4] 1> MS 100 [2016-02-18T08:41:26.593Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
[junit4] 1> DW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: abort
[junit4] 1> DW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: done abort success=true
[junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: rollback: infos=
[junit4] 1> MS 100 [2016-02-18T08:41:26.593Z; 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=BE14B687580DC301 -Dtests.slow=true -Dtests.locale=es-PR -Dtests.timezone=Asia/Phnom_Penh -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] FAILURE 0.55s J1 | TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler <<<
[junit4] > Throwable #1: java.lang.AssertionError
[junit4] > at __randomizedtesting.SeedInfo.seed([BE14B687580DC301:39950B2A5C2DB905]:0)
[junit4] > at org.apache.lucene.TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler(TestMergeSchedulerExternal.java:126)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}, sim=DefaultSimilarity, locale=es-PR, timezone=Asia/Phnom_Penh
[junit4] 2> NOTE: Mac OS X 10.8.5 x86_64/Oracle Corporation 1.8.0_72 (64-bit)/cpus=3,threads=1,free=101265472,total=218628096
[junit4] 2> NOTE: All tests run in this JVM: [TestLongBitSet, TestSegmentTermEnum, TestSparseFixedBitSet, TestLucene50SegmentInfoFormat, TestSimpleExplanations, TestStressAdvance, TestExternalCodecs, TestNumericRangeQuery64, TestRegExp, TestIndexReaderClose, TestDirectory, TestFieldValueQuery, TestBitDocIdSetBuilder, TestSortedSetSortField, TestCachingWrapperFilter, TestCharFilter, TestSimilarity2, TestDocTermOrdsRewriteMethod, TestCodecs, TestSortedNumericSortField, TestRecyclingIntBlockAllocator, TestSpansAdvanced, TestIndexWriterMergePolicy, TestNRTCachingDirectory, TestBooleanOr, TestByteArrayDataInput, TestIndexWriterForceMerge, TestBinaryDocValuesUpdates, TestConsistentFieldNumbers, TestFilterSpans, TestLevenshteinAutomata, TestDocValues, TestBagOfPositions, TestSpanMultiTermQueryWrapper, TestSleepingLockWrapper, TestRamUsageEstimator, TestSearcherManager, TestFixedBitSet, TestSentinelIntSet, TestAutomaton, Test2BSortedDocValuesOrds, TestMergeSchedulerExternal]
[junit4] Completed [95/421 (1!)] on J1 in 0.59s, 2 tests, 1 failure <<< FAILURES!
[...truncated 1060 lines...]
BUILD FAILED
/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/build.xml:750: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/build.xml:694: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/build.xml:59: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/lucene/build.xml:50: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/lucene/common-build.xml:1477: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/lucene/common-build.xml:1033: There were test failures: 421 suites (1 ignored), 3386 tests, 1 failure, 48 ignored (44 assumptions) [seed: BE14B687580DC301]
Total time: 7 minutes 18 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
Re: [JENKINS] Lucene-Solr-5.x-MacOSX (64bit/jdk1.8.0) - Build # 3039
- Still Failing!
Posted by Michael McCandless <lu...@mikemccandless.com>.
Well, I committed some more verbosity here, but it's sure looking like
on OS X it sometimes "forgets" to execute a finally clause in
ConcurrentMergeScheduler$MergeThread.run
I eagerly await the next time it fails.
Mike McCandless
http://blog.mikemccandless.com
On Thu, Feb 18, 2016 at 9:08 AM, Michael McCandless
<lu...@mikemccandless.com> wrote:
> Ahh, it finally failed again (on OS X). I'll dig.
>
> Mike McCandless
>
> http://blog.mikemccandless.com
>
>
> On Thu, Feb 18, 2016 at 3:46 AM, Policeman Jenkins Server
> <je...@thetaphi.de> wrote:
>> Build: http://jenkins.thetaphi.de/job/Lucene-Solr-5.x-MacOSX/3039/
>> Java: 64bit/jdk1.8.0 -XX:-UseCompressedOops -XX:+UseParallelGC
>>
>> 1 tests failed.
>> FAILED: org.apache.lucene.TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler
>>
>> Error Message:
>>
>>
>> Stack Trace:
>> java.lang.AssertionError
>> at __randomizedtesting.SeedInfo.seed([BE14B687580DC301:39950B2A5C2DB905]: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:126)
>> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
>> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>> at java.lang.reflect.Method.invoke(Method.java:498)
>> at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1764)
>> at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:871)
>> at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:907)
>> at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:921)
>> 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:367)
>> at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:809)
>> at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:460)
>> at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:880)
>> at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:781)
>> at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:816)
>> at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:827)
>> 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:367)
>> at java.lang.Thread.run(Thread.java:745)
>>
>>
>>
>>
>> Build Log:
>> [...truncated 513 lines...]
>> [junit4] Suite: org.apache.lucene.TestMergeSchedulerExternal
>> [junit4] 1> TEST FAILED; IW infoStream output:
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: init: current segments file is "segments"; deletionPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy@4fd483a5
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "" [0 segments ; isCommit = false]
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: init: create=true
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]:
>> [junit4] 1> dir=MockDirectoryWrapper(RAMDirectory@6f9049f8 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@785f410e)
>> [junit4] 1> index=
>> [junit4] 1> version=5.6.0
>> [junit4] 1> analyzer=org.apache.lucene.analysis.MockAnalyzer
>> [junit4] 1> ramBufferSizeMB=-1.0
>> [junit4] 1> maxBufferedDocs=2
>> [junit4] 1> maxBufferedDeleteTerms=-1
>> [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.ClassicSimilarity
>> [junit4] 1> mergeScheduler=MyMergeScheduler: maxThreadCount=-1, maxMergeCount=-1, ioThrottle=true
>> [junit4] 1> default WRITE_LOCK_TIMEOUT=0
>> [junit4] 1> writeLockTimeout=0
>> [junit4] 1> codec=Asserting(Lucene54): {}, docValues:{}
>> [junit4] 1> infoStream=org.apache.lucene.util.PrintStreamInfoStream
>> [junit4] 1> mergePolicy=[LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=29, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
>> [junit4] 1> indexerThreadPool=org.apache.lucene.index.DocumentsWriterPerThreadPool@28a76779
>> [junit4] 1> readerPooling=false
>> [junit4] 1> perThreadHardLimitMB=1945
>> [junit4] 1> useCompoundFile=false
>> [junit4] 1> commitOnClose=true
>> [junit4] 1> writer=org.apache.lucene.index.IndexWriter@4515341c
>> [junit4] 1>
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: MMapDirectory.UNMAP_SUPPORTED=true
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.12Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _0 numDocs=2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.12Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.12Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.124Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.153Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 28 msec to write postings and finish vectors
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.157Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.157Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.157Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.157Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_0.fdx, _0_Asserting_0.doc, _0_Asserting_0.tim, _0.fdt, _0_Asserting_0.tip, _0.fnm]
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.158Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.158Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_0 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
>> [junit4] 1> DW 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=1 seg=_0(5.6.0):C2
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2" [1 segments ; isCommit = false]
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 1 segments
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 1 segments
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: initDynamicDefaults spins=false maxThreadCount=1 maxMergeCount=6
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.167Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _1 numDocs=2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.168Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.168Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.172Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.192Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 20 msec to write postings and finish vectors
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_1_Asserting_0.tip, _1_Asserting_0.doc, _1_Asserting_0.tim, _1.fdx, _1.fnm, _1.fdt]
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.197Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_1 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
>> [junit4] 1> DW 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=2 seg=_1(5.6.0):C2
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2" [2 segments ; isCommit = false]
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 2 segments
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 2 segments
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.208Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _2 numDocs=2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.208Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.208Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.211Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.248Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 36 msec to write postings and finish vectors
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_2.fdt, _2_Asserting_0.tip, _2.fnm, _2.fdx, _2_Asserting_0.doc, _2_Asserting_0.tim]
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.275Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_2 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
>> [junit4] 1> DW 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=3 seg=_2(5.6.0):C2
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2" [3 segments ; isCommit = false]
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 3 segments
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 3 segments
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.285Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _3 numDocs=2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.285Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.285Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.289Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.313Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 23 msec to write postings and finish vectors
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 12 msec to write fieldInfos
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_3.fdx, _3_Asserting_0.doc, _3.fnm, _3_Asserting_0.tim, _3.fdt, _3_Asserting_0.tip]
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_3 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
>> [junit4] 1> DW 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=4 seg=_3(5.6.0):C2
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2" [4 segments ; isCommit = false]
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 4 segments
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 4 segments
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.336Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _4 numDocs=2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.336Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.336Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.339Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.354Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 15 msec to write postings and finish vectors
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_4.fdt, _4.fnm, _4_Asserting_0.doc, _4_Asserting_0.tim, _4_Asserting_0.tip, _4.fdx]
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_4 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
>> [junit4] 1> DW 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=5 seg=_4(5.6.0):C2
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2" [5 segments ; isCommit = false]
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 5 segments
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 5 segments
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.368Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _5 numDocs=2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.368Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.368Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.372Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.401Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 28 msec to write postings and finish vectors
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_5.fnm, _5_Asserting_0.tip, _5.fdt, _5_Asserting_0.doc, _5_Asserting_0.tim, _5.fdx]
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_5 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
>> [junit4] 1> DW 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=6 seg=_5(5.6.0):C2
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2" [6 segments ; isCommit = false]
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 6 segments
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 6 segments
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.44Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _6 numDocs=2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.44Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.44Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.444Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.459Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 15 msec to write postings and finish vectors
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_6_Asserting_0.doc, _6_Asserting_0.tim, _6.fdt, _6.fnm, _6.fdx, _6_Asserting_0.tip]
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_6 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
>> [junit4] 1> DW 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=7 seg=_6(5.6.0):C2
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2" [7 segments ; isCommit = false]
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 7 segments
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_6(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 7 segments
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.49Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _7 numDocs=2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.49Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.49Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.495Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.51Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 15 msec to write postings and finish vectors
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to write fieldInfos
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_7_Asserting_0.tip, _7.fnm, _7_Asserting_0.doc, _7_Asserting_0.tim, _7.fdt, _7.fdx]
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_7 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
>> [junit4] 1> DW 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=8 seg=_7(5.6.0):C2
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2" [8 segments ; isCommit = false]
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 8 segments
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_6(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_7(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 8 segments
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.525Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _8 numDocs=2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.525Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.525Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.529Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.544Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 14 msec to write postings and finish vectors
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to write fieldInfos
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_8_Asserting_0.doc, _8_Asserting_0.tim, _8.fdx, _8_Asserting_0.tip, _8.fdt, _8.fnm]
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_8 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
>> [junit4] 1> DW 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=9 seg=_8(5.6.0):C2
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2" [9 segments ; isCommit = false]
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 9 segments
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_6(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_7(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_8(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 9 segments
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.557Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _9 numDocs=2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.557Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.557Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.562Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.577Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 15 msec to write postings and finish vectors
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_9.fdx, _9.fdt, _9.fnm, _9_Asserting_0.doc, _9_Asserting_0.tim, _9_Asserting_0.tip]
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
>> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_9 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
>> [junit4] 1> DW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=10 seg=_9(5.6.0):C2
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2" [10 segments ; isCommit = false]
>> [junit4] 1> IFD 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 10 segments
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_6(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_7(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_8(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_9(5.6.0):C2 level=3.0503798 size=0.001 MB
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 10 segments
>> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: add merge=_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2 start=0 end=10
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: add merge to pendingMerges: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2 [total 1 pending]
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge merging= []
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_0(5.6.0):C2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_1(5.6.0):C2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_2(5.6.0):C2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_3(5.6.0):C2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_4(5.6.0):C2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_5(5.6.0):C2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_6(5.6.0):C2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_7(5.6.0):C2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_8(5.6.0):C2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_9(5.6.0):C2
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: consider merge _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: launch new thread [MyMergeThread]
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.59Z; MyMergeThread]: merge thread: start
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.591Z; MyMergeThread]: now apply deletes for 10 merging segments
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.591Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 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> BD 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: applyDeletes: open segment readers took 0 msec
>> [junit4] 1> BD 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: applyDeletes: no segments; skipping
>> [junit4] 1> BD 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: prune sis=segments: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2 minGen=1 packetCount=0
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: merge seg=_a _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: now merge
>> [junit4] 1> merge=_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
>> [junit4] 1> index=_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: merging _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: handleMergeException: merge=_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2 exc=java.io.IOException: now failing during merge
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: hit exception during merge
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: hit tragic IOException inside merge
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: rollback
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: all running merges have aborted
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: rollback: done finish merges
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.593Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
>> [junit4] 1> DW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: abort
>> [junit4] 1> DW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: done abort success=true
>> [junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: rollback: infos=
>> [junit4] 1> MS 100 [2016-02-18T08:41:26.593Z; 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=BE14B687580DC301 -Dtests.slow=true -Dtests.locale=es-PR -Dtests.timezone=Asia/Phnom_Penh -Dtests.asserts=true -Dtests.file.encoding=UTF-8
>> [junit4] FAILURE 0.55s J1 | TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler <<<
>> [junit4] > Throwable #1: java.lang.AssertionError
>> [junit4] > at __randomizedtesting.SeedInfo.seed([BE14B687580DC301:39950B2A5C2DB905]:0)
>> [junit4] > at org.apache.lucene.TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler(TestMergeSchedulerExternal.java:126)
>> [junit4] > at java.lang.Thread.run(Thread.java:745)
>> [junit4] 2> NOTE: test params are: codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}, sim=DefaultSimilarity, locale=es-PR, timezone=Asia/Phnom_Penh
>> [junit4] 2> NOTE: Mac OS X 10.8.5 x86_64/Oracle Corporation 1.8.0_72 (64-bit)/cpus=3,threads=1,free=101265472,total=218628096
>> [junit4] 2> NOTE: All tests run in this JVM: [TestLongBitSet, TestSegmentTermEnum, TestSparseFixedBitSet, TestLucene50SegmentInfoFormat, TestSimpleExplanations, TestStressAdvance, TestExternalCodecs, TestNumericRangeQuery64, TestRegExp, TestIndexReaderClose, TestDirectory, TestFieldValueQuery, TestBitDocIdSetBuilder, TestSortedSetSortField, TestCachingWrapperFilter, TestCharFilter, TestSimilarity2, TestDocTermOrdsRewriteMethod, TestCodecs, TestSortedNumericSortField, TestRecyclingIntBlockAllocator, TestSpansAdvanced, TestIndexWriterMergePolicy, TestNRTCachingDirectory, TestBooleanOr, TestByteArrayDataInput, TestIndexWriterForceMerge, TestBinaryDocValuesUpdates, TestConsistentFieldNumbers, TestFilterSpans, TestLevenshteinAutomata, TestDocValues, TestBagOfPositions, TestSpanMultiTermQueryWrapper, TestSleepingLockWrapper, TestRamUsageEstimator, TestSearcherManager, TestFixedBitSet, TestSentinelIntSet, TestAutomaton, Test2BSortedDocValuesOrds, TestMergeSchedulerExternal]
>> [junit4] Completed [95/421 (1!)] on J1 in 0.59s, 2 tests, 1 failure <<< FAILURES!
>>
>> [...truncated 1060 lines...]
>> BUILD FAILED
>> /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/build.xml:750: The following error occurred while executing this line:
>> /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/build.xml:694: The following error occurred while executing this line:
>> /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/build.xml:59: The following error occurred while executing this line:
>> /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/lucene/build.xml:50: The following error occurred while executing this line:
>> /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/lucene/common-build.xml:1477: The following error occurred while executing this line:
>> /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/lucene/common-build.xml:1033: There were test failures: 421 suites (1 ignored), 3386 tests, 1 failure, 48 ignored (44 assumptions) [seed: BE14B687580DC301]
>>
>> Total time: 7 minutes 18 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
>>
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
>> For additional commands, e-mail: dev-help@lucene.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org
Re: [JENKINS] Lucene-Solr-5.x-MacOSX (64bit/jdk1.8.0) - Build # 3039
- Still Failing!
Posted by Michael McCandless <lu...@mikemccandless.com>.
Ahh, it finally failed again (on OS X). I'll dig.
Mike McCandless
http://blog.mikemccandless.com
On Thu, Feb 18, 2016 at 3:46 AM, Policeman Jenkins Server
<je...@thetaphi.de> wrote:
> Build: http://jenkins.thetaphi.de/job/Lucene-Solr-5.x-MacOSX/3039/
> Java: 64bit/jdk1.8.0 -XX:-UseCompressedOops -XX:+UseParallelGC
>
> 1 tests failed.
> FAILED: org.apache.lucene.TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler
>
> Error Message:
>
>
> Stack Trace:
> java.lang.AssertionError
> at __randomizedtesting.SeedInfo.seed([BE14B687580DC301:39950B2A5C2DB905]: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:126)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1764)
> at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:871)
> at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:907)
> at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:921)
> 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:367)
> at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:809)
> at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:460)
> at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:880)
> at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:781)
> at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:816)
> at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:827)
> 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:367)
> at java.lang.Thread.run(Thread.java:745)
>
>
>
>
> Build Log:
> [...truncated 513 lines...]
> [junit4] Suite: org.apache.lucene.TestMergeSchedulerExternal
> [junit4] 1> TEST FAILED; IW infoStream output:
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: init: current segments file is "segments"; deletionPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy@4fd483a5
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "" [0 segments ; isCommit = false]
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
> [junit4] 1> IW 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: init: create=true
> [junit4] 1> IW 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]:
> [junit4] 1> dir=MockDirectoryWrapper(RAMDirectory@6f9049f8 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@785f410e)
> [junit4] 1> index=
> [junit4] 1> version=5.6.0
> [junit4] 1> analyzer=org.apache.lucene.analysis.MockAnalyzer
> [junit4] 1> ramBufferSizeMB=-1.0
> [junit4] 1> maxBufferedDocs=2
> [junit4] 1> maxBufferedDeleteTerms=-1
> [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.ClassicSimilarity
> [junit4] 1> mergeScheduler=MyMergeScheduler: maxThreadCount=-1, maxMergeCount=-1, ioThrottle=true
> [junit4] 1> default WRITE_LOCK_TIMEOUT=0
> [junit4] 1> writeLockTimeout=0
> [junit4] 1> codec=Asserting(Lucene54): {}, docValues:{}
> [junit4] 1> infoStream=org.apache.lucene.util.PrintStreamInfoStream
> [junit4] 1> mergePolicy=[LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=29, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
> [junit4] 1> indexerThreadPool=org.apache.lucene.index.DocumentsWriterPerThreadPool@28a76779
> [junit4] 1> readerPooling=false
> [junit4] 1> perThreadHardLimitMB=1945
> [junit4] 1> useCompoundFile=false
> [junit4] 1> commitOnClose=true
> [junit4] 1> writer=org.apache.lucene.index.IndexWriter@4515341c
> [junit4] 1>
> [junit4] 1> IW 100 [2016-02-18T08:41:26.108Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: MMapDirectory.UNMAP_SUPPORTED=true
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.12Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _0 numDocs=2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.12Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
> [junit4] 1> IW 100 [2016-02-18T08:41:26.12Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
> [junit4] 1> IW 100 [2016-02-18T08:41:26.124Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
> [junit4] 1> IW 100 [2016-02-18T08:41:26.153Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 28 msec to write postings and finish vectors
> [junit4] 1> IW 100 [2016-02-18T08:41:26.157Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.157Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.157Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.157Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_0.fdx, _0_Asserting_0.doc, _0_Asserting_0.tim, _0.fdt, _0_Asserting_0.tip, _0.fnm]
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.158Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.158Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_0 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
> [junit4] 1> DW 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
> [junit4] 1> IW 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
> [junit4] 1> IW 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=1 seg=_0(5.6.0):C2
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2" [1 segments ; isCommit = false]
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 1 segments
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 1 segments
> [junit4] 1> MS 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: initDynamicDefaults spins=false maxThreadCount=1 maxMergeCount=6
> [junit4] 1> MS 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
> [junit4] 1> MS 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2
> [junit4] 1> MS 100 [2016-02-18T08:41:26.165Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.167Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _1 numDocs=2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.168Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
> [junit4] 1> IW 100 [2016-02-18T08:41:26.168Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
> [junit4] 1> IW 100 [2016-02-18T08:41:26.172Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
> [junit4] 1> IW 100 [2016-02-18T08:41:26.192Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 20 msec to write postings and finish vectors
> [junit4] 1> IW 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_1_Asserting_0.tip, _1_Asserting_0.doc, _1_Asserting_0.tim, _1.fdx, _1.fnm, _1.fdt]
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.195Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.197Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_1 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
> [junit4] 1> DW 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
> [junit4] 1> IW 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
> [junit4] 1> IW 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=2 seg=_1(5.6.0):C2
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2" [2 segments ; isCommit = false]
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 2 segments
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 2 segments
> [junit4] 1> MS 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
> [junit4] 1> MS 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2
> [junit4] 1> MS 100 [2016-02-18T08:41:26.205Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.208Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _2 numDocs=2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.208Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
> [junit4] 1> IW 100 [2016-02-18T08:41:26.208Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
> [junit4] 1> IW 100 [2016-02-18T08:41:26.211Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
> [junit4] 1> IW 100 [2016-02-18T08:41:26.248Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 36 msec to write postings and finish vectors
> [junit4] 1> IW 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_2.fdt, _2_Asserting_0.tip, _2.fnm, _2.fdx, _2_Asserting_0.doc, _2_Asserting_0.tim]
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.252Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.275Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_2 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
> [junit4] 1> DW 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
> [junit4] 1> IW 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
> [junit4] 1> IW 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=3 seg=_2(5.6.0):C2
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2" [3 segments ; isCommit = false]
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 3 segments
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 3 segments
> [junit4] 1> MS 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
> [junit4] 1> MS 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2
> [junit4] 1> MS 100 [2016-02-18T08:41:26.282Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.285Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _3 numDocs=2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.285Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
> [junit4] 1> IW 100 [2016-02-18T08:41:26.285Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
> [junit4] 1> IW 100 [2016-02-18T08:41:26.289Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
> [junit4] 1> IW 100 [2016-02-18T08:41:26.313Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 23 msec to write postings and finish vectors
> [junit4] 1> IW 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 12 msec to write fieldInfos
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_3.fdx, _3_Asserting_0.doc, _3.fnm, _3_Asserting_0.tim, _3.fdt, _3_Asserting_0.tip]
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.325Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_3 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
> [junit4] 1> DW 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
> [junit4] 1> IW 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
> [junit4] 1> IW 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=4 seg=_3(5.6.0):C2
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2" [4 segments ; isCommit = false]
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 4 segments
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 4 segments
> [junit4] 1> MS 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
> [junit4] 1> MS 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2
> [junit4] 1> MS 100 [2016-02-18T08:41:26.332Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.336Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _4 numDocs=2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.336Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
> [junit4] 1> IW 100 [2016-02-18T08:41:26.336Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
> [junit4] 1> IW 100 [2016-02-18T08:41:26.339Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
> [junit4] 1> IW 100 [2016-02-18T08:41:26.354Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 15 msec to write postings and finish vectors
> [junit4] 1> IW 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_4.fdt, _4.fnm, _4_Asserting_0.doc, _4_Asserting_0.tim, _4_Asserting_0.tip, _4.fdx]
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.358Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_4 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
> [junit4] 1> DW 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
> [junit4] 1> IW 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
> [junit4] 1> IW 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=5 seg=_4(5.6.0):C2
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2" [5 segments ; isCommit = false]
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 5 segments
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 5 segments
> [junit4] 1> MS 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
> [junit4] 1> MS 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2
> [junit4] 1> MS 100 [2016-02-18T08:41:26.365Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.368Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _5 numDocs=2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.368Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
> [junit4] 1> IW 100 [2016-02-18T08:41:26.368Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
> [junit4] 1> IW 100 [2016-02-18T08:41:26.372Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
> [junit4] 1> IW 100 [2016-02-18T08:41:26.401Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 28 msec to write postings and finish vectors
> [junit4] 1> IW 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_5.fnm, _5_Asserting_0.tip, _5.fdt, _5_Asserting_0.doc, _5_Asserting_0.tim, _5.fdx]
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.404Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_5 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
> [junit4] 1> DW 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
> [junit4] 1> IW 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
> [junit4] 1> IW 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=6 seg=_5(5.6.0):C2
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2" [6 segments ; isCommit = false]
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 6 segments
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.422Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 6 segments
> [junit4] 1> MS 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
> [junit4] 1> MS 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2
> [junit4] 1> MS 100 [2016-02-18T08:41:26.437Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.44Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _6 numDocs=2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.44Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
> [junit4] 1> IW 100 [2016-02-18T08:41:26.44Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
> [junit4] 1> IW 100 [2016-02-18T08:41:26.444Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
> [junit4] 1> IW 100 [2016-02-18T08:41:26.459Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 15 msec to write postings and finish vectors
> [junit4] 1> IW 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_6_Asserting_0.doc, _6_Asserting_0.tim, _6.fdt, _6.fnm, _6.fdx, _6_Asserting_0.tip]
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.463Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_6 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
> [junit4] 1> DW 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
> [junit4] 1> IW 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
> [junit4] 1> IW 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=7 seg=_6(5.6.0):C2
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2" [7 segments ; isCommit = false]
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 7 segments
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.474Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_6(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 7 segments
> [junit4] 1> MS 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
> [junit4] 1> MS 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2
> [junit4] 1> MS 100 [2016-02-18T08:41:26.487Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.49Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _7 numDocs=2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.49Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
> [junit4] 1> IW 100 [2016-02-18T08:41:26.49Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
> [junit4] 1> IW 100 [2016-02-18T08:41:26.495Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
> [junit4] 1> IW 100 [2016-02-18T08:41:26.51Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 15 msec to write postings and finish vectors
> [junit4] 1> IW 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to write fieldInfos
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_7_Asserting_0.tip, _7.fnm, _7_Asserting_0.doc, _7_Asserting_0.tim, _7.fdt, _7.fdx]
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.514Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_7 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
> [junit4] 1> DW 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
> [junit4] 1> IW 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
> [junit4] 1> IW 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=8 seg=_7(5.6.0):C2
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2" [8 segments ; isCommit = false]
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 8 segments
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_6(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_7(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 8 segments
> [junit4] 1> MS 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
> [junit4] 1> MS 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2
> [junit4] 1> MS 100 [2016-02-18T08:41:26.522Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.525Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _8 numDocs=2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.525Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
> [junit4] 1> IW 100 [2016-02-18T08:41:26.525Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
> [junit4] 1> IW 100 [2016-02-18T08:41:26.529Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to finish stored fields
> [junit4] 1> IW 100 [2016-02-18T08:41:26.544Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 14 msec to write postings and finish vectors
> [junit4] 1> IW 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to write fieldInfos
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_8_Asserting_0.doc, _8_Asserting_0.tim, _8.fdx, _8_Asserting_0.tip, _8.fdt, _8.fnm]
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.548Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_8 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
> [junit4] 1> DW 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
> [junit4] 1> IW 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
> [junit4] 1> IW 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=9 seg=_8(5.6.0):C2
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2" [9 segments ; isCommit = false]
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 9 segments
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_6(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_7(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_8(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 9 segments
> [junit4] 1> MS 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
> [junit4] 1> MS 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2
> [junit4] 1> MS 100 [2016-02-18T08:41:26.555Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.557Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flush postings as segment _9 numDocs=2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.557Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write norms
> [junit4] 1> IW 100 [2016-02-18T08:41:26.557Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to write docValues
> [junit4] 1> IW 100 [2016-02-18T08:41:26.562Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 4 msec to finish stored fields
> [junit4] 1> IW 100 [2016-02-18T08:41:26.577Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 15 msec to write postings and finish vectors
> [junit4] 1> IW 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 3 msec to write fieldInfos
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has 0 deleted docs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: new segment has no vectors; no norms; no docValues; no prox; no freqs
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushedFiles=[_9.fdx, _9.fdt, _9.fnm, _9_Asserting_0.doc, _9_Asserting_0.tim, _9_Asserting_0.tip]
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}
> [junit4] 1> DWPT 100 [2016-02-18T08:41:26.581Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: flushed: segment=_9 ramUsed=0.071 MB newFlushedSize=0.001 MB docs/MB=3,000.217
> [junit4] 1> DW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment seg-private updates=null
> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publishFlushedSegment
> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: publish sets newSegment delGen=10 seg=_9(5.6.0):C2
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now checkpoint "_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2" [10 segments ; isCommit = false]
> [junit4] 1> IFD 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 0 msec to checkpoint
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: findMerges: 10 segments
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_0(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_1(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_2(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_3(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_4(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_5(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_6(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_7(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_8(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: seg=_9(5.6.0):C2 level=3.0503798 size=0.001 MB
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: level -1.0 to 3.0503798: 10 segments
> [junit4] 1> LMP 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: add merge=_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2 start=0 end=10
> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: add merge to pendingMerges: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2 [total 1 pending]
> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge merging= []
> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_0(5.6.0):C2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_1(5.6.0):C2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_2(5.6.0):C2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_3(5.6.0):C2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_4(5.6.0):C2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_5(5.6.0):C2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_6(5.6.0):C2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_7(5.6.0):C2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_8(5.6.0):C2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: registerMerge info=_9(5.6.0):C2
> [junit4] 1> MS 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: now merge
> [junit4] 1> MS 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: index: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
> [junit4] 1> MS 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: consider merge _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
> [junit4] 1> MS 100 [2016-02-18T08:41:26.586Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: launch new thread [MyMergeThread]
> [junit4] 1> MS 100 [2016-02-18T08:41:26.59Z; MyMergeThread]: merge thread: start
> [junit4] 1> IW 100 [2016-02-18T08:41:26.591Z; MyMergeThread]: now apply deletes for 10 merging segments
> [junit4] 1> MS 100 [2016-02-18T08:41:26.591Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: 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> BD 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: applyDeletes: open segment readers took 0 msec
> [junit4] 1> BD 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: applyDeletes: no segments; skipping
> [junit4] 1> BD 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: prune sis=segments: _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2 minGen=1 packetCount=0
> [junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: merge seg=_a _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: now merge
> [junit4] 1> merge=_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
> [junit4] 1> index=_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: merging _0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2
> [junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: handleMergeException: merge=_0(5.6.0):C2 _1(5.6.0):C2 _2(5.6.0):C2 _3(5.6.0):C2 _4(5.6.0):C2 _5(5.6.0):C2 _6(5.6.0):C2 _7(5.6.0):C2 _8(5.6.0):C2 _9(5.6.0):C2 exc=java.io.IOException: now failing during merge
> [junit4] 1> IW 100 [2016-02-18T08:41:26.592Z; MyMergeThread]: hit exception during merge
> [junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: hit tragic IOException inside merge
> [junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: rollback
> [junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: all running merges have aborted
> [junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: rollback: done finish merges
> [junit4] 1> MS 100 [2016-02-18T08:41:26.593Z; TEST-TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler-seed#[BE14B687580DC301]]: no more merges pending; now return
> [junit4] 1> DW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: abort
> [junit4] 1> DW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: done abort success=true
> [junit4] 1> IW 100 [2016-02-18T08:41:26.593Z; MyMergeThread]: rollback: infos=
> [junit4] 1> MS 100 [2016-02-18T08:41:26.593Z; 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=BE14B687580DC301 -Dtests.slow=true -Dtests.locale=es-PR -Dtests.timezone=Asia/Phnom_Penh -Dtests.asserts=true -Dtests.file.encoding=UTF-8
> [junit4] FAILURE 0.55s J1 | TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler <<<
> [junit4] > Throwable #1: java.lang.AssertionError
> [junit4] > at __randomizedtesting.SeedInfo.seed([BE14B687580DC301:39950B2A5C2DB905]:0)
> [junit4] > at org.apache.lucene.TestMergeSchedulerExternal.testSubclassConcurrentMergeScheduler(TestMergeSchedulerExternal.java:126)
> [junit4] > at java.lang.Thread.run(Thread.java:745)
> [junit4] 2> NOTE: test params are: codec=Asserting(Lucene54): {id=PostingsFormat(name=Asserting)}, docValues:{}, sim=DefaultSimilarity, locale=es-PR, timezone=Asia/Phnom_Penh
> [junit4] 2> NOTE: Mac OS X 10.8.5 x86_64/Oracle Corporation 1.8.0_72 (64-bit)/cpus=3,threads=1,free=101265472,total=218628096
> [junit4] 2> NOTE: All tests run in this JVM: [TestLongBitSet, TestSegmentTermEnum, TestSparseFixedBitSet, TestLucene50SegmentInfoFormat, TestSimpleExplanations, TestStressAdvance, TestExternalCodecs, TestNumericRangeQuery64, TestRegExp, TestIndexReaderClose, TestDirectory, TestFieldValueQuery, TestBitDocIdSetBuilder, TestSortedSetSortField, TestCachingWrapperFilter, TestCharFilter, TestSimilarity2, TestDocTermOrdsRewriteMethod, TestCodecs, TestSortedNumericSortField, TestRecyclingIntBlockAllocator, TestSpansAdvanced, TestIndexWriterMergePolicy, TestNRTCachingDirectory, TestBooleanOr, TestByteArrayDataInput, TestIndexWriterForceMerge, TestBinaryDocValuesUpdates, TestConsistentFieldNumbers, TestFilterSpans, TestLevenshteinAutomata, TestDocValues, TestBagOfPositions, TestSpanMultiTermQueryWrapper, TestSleepingLockWrapper, TestRamUsageEstimator, TestSearcherManager, TestFixedBitSet, TestSentinelIntSet, TestAutomaton, Test2BSortedDocValuesOrds, TestMergeSchedulerExternal]
> [junit4] Completed [95/421 (1!)] on J1 in 0.59s, 2 tests, 1 failure <<< FAILURES!
>
> [...truncated 1060 lines...]
> BUILD FAILED
> /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/build.xml:750: The following error occurred while executing this line:
> /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/build.xml:694: The following error occurred while executing this line:
> /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/build.xml:59: The following error occurred while executing this line:
> /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/lucene/build.xml:50: The following error occurred while executing this line:
> /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/lucene/common-build.xml:1477: The following error occurred while executing this line:
> /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/lucene/common-build.xml:1033: There were test failures: 421 suites (1 ignored), 3386 tests, 1 failure, 48 ignored (44 assumptions) [seed: BE14B687580DC301]
>
> Total time: 7 minutes 18 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
>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
> For additional commands, e-mail: dev-help@lucene.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org