Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 4.0-ALPHA
    • Component/s: None
    • Labels:
      None
    • Lucene Fields:
      New

      Description

      Build server logs. Reproduces on at least two machines.

          [junit] ------------- Standard Error -----------------
          [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8"
          [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Etc/GMT+1
          [junit] NOTE: all tests run in this JVM:
          [junit] [TestStressNRT]
          [junit] NOTE: Linux 3.0.0-16-generic amd64/Sun Microsystems Inc. 1.6.0_27 (64-bit)/cpus=2,threads=1,free=74960064,total=135987200
          [junit] ------------- ---------------- ---------------
          [junit] Testcase: test(org.apache.lucene.index.TestStressNRT):	Caused an ERROR
          [junit] MockDirectoryWrapper: cannot close: there are still open files: {_ng.cfs=8}
          [junit] java.lang.RuntimeException: MockDirectoryWrapper: cannot close: there are still open files: {_ng.cfs=8}
          [junit] 	at org.apache.lucene.store.MockDirectoryWrapper.close(MockDirectoryWrapper.java:555)
          [junit] 	at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:385)
          [junit] 	at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743)
          [junit] 	at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639)
          [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
          [junit] 	at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538)
          [junit] 	at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600)
          [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164)
          [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57)
          [junit] 	at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21)
          [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
          [junit] Caused by: java.lang.RuntimeException: unclosed IndexInput: _ng.cfs
          [junit] 	at org.apache.lucene.store.MockDirectoryWrapper.addFileHandle(MockDirectoryWrapper.java:479)
          [junit] 	at org.apache.lucene.store.MockDirectoryWrapper$1.openSlice(MockDirectoryWrapper.java:777)
          [junit] 	at org.apache.lucene.store.CompoundFileDirectory.openInput(CompoundFileDirectory.java:221)
          [junit] 	at org.apache.lucene.codecs.lucene3x.TermInfosReader.<init>(TermInfosReader.java:112)
          [junit] 	at org.apache.lucene.codecs.lucene3x.Lucene3xFields.<init>(Lucene3xFields.java:84)
          [junit] 	at org.apache.lucene.codecs.lucene3x.PreFlexRWPostingsFormat$1.<init>(PreFlexRWPostingsFormat.java:51)
          [junit] 	at org.apache.lucene.codecs.lucene3x.PreFlexRWPostingsFormat.fieldsProducer(PreFlexRWPostingsFormat.java:51)
          [junit] 	at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:108)
          [junit] 	at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:51)
          [junit] 	at org.apache.lucene.index.IndexWriter$ReadersAndLiveDocs.getMergeReader(IndexWriter.java:521)
          [junit] 	at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3587)
          [junit] 	at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257)
          [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382)
          [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451)
          [junit] 
          [junit] 
          [junit] Test org.apache.lucene.index.TestStressNRT FAILED
      
      1. output1.log
        5 kB
        Dawid Weiss
      2. output2.log
        5 kB
        Dawid Weiss
      3. output3.log
        5 kB
        Dawid Weiss
      4. output4.log
        6 kB
        Dawid Weiss
      5. hoss-r1298470-fixed-seed__TEST-org.apache.lucene.index.TestStressNRT.xml
        18 kB
        Hoss Man
      6. LUCENE-3855.patch
        43 kB
        Michael McCandless

        Activity

        Hide
        Robert Muir added a comment -

        This must be a timing issue/race of some sort?

        Doesn't reproduce on my machine... does it need multiple iterations usually to fail?

        Show
        Robert Muir added a comment - This must be a timing issue/race of some sort? Doesn't reproduce on my machine... does it need multiple iterations usually to fail?
        Hide
        Dawid Weiss added a comment -

        Ok, it doesn't always happen, but it happens quite frequently (I re-run the test from scratch, didn't use repetitions). Interestingly, the problem seems to be different every time. I'll attach logs.

        Show
        Dawid Weiss added a comment - Ok, it doesn't always happen, but it happens quite frequently (I re-run the test from scratch, didn't use repetitions). Interestingly, the problem seems to be different every time. I'll attach logs.
        Hide
        Dawid Weiss added a comment -

        Four executions, four errors (same seed).

        Show
        Dawid Weiss added a comment - Four executions, four errors (same seed).
        Hide
        Dawid Weiss added a comment -
        junit-sequential:
            [junit] Testsuite: org.apache.lucene.index.TestStressNRT
            [junit] Tests run: 1, Failures: 0, Errors: 1, Time elapsed: 10.377 sec
            [junit] 
            [junit] ------------- Standard Error -----------------
            [junit] The following exceptions were thrown by threads:
            [junit] *** Thread: Lucene Merge Thread #133 ***
            [junit] org.apache.lucene.index.MergePolicy$MergeException: java.lang.AssertionError
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeException(ConcurrentMergeScheduler.java:507)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:480)
            [junit] Caused by: java.lang.AssertionError
            [junit] 	at org.apache.lucene.index.IndexWriter.commitMergedDeletes(IndexWriter.java:3028)
            [junit] 	at org.apache.lucene.index.IndexWriter.commitMerge(IndexWriter.java:3137)
            [junit] 	at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3718)
            [junit] 	at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451)
            [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8"
            [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8"
            [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Etc/GMT+1
            [junit] NOTE: all tests run in this JVM:
            [junit] [TestStressNRT]
            [junit] NOTE: Linux 3.0.0-16-generic amd64/Sun Microsystems Inc. 1.6.0_27 (64-bit)/cpus=2,threads=1,free=86308600,total=202244096
            [junit] ------------- ---------------- ---------------
            [junit] Testcase: test(org.apache.lucene.index.TestStressNRT):	Caused an ERROR
            [junit] java.lang.AssertionError: Some threads threw uncaught exceptions!
            [junit] java.lang.RuntimeException: java.lang.AssertionError: Some threads threw uncaught exceptions!
            [junit] 	at org.apache.lucene.util.LuceneTestCase.tearDownInternal(LuceneTestCase.java:816)
            [junit] 	at org.apache.lucene.util.LuceneTestCase.access$1100(LuceneTestCase.java:137)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:640)
            [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57)
            [junit] 	at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21)
            [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit] Caused by: java.lang.AssertionError: Some threads threw uncaught exceptions!
            [junit] 	at org.apache.lucene.util.LuceneTestCase.checkUncaughtExceptionsAfter(LuceneTestCase.java:844)
            [junit] 	at org.apache.lucene.util.LuceneTestCase.tearDownInternal(LuceneTestCase.java:788)
            [junit] 
            [junit] 
        
        junit-sequential:
            [junit] Testsuite: org.apache.lucene.index.TestStressNRT
            [junit] Tests run: 1, Failures: 0, Errors: 1, Time elapsed: 11.454 sec
            [junit] 
            [junit] ------------- Standard Error -----------------
            [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8"
            [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Etc/GMT+1
            [junit] NOTE: all tests run in this JVM:
            [junit] [TestStressNRT]
            [junit] NOTE: Linux 3.0.0-16-generic amd64/Sun Microsystems Inc. 1.6.0_27 (64-bit)/cpus=2,threads=1,free=77427992,total=143851520
            [junit] ------------- ---------------- ---------------
            [junit] Testcase: test(org.apache.lucene.index.TestStressNRT):	Caused an ERROR
            [junit] MockDirectoryWrapper: cannot close: there are still open files: {_eb.cfs=5}
            [junit] java.lang.RuntimeException: MockDirectoryWrapper: cannot close: there are still open files: {_eb.cfs=5}
            [junit] 	at org.apache.lucene.store.MockDirectoryWrapper.close(MockDirectoryWrapper.java:555)
            [junit] 	at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:385)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639)
            [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57)
            [junit] 	at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21)
            [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit] Caused by: java.lang.RuntimeException: unclosed IndexInput: _eb.cfs
            [junit] 	at org.apache.lucene.store.MockDirectoryWrapper.addFileHandle(MockDirectoryWrapper.java:479)
            [junit] 	at org.apache.lucene.store.MockDirectoryWrapper$1.openSlice(MockDirectoryWrapper.java:777)
            [junit] 	at org.apache.lucene.store.CompoundFileDirectory.openInput(CompoundFileDirectory.java:221)
            [junit] 	at org.apache.lucene.codecs.lucene3x.TermInfosReader.<init>(TermInfosReader.java:112)
            [junit] 	at org.apache.lucene.codecs.lucene3x.Lucene3xFields.<init>(Lucene3xFields.java:84)
            [junit] 	at org.apache.lucene.codecs.lucene3x.PreFlexRWPostingsFormat$1.<init>(PreFlexRWPostingsFormat.java:51)
            [junit] 	at org.apache.lucene.codecs.lucene3x.PreFlexRWPostingsFormat.fieldsProducer(PreFlexRWPostingsFormat.java:51)
            [junit] 	at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:108)
            [junit] 	at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:51)
            [junit] 	at org.apache.lucene.index.IndexWriter$ReadersAndLiveDocs.getMergeReader(IndexWriter.java:521)
            [junit] 	at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3587)
            [junit] 	at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451)
            [junit] 
            [junit] 
        
        junit-sequential:
            [junit] Testsuite: org.apache.lucene.index.TestStressNRT
            [junit] Tests run: 1, Failures: 0, Errors: 1, Time elapsed: 10.892 sec
            [junit] 
            [junit] ------------- Standard Error -----------------
            [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8"
            [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Etc/GMT+1
            [junit] NOTE: all tests run in this JVM:
            [junit] [TestStressNRT]
            [junit] NOTE: Linux 3.0.0-16-generic amd64/Sun Microsystems Inc. 1.6.0_27 (64-bit)/cpus=2,threads=1,free=70056648,total=148111360
            [junit] ------------- ---------------- ---------------
            [junit] Testcase: test(org.apache.lucene.index.TestStressNRT):	Caused an ERROR
            [junit] MockDirectoryWrapper: cannot close: there are still open files: {_30.frq=1, _l8.cfs=5, _30.tis=1, _30.tvx=1, _30.fdx=1, _30.fdt=1, _30.tvf=1, _30.tvd=1}
            [junit] java.lang.RuntimeException: MockDirectoryWrapper: cannot close: there are still open files: {_30.frq=1, _l8.cfs=5, _30.tis=1, _30.tvx=1, _30.fdx=1, _30.fdt=1, _30.tvf=1, _30.tvd=1}
            [junit] 	at org.apache.lucene.store.MockDirectoryWrapper.close(MockDirectoryWrapper.java:555)
            [junit] 	at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:385)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639)
            [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57)
            [junit] 	at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21)
            [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit] Caused by: java.lang.RuntimeException: unclosed IndexInput: _30.tis
            [junit] 	at org.apache.lucene.store.MockDirectoryWrapper.addFileHandle(MockDirectoryWrapper.java:479)
            [junit] 	at org.apache.lucene.store.MockDirectoryWrapper.openInput(MockDirectoryWrapper.java:504)
            [junit] 	at org.apache.lucene.codecs.lucene3x.TermInfosReader.<init>(TermInfosReader.java:112)
            [junit] 	at org.apache.lucene.codecs.lucene3x.Lucene3xFields.<init>(Lucene3xFields.java:84)
            [junit] 	at org.apache.lucene.codecs.lucene3x.PreFlexRWPostingsFormat$1.<init>(PreFlexRWPostingsFormat.java:51)
            [junit] 	at org.apache.lucene.codecs.lucene3x.PreFlexRWPostingsFormat.fieldsProducer(PreFlexRWPostingsFormat.java:51)
            [junit] 	at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:108)
            [junit] 	at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:51)
            [junit] 	at org.apache.lucene.index.IndexWriter$ReadersAndLiveDocs.getMergeReader(IndexWriter.java:521)
            [junit] 	at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3587)
            [junit] 	at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451)
            [junit] 
            [junit] 
        
        junit-sequential:
            [junit] Testsuite: org.apache.lucene.index.TestStressNRT
            [junit] Tests run: 1, Failures: 0, Errors: 1, Time elapsed: 11.678 sec
            [junit] 
            [junit] ------------- Standard Error -----------------
            [junit] The following exceptions were thrown by threads:
            [junit] *** Thread: Lucene Merge Thread #78 ***
            [junit] org.apache.lucene.index.MergePolicy$MergeException: java.lang.AssertionError
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeException(ConcurrentMergeScheduler.java:507)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:480)
            [junit] Caused by: java.lang.AssertionError
            [junit] 	at org.apache.lucene.index.IndexWriter.commitMergedDeletes(IndexWriter.java:3028)
            [junit] 	at org.apache.lucene.index.IndexWriter.commitMerge(IndexWriter.java:3137)
            [junit] 	at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3718)
            [junit] 	at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451)
            [junit] *** Thread: Lucene Merge Thread #125 ***
            [junit] org.apache.lucene.index.MergePolicy$MergeException: java.lang.AssertionError
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeException(ConcurrentMergeScheduler.java:507)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:480)
            [junit] Caused by: java.lang.AssertionError
            [junit] 	at org.apache.lucene.index.IndexWriter.commitMergedDeletes(IndexWriter.java:3028)
            [junit] 	at org.apache.lucene.index.IndexWriter.commitMerge(IndexWriter.java:3137)
            [junit] 	at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3718)
            [junit] 	at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451)
            [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8"
            [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8"
            [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Etc/GMT+1
            [junit] NOTE: all tests run in this JVM:
            [junit] [TestStressNRT]
            [junit] NOTE: Linux 3.0.0-16-generic amd64/Sun Microsystems Inc. 1.6.0_27 (64-bit)/cpus=2,threads=1,free=135293744,total=194379776
            [junit] ------------- ---------------- ---------------
            [junit] Testcase: test(org.apache.lucene.index.TestStressNRT):	Caused an ERROR
            [junit] java.lang.AssertionError: Some threads threw uncaught exceptions!
            [junit] java.lang.RuntimeException: java.lang.AssertionError: Some threads threw uncaught exceptions!
            [junit] 	at org.apache.lucene.util.LuceneTestCase.tearDownInternal(LuceneTestCase.java:816)
            [junit] 	at org.apache.lucene.util.LuceneTestCase.access$1100(LuceneTestCase.java:137)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:640)
            [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57)
            [junit] 	at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21)
            [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit] Caused by: java.lang.AssertionError: Some threads threw uncaught exceptions!
            [junit] 	at org.apache.lucene.util.LuceneTestCase.checkUncaughtExceptionsAfter(LuceneTestCase.java:844)
            [junit] 	at org.apache.lucene.util.LuceneTestCase.tearDownInternal(LuceneTestCase.java:788)
            [junit] 
            [junit] 
        
        Show
        Dawid Weiss added a comment - junit-sequential: [junit] Testsuite: org.apache.lucene.index.TestStressNRT [junit] Tests run: 1, Failures: 0, Errors: 1, Time elapsed: 10.377 sec [junit] [junit] ------------- Standard Error ----------------- [junit] The following exceptions were thrown by threads: [junit] *** Thread: Lucene Merge Thread #133 *** [junit] org.apache.lucene.index.MergePolicy$MergeException: java.lang.AssertionError [junit] at org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeException(ConcurrentMergeScheduler.java:507) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:480) [junit] Caused by: java.lang.AssertionError [junit] at org.apache.lucene.index.IndexWriter.commitMergedDeletes(IndexWriter.java:3028) [junit] at org.apache.lucene.index.IndexWriter.commitMerge(IndexWriter.java:3137) [junit] at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3718) [junit] at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451) [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8" [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8" [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Etc/GMT+1 [junit] NOTE: all tests run in this JVM: [junit] [TestStressNRT] [junit] NOTE: Linux 3.0.0-16-generic amd64/Sun Microsystems Inc. 1.6.0_27 (64-bit)/cpus=2,threads=1,free=86308600,total=202244096 [junit] ------------- ---------------- --------------- [junit] Testcase: test(org.apache.lucene.index.TestStressNRT): Caused an ERROR [junit] java.lang.AssertionError: Some threads threw uncaught exceptions! [junit] java.lang.RuntimeException: java.lang.AssertionError: Some threads threw uncaught exceptions! [junit] at org.apache.lucene.util.LuceneTestCase.tearDownInternal(LuceneTestCase.java:816) [junit] at org.apache.lucene.util.LuceneTestCase.access$1100(LuceneTestCase.java:137) [junit] at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:640) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538) [junit] at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57) [junit] at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] Caused by: java.lang.AssertionError: Some threads threw uncaught exceptions! [junit] at org.apache.lucene.util.LuceneTestCase.checkUncaughtExceptionsAfter(LuceneTestCase.java:844) [junit] at org.apache.lucene.util.LuceneTestCase.tearDownInternal(LuceneTestCase.java:788) [junit] [junit] junit-sequential: [junit] Testsuite: org.apache.lucene.index.TestStressNRT [junit] Tests run: 1, Failures: 0, Errors: 1, Time elapsed: 11.454 sec [junit] [junit] ------------- Standard Error ----------------- [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8" [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Etc/GMT+1 [junit] NOTE: all tests run in this JVM: [junit] [TestStressNRT] [junit] NOTE: Linux 3.0.0-16-generic amd64/Sun Microsystems Inc. 1.6.0_27 (64-bit)/cpus=2,threads=1,free=77427992,total=143851520 [junit] ------------- ---------------- --------------- [junit] Testcase: test(org.apache.lucene.index.TestStressNRT): Caused an ERROR [junit] MockDirectoryWrapper: cannot close: there are still open files: {_eb.cfs=5} [junit] java.lang.RuntimeException: MockDirectoryWrapper: cannot close: there are still open files: {_eb.cfs=5} [junit] at org.apache.lucene.store.MockDirectoryWrapper.close(MockDirectoryWrapper.java:555) [junit] at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:385) [junit] at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743) [junit] at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538) [junit] at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57) [junit] at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] Caused by: java.lang.RuntimeException: unclosed IndexInput: _eb.cfs [junit] at org.apache.lucene.store.MockDirectoryWrapper.addFileHandle(MockDirectoryWrapper.java:479) [junit] at org.apache.lucene.store.MockDirectoryWrapper$1.openSlice(MockDirectoryWrapper.java:777) [junit] at org.apache.lucene.store.CompoundFileDirectory.openInput(CompoundFileDirectory.java:221) [junit] at org.apache.lucene.codecs.lucene3x.TermInfosReader.<init>(TermInfosReader.java:112) [junit] at org.apache.lucene.codecs.lucene3x.Lucene3xFields.<init>(Lucene3xFields.java:84) [junit] at org.apache.lucene.codecs.lucene3x.PreFlexRWPostingsFormat$1.<init>(PreFlexRWPostingsFormat.java:51) [junit] at org.apache.lucene.codecs.lucene3x.PreFlexRWPostingsFormat.fieldsProducer(PreFlexRWPostingsFormat.java:51) [junit] at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:108) [junit] at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:51) [junit] at org.apache.lucene.index.IndexWriter$ReadersAndLiveDocs.getMergeReader(IndexWriter.java:521) [junit] at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3587) [junit] at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451) [junit] [junit] junit-sequential: [junit] Testsuite: org.apache.lucene.index.TestStressNRT [junit] Tests run: 1, Failures: 0, Errors: 1, Time elapsed: 10.892 sec [junit] [junit] ------------- Standard Error ----------------- [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8" [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Etc/GMT+1 [junit] NOTE: all tests run in this JVM: [junit] [TestStressNRT] [junit] NOTE: Linux 3.0.0-16-generic amd64/Sun Microsystems Inc. 1.6.0_27 (64-bit)/cpus=2,threads=1,free=70056648,total=148111360 [junit] ------------- ---------------- --------------- [junit] Testcase: test(org.apache.lucene.index.TestStressNRT): Caused an ERROR [junit] MockDirectoryWrapper: cannot close: there are still open files: {_30.frq=1, _l8.cfs=5, _30.tis=1, _30.tvx=1, _30.fdx=1, _30.fdt=1, _30.tvf=1, _30.tvd=1} [junit] java.lang.RuntimeException: MockDirectoryWrapper: cannot close: there are still open files: {_30.frq=1, _l8.cfs=5, _30.tis=1, _30.tvx=1, _30.fdx=1, _30.fdt=1, _30.tvf=1, _30.tvd=1} [junit] at org.apache.lucene.store.MockDirectoryWrapper.close(MockDirectoryWrapper.java:555) [junit] at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:385) [junit] at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743) [junit] at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538) [junit] at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57) [junit] at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] Caused by: java.lang.RuntimeException: unclosed IndexInput: _30.tis [junit] at org.apache.lucene.store.MockDirectoryWrapper.addFileHandle(MockDirectoryWrapper.java:479) [junit] at org.apache.lucene.store.MockDirectoryWrapper.openInput(MockDirectoryWrapper.java:504) [junit] at org.apache.lucene.codecs.lucene3x.TermInfosReader.<init>(TermInfosReader.java:112) [junit] at org.apache.lucene.codecs.lucene3x.Lucene3xFields.<init>(Lucene3xFields.java:84) [junit] at org.apache.lucene.codecs.lucene3x.PreFlexRWPostingsFormat$1.<init>(PreFlexRWPostingsFormat.java:51) [junit] at org.apache.lucene.codecs.lucene3x.PreFlexRWPostingsFormat.fieldsProducer(PreFlexRWPostingsFormat.java:51) [junit] at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:108) [junit] at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:51) [junit] at org.apache.lucene.index.IndexWriter$ReadersAndLiveDocs.getMergeReader(IndexWriter.java:521) [junit] at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3587) [junit] at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451) [junit] [junit] junit-sequential: [junit] Testsuite: org.apache.lucene.index.TestStressNRT [junit] Tests run: 1, Failures: 0, Errors: 1, Time elapsed: 11.678 sec [junit] [junit] ------------- Standard Error ----------------- [junit] The following exceptions were thrown by threads: [junit] *** Thread: Lucene Merge Thread #78 *** [junit] org.apache.lucene.index.MergePolicy$MergeException: java.lang.AssertionError [junit] at org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeException(ConcurrentMergeScheduler.java:507) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:480) [junit] Caused by: java.lang.AssertionError [junit] at org.apache.lucene.index.IndexWriter.commitMergedDeletes(IndexWriter.java:3028) [junit] at org.apache.lucene.index.IndexWriter.commitMerge(IndexWriter.java:3137) [junit] at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3718) [junit] at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451) [junit] *** Thread: Lucene Merge Thread #125 *** [junit] org.apache.lucene.index.MergePolicy$MergeException: java.lang.AssertionError [junit] at org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeException(ConcurrentMergeScheduler.java:507) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:480) [junit] Caused by: java.lang.AssertionError [junit] at org.apache.lucene.index.IndexWriter.commitMergedDeletes(IndexWriter.java:3028) [junit] at org.apache.lucene.index.IndexWriter.commitMerge(IndexWriter.java:3137) [junit] at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3718) [junit] at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451) [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8" [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8" [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Etc/GMT+1 [junit] NOTE: all tests run in this JVM: [junit] [TestStressNRT] [junit] NOTE: Linux 3.0.0-16-generic amd64/Sun Microsystems Inc. 1.6.0_27 (64-bit)/cpus=2,threads=1,free=135293744,total=194379776 [junit] ------------- ---------------- --------------- [junit] Testcase: test(org.apache.lucene.index.TestStressNRT): Caused an ERROR [junit] java.lang.AssertionError: Some threads threw uncaught exceptions! [junit] java.lang.RuntimeException: java.lang.AssertionError: Some threads threw uncaught exceptions! [junit] at org.apache.lucene.util.LuceneTestCase.tearDownInternal(LuceneTestCase.java:816) [junit] at org.apache.lucene.util.LuceneTestCase.access$1100(LuceneTestCase.java:137) [junit] at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:640) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538) [junit] at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57) [junit] at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] Caused by: java.lang.AssertionError: Some threads threw uncaught exceptions! [junit] at org.apache.lucene.util.LuceneTestCase.checkUncaughtExceptionsAfter(LuceneTestCase.java:844) [junit] at org.apache.lucene.util.LuceneTestCase.tearDownInternal(LuceneTestCase.java:788) [junit] [junit]
        Hide
        Dawid Weiss added a comment -

        I began to think it's the Java version/ jvm bug that is causing these, but doesn't seem like it. Ran with the newest JRE 1.6:

        junit-sequential:
            [junit] Testsuite: org.apache.lucene.index.TestStressNRT
            [junit] Tests run: 1, Failures: 1, Errors: 0, Time elapsed: 9.536 sec
            [junit]
            [junit] ------------- Standard Error -----------------
            [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8"
            [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=US/East-Indiana
            [junit] NOTE: all tests run in this JVM:
            [junit] [TestStressNRT]
            [junit] NOTE: Linux 3.0.0-16-generic amd64/Sun Microsystems Inc. 1.6.0_31 (64-bit)/cpus=2,threads=1,free=95936736,total=148307968
            [junit] ------------- ---------------- ---------------
            [junit] Testcase: test(org.apache.lucene.index.TestStressNRT):      FAILED
            [junit] info=_gx(4.0):C9/7 isn't live
            [junit] junit.framework.AssertionFailedError: info=_gx(4.0):C9/7 isn't live
            [junit]     at org.apache.lucene.index.IndexWriter$ReaderPool.infoIsLive(IndexWriter.java:663)
            [junit]     at org.apache.lucene.index.IndexWriter$ReaderPool.dropAll(IndexWriter.java:717)
            [junit]     at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:1136)
            [junit]     at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1069)
            [junit]     at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1033)
            [junit]     at org.apache.lucene.index.RandomIndexWriter.close(RandomIndexWriter.java:408)
            [junit]     at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:380)
            [junit]     at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743)
            [junit]     at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639)
            [junit]     at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit]     at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538)
            [junit]     at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600)
            [junit]     at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164)
            [junit]     at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57)
            [junit]     at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21)
            [junit]     at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit]
            [junit]
            [junit] Test org.apache.lucene.index.TestStressNRT FAILED
        
        Show
        Dawid Weiss added a comment - I began to think it's the Java version/ jvm bug that is causing these, but doesn't seem like it. Ran with the newest JRE 1.6: junit-sequential: [junit] Testsuite: org.apache.lucene.index.TestStressNRT [junit] Tests run: 1, Failures: 1, Errors: 0, Time elapsed: 9.536 sec [junit] [junit] ------------- Standard Error ----------------- [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8" [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=US/East-Indiana [junit] NOTE: all tests run in this JVM: [junit] [TestStressNRT] [junit] NOTE: Linux 3.0.0-16-generic amd64/Sun Microsystems Inc. 1.6.0_31 (64-bit)/cpus=2,threads=1,free=95936736,total=148307968 [junit] ------------- ---------------- --------------- [junit] Testcase: test(org.apache.lucene.index.TestStressNRT): FAILED [junit] info=_gx(4.0):C9/7 isn't live [junit] junit.framework.AssertionFailedError: info=_gx(4.0):C9/7 isn't live [junit] at org.apache.lucene.index.IndexWriter$ReaderPool.infoIsLive(IndexWriter.java:663) [junit] at org.apache.lucene.index.IndexWriter$ReaderPool.dropAll(IndexWriter.java:717) [junit] at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:1136) [junit] at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1069) [junit] at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1033) [junit] at org.apache.lucene.index.RandomIndexWriter.close(RandomIndexWriter.java:408) [junit] at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:380) [junit] at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743) [junit] at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538) [junit] at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57) [junit] at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] [junit] [junit] Test org.apache.lucene.index.TestStressNRT FAILED
        Hide
        Dawid Weiss added a comment -

        Can't reproduce this on Windows, interestingly. But on another Ubuntu machine, without a problem –

        junit-sequential:
            [junit] Testsuite: org.apache.lucene.index.TestStressNRT
            [junit] Tests run: 1, Failures: 1, Errors: 0, Time elapsed: 4.449 sec
            [junit]
            [junit] ------------- Standard Error -----------------
            [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8"
            [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Etc/GMT+11
            [junit] NOTE: all tests run in this JVM:
            [junit] [TestStressNRT]
            [junit] NOTE: Linux 2.6.32-38-server amd64/Sun Microsystems Inc. 1.6.0_20 (64-bit)/cpus=4,threads=1,free=150044128,total=174260224
            [junit] ------------- ---------------- ---------------
            [junit] Testcase: test(org.apache.lucene.index.TestStressNRT):      FAILED
            [junit] info=_dm(4.0):cv6/4 isn't live
            [junit] junit.framework.AssertionFailedError: info=_dm(4.0):cv6/4 isn't live
            [junit]     at org.apache.lucene.index.IndexWriter$ReaderPool.infoIsLive(IndexWriter.java:663)
            [junit]     at org.apache.lucene.index.IndexWriter$ReaderPool.dropAll(IndexWriter.java:717)
            [junit]     at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:1136)
            [junit]     at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1069)
            [junit]     at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1033)
            [junit]     at org.apache.lucene.index.RandomIndexWriter.close(RandomIndexWriter.java:408)
            [junit]     at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:380)
            [junit]     at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743)
            [junit]     at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639)
            [junit]     at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit]     at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538)
            [junit]     at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600)
            [junit]     at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164)
            [junit]     at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57)
            [junit]     at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21)
            [junit]     at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit]
            [junit]
            [junit] Test org.apache.lucene.index.TestStressNRT FAILED
        
        Show
        Dawid Weiss added a comment - Can't reproduce this on Windows, interestingly. But on another Ubuntu machine, without a problem – junit-sequential: [junit] Testsuite: org.apache.lucene.index.TestStressNRT [junit] Tests run: 1, Failures: 1, Errors: 0, Time elapsed: 4.449 sec [junit] [junit] ------------- Standard Error ----------------- [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8" [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Etc/GMT+11 [junit] NOTE: all tests run in this JVM: [junit] [TestStressNRT] [junit] NOTE: Linux 2.6.32-38-server amd64/Sun Microsystems Inc. 1.6.0_20 (64-bit)/cpus=4,threads=1,free=150044128,total=174260224 [junit] ------------- ---------------- --------------- [junit] Testcase: test(org.apache.lucene.index.TestStressNRT): FAILED [junit] info=_dm(4.0):cv6/4 isn't live [junit] junit.framework.AssertionFailedError: info=_dm(4.0):cv6/4 isn't live [junit] at org.apache.lucene.index.IndexWriter$ReaderPool.infoIsLive(IndexWriter.java:663) [junit] at org.apache.lucene.index.IndexWriter$ReaderPool.dropAll(IndexWriter.java:717) [junit] at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:1136) [junit] at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1069) [junit] at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1033) [junit] at org.apache.lucene.index.RandomIndexWriter.close(RandomIndexWriter.java:408) [junit] at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:380) [junit] at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743) [junit] at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538) [junit] at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57) [junit] at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] [junit] [junit] Test org.apache.lucene.index.TestStressNRT FAILED
        Hide
        Gilad Barkai added a comment -

        It fails here as well, not as often though,

            [junit] ------------- Standard Error -----------------
            [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8"
            [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=US/East-Indiana
            [junit] NOTE: all tests run in this JVM:
            [junit] [TestStressNRT]
            [junit] NOTE: Linux 3.2.7-1.fc16.x86_64 amd64/Sun Microsystems Inc. 1.6.0_24 (64-bit)/cpus=2,threads=1,free=44668576,total=133169152
            [junit] ------------- ---------------- ---------------
        
            [junit] Testcase: test(org.apache.lucene.index.TestStressNRT):	Caused an ERROR
            [junit] MockDirectoryWrapper: cannot close: there are still open files: {_vv.cfs=5, _j1.cfs=5}
            [junit] java.lang.RuntimeException: MockDirectoryWrapper: cannot close: there are still open files: {_vv.cfs=5, _j1.cfs=5}
            [junit] 	at org.apache.lucene.store.MockDirectoryWrapper.close(MockDirectoryWrapper.java:555)
            [junit] 	at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:385)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639)
            [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57)
            [junit] 	at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21)
            [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit] Caused by: java.lang.RuntimeException: unclosed IndexInput: _j1.cfs
            [junit] 	at org.apache.lucene.store.MockDirectoryWrapper.addFileHandle(MockDirectoryWrapper.java:479)
            [junit] 	at org.apache.lucene.store.MockDirectoryWrapper$1.openSlice(MockDirectoryWrapper.java:777)
            [junit] 	at org.apache.lucene.store.CompoundFileDirectory.openInput(CompoundFileDirectory.java:221)
            [junit] 	at org.apache.lucene.codecs.lucene3x.Lucene3xStoredFieldsReader.<init>(Lucene3xStoredFieldsReader.java:156)
            [junit] 	at org.apache.lucene.codecs.lucene3x.Lucene3xStoredFieldsFormat.fieldsReader(Lucene3xStoredFieldsFormat.java:38)
            [junit] 	at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:116)
            [junit] 	at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:51)
            [junit] 	at org.apache.lucene.index.IndexWriter$ReadersAndLiveDocs.getMergeReader(IndexWriter.java:521)
            [junit] 	at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3587)
            [junit] 	at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451)
            [junit] 
        
        Show
        Gilad Barkai added a comment - It fails here as well, not as often though, [junit] ------------- Standard Error ----------------- [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8" [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=US/East-Indiana [junit] NOTE: all tests run in this JVM: [junit] [TestStressNRT] [junit] NOTE: Linux 3.2.7-1.fc16.x86_64 amd64/Sun Microsystems Inc. 1.6.0_24 (64-bit)/cpus=2,threads=1,free=44668576,total=133169152 [junit] ------------- ---------------- --------------- [junit] Testcase: test(org.apache.lucene.index.TestStressNRT): Caused an ERROR [junit] MockDirectoryWrapper: cannot close: there are still open files: {_vv.cfs=5, _j1.cfs=5} [junit] java.lang.RuntimeException: MockDirectoryWrapper: cannot close: there are still open files: {_vv.cfs=5, _j1.cfs=5} [junit] at org.apache.lucene.store.MockDirectoryWrapper.close(MockDirectoryWrapper.java:555) [junit] at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:385) [junit] at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743) [junit] at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538) [junit] at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57) [junit] at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] Caused by: java.lang.RuntimeException: unclosed IndexInput: _j1.cfs [junit] at org.apache.lucene.store.MockDirectoryWrapper.addFileHandle(MockDirectoryWrapper.java:479) [junit] at org.apache.lucene.store.MockDirectoryWrapper$1.openSlice(MockDirectoryWrapper.java:777) [junit] at org.apache.lucene.store.CompoundFileDirectory.openInput(CompoundFileDirectory.java:221) [junit] at org.apache.lucene.codecs.lucene3x.Lucene3xStoredFieldsReader.<init>(Lucene3xStoredFieldsReader.java:156) [junit] at org.apache.lucene.codecs.lucene3x.Lucene3xStoredFieldsFormat.fieldsReader(Lucene3xStoredFieldsFormat.java:38) [junit] at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:116) [junit] at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:51) [junit] at org.apache.lucene.index.IndexWriter$ReadersAndLiveDocs.getMergeReader(IndexWriter.java:521) [junit] at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3587) [junit] at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451) [junit]
        Hide
        Dawid Weiss added a comment -

        Yep, there is something severely wrong in there, but I won't be able to figure it out on my own. Don't get the logic in IndexWriter. But I tracked one of the above exceptions to this scenario:

            [junit] junit.framework.AssertionFailedError: info=_dm(4.0):cv6/4 isn't live
            [junit]     at org.apache.lucene.index.IndexWriter$ReaderPool.infoIsLive(IndexWriter.java:663)
            [junit]     at org.apache.lucene.index.IndexWriter$ReaderPool.dropAll(IndexWriter.java:717)
            [junit]     at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:1136)
            [junit]     at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1069)
            [junit]     at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1033)
            [junit]     at org.apache.lucene.index.RandomIndexWriter.close(RandomIndexWriter.java:408)
            [junit]     at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:380)
        

        So, the case here is that infoIsLive attempts to check:

              int idx = segmentInfos.indexOf(info);
              assert idx != -1: "info=" + info + " isn't live";
        

        I added tracing to segmentInfos when segments do get removed from the underlying array. Once executed, I get the listing:

        ...
        >>> Removing: _o1(4.0):Cv13/13
        >>> Removing: _o0(4.0):Cv6/6
        >>> Removing: _nu(4.0):C12/12
        >>> Removing: _nw(4.0):Cv12/12
        >>> Removing: _o9(4.0):c2/2
        >>> Removing: _q2(4.0):C12/12
        >>> Removing: _qc(4.0):Cv7/7
        >>> Removing: _q6(4.0):C12/12
        >>> Not found: _d9(4.0):Cv8/3
        

        But that last segment is never on the list of removed segments. It was never added there in the first place. The allocation stack for that segment is:

        	at java.lang.Thread.getStackTrace(Thread.java:1436)
        	at org.apache.lucene.index.SegmentInfo.<init>(SegmentInfo.java:130)
        	at org.apache.lucene.index.IndexWriter._mergeInit(IndexWriter.java:3418)
        	at org.apache.lucene.index.IndexWriter.mergeInit(IndexWriter.java:3382)
        	at org.apache.lucene.index.ConcurrentMergeScheduler.merge(ConcurrentMergeScheduler.java:346)
        	at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1905)
        	at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1899)
        	at org.apache.lucene.index.IndexWriter.prepareCommit(IndexWriter.java:2726)
        	at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:2809)
        	at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:2791)
        	at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:2775)
        	at org.apache.lucene.index.RandomIndexWriter.commit(RandomIndexWriter.java:313)
        	at org.apache.lucene.index.TestStressNRT$1.run(TestStressNRT.java:156)
        

        So this looks like a race condition between closing the writer and a concurrent merge scheduler?

        Let me know if you need any further stacks/ tracing listings – this is fairly easy to reproduce on my machine and I can add anything.

        Show
        Dawid Weiss added a comment - Yep, there is something severely wrong in there, but I won't be able to figure it out on my own. Don't get the logic in IndexWriter. But I tracked one of the above exceptions to this scenario: [junit] junit.framework.AssertionFailedError: info=_dm(4.0):cv6/4 isn't live [junit] at org.apache.lucene.index.IndexWriter$ReaderPool.infoIsLive(IndexWriter.java:663) [junit] at org.apache.lucene.index.IndexWriter$ReaderPool.dropAll(IndexWriter.java:717) [junit] at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:1136) [junit] at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1069) [junit] at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1033) [junit] at org.apache.lucene.index.RandomIndexWriter.close(RandomIndexWriter.java:408) [junit] at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:380) So, the case here is that infoIsLive attempts to check: int idx = segmentInfos.indexOf(info); assert idx != -1: "info=" + info + " isn't live"; I added tracing to segmentInfos when segments do get removed from the underlying array. Once executed, I get the listing: ... >>> Removing: _o1(4.0):Cv13/13 >>> Removing: _o0(4.0):Cv6/6 >>> Removing: _nu(4.0):C12/12 >>> Removing: _nw(4.0):Cv12/12 >>> Removing: _o9(4.0):c2/2 >>> Removing: _q2(4.0):C12/12 >>> Removing: _qc(4.0):Cv7/7 >>> Removing: _q6(4.0):C12/12 >>> Not found: _d9(4.0):Cv8/3 But that last segment is never on the list of removed segments. It was never added there in the first place. The allocation stack for that segment is: at java.lang.Thread.getStackTrace(Thread.java:1436) at org.apache.lucene.index.SegmentInfo.<init>(SegmentInfo.java:130) at org.apache.lucene.index.IndexWriter._mergeInit(IndexWriter.java:3418) at org.apache.lucene.index.IndexWriter.mergeInit(IndexWriter.java:3382) at org.apache.lucene.index.ConcurrentMergeScheduler.merge(ConcurrentMergeScheduler.java:346) at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1905) at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1899) at org.apache.lucene.index.IndexWriter.prepareCommit(IndexWriter.java:2726) at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:2809) at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:2791) at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:2775) at org.apache.lucene.index.RandomIndexWriter.commit(RandomIndexWriter.java:313) at org.apache.lucene.index.TestStressNRT$1.run(TestStressNRT.java:156) So this looks like a race condition between closing the writer and a concurrent merge scheduler? Let me know if you need any further stacks/ tracing listings – this is fairly easy to reproduce on my machine and I can add anything.
        Hide
        Dawid Weiss added a comment - - edited

        This is definitely a race between ConcurrentMergeScheduler and the thread calling close. Everything else seems to stem from this problem. For example this one:

        java.lang.RuntimeException: MockDirectoryWrapper: cannot close: there are still open files: {_dc.tvx=1, _dc.tvf=1, _dc.tvd=1, _dc.fdx=1, _dc.fdt=1, _dc.frq=1, _dc.tis=1}
        	at org.apache.lucene.store.MockDirectoryWrapper.close(MockDirectoryWrapper.java:555)
        	at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:385)
        

        has an underlying open file handle stack:

        Caused by: java.lang.RuntimeException: unclosed IndexInput: _dc.tvf
        	at org.apache.lucene.store.MockDirectoryWrapper.addFileHandle(MockDirectoryWrapper.java:479)
        	at org.apache.lucene.store.MockDirectoryWrapper.openInput(MockDirectoryWrapper.java:504)
        	at org.apache.lucene.codecs.lucene3x.Lucene3xTermVectorsReader.<init>(Lucene3xTermVectorsReader.java:137)
        	at org.apache.lucene.codecs.lucene3x.PreFlexRWTermVectorsFormat$1.<init>(PreFlexRWTermVectorsFormat.java:39)
        	at org.apache.lucene.codecs.lucene3x.PreFlexRWTermVectorsFormat.vectorsReader(PreFlexRWTermVectorsFormat.java:39)
        	at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:119)
        	at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:51)
        	at org.apache.lucene.index.IndexWriter$ReadersAndLiveDocs.getMergeReader(IndexWriter.java:521)
        	at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3591)
        	at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3261)
        	at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382)
        	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451)
        

        Uwe, this just calls for your German analytic mind to solve

        Show
        Dawid Weiss added a comment - - edited This is definitely a race between ConcurrentMergeScheduler and the thread calling close. Everything else seems to stem from this problem. For example this one: java.lang.RuntimeException: MockDirectoryWrapper: cannot close: there are still open files: {_dc.tvx=1, _dc.tvf=1, _dc.tvd=1, _dc.fdx=1, _dc.fdt=1, _dc.frq=1, _dc.tis=1} at org.apache.lucene.store.MockDirectoryWrapper.close(MockDirectoryWrapper.java:555) at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:385) has an underlying open file handle stack: Caused by: java.lang.RuntimeException: unclosed IndexInput: _dc.tvf at org.apache.lucene.store.MockDirectoryWrapper.addFileHandle(MockDirectoryWrapper.java:479) at org.apache.lucene.store.MockDirectoryWrapper.openInput(MockDirectoryWrapper.java:504) at org.apache.lucene.codecs.lucene3x.Lucene3xTermVectorsReader.<init>(Lucene3xTermVectorsReader.java:137) at org.apache.lucene.codecs.lucene3x.PreFlexRWTermVectorsFormat$1.<init>(PreFlexRWTermVectorsFormat.java:39) at org.apache.lucene.codecs.lucene3x.PreFlexRWTermVectorsFormat.vectorsReader(PreFlexRWTermVectorsFormat.java:39) at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:119) at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:51) at org.apache.lucene.index.IndexWriter$ReadersAndLiveDocs.getMergeReader(IndexWriter.java:521) at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3591) at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3261) at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382) at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451) Uwe, this just calls for your German analytic mind to solve
        Hide
        Michael McCandless added a comment -

        I can [eventually] reproduce the failure too, if I beast the test...

        Show
        Michael McCandless added a comment - I can [eventually] reproduce the failure too, if I beast the test...
        Hide
        Dawid Weiss added a comment -

        I think you can try to run a few threads in the background doing just while (true);. I have a slower computer 2-core computer and this happens there most often.

        Show
        Dawid Weiss added a comment - I think you can try to run a few threads in the background doing just while (true);. I have a slower computer 2-core computer and this happens there most often.
        Hide
        Michael McCandless added a comment -

        Hmm... compounding problems here is that, somehow, an exception is occurring in a CMS merge thread, yet is never reported by the test runner. I hit a fail, and only got this:

            [junit] ------------- Standard Error -----------------
            [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8"
            [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Australia/LHI
            [junit] NOTE: all tests run in this JVM:
            [junit] [TestStressNRT]
            [junit] NOTE: Linux 2.6.33.6-147.fc13.x86_64 amd64/Sun Microsystems Inc. 1.6.0_21 (64-bit)/cpus=24,threads=1,free=257856112,total=285933568
            [junit] ------------- ---------------- ---------------
            [junit] Testcase: test(org.apache.lucene.index.TestStressNRT):	FAILED
            [junit] info=_fu(4.0):C11/1 isn't live
            [junit] junit.framework.AssertionFailedError: info=_fu(4.0):C11/1 isn't live
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57)
            [junit] 	at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21)
            [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit] 	at org.apache.lucene.index.IndexWriter$ReaderPool.infoIsLive(IndexWriter.java:663)
            [junit] 	at org.apache.lucene.index.IndexWriter$ReaderPool.dropAll(IndexWriter.java:717)
            [junit] 	at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:1137)
            [junit] 	at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1069)
            [junit] 	at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1033)
            [junit] 	at org.apache.lucene.index.RandomIndexWriter.close(RandomIndexWriter.java:408)
            [junit] 	at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:386)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639)
            [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600)
            [junit] 
            [junit] 
        

        I also separately added a SOP to ConcurrentMergeScheduler.handleMergeException and we are calling that... yet something is not then reporting this exception.

        However: I made a silly small test case that spawns a thread that throws an exception from its run method, and when I run that indeed I see the "unhandled exception from thread". So I'm not sure why exceptions in CMS threads in particular are not being reported...

        Show
        Michael McCandless added a comment - Hmm... compounding problems here is that, somehow, an exception is occurring in a CMS merge thread, yet is never reported by the test runner. I hit a fail, and only got this: [junit] ------------- Standard Error ----------------- [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8" [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Australia/LHI [junit] NOTE: all tests run in this JVM: [junit] [TestStressNRT] [junit] NOTE: Linux 2.6.33.6-147.fc13.x86_64 amd64/Sun Microsystems Inc. 1.6.0_21 (64-bit)/cpus=24,threads=1,free=257856112,total=285933568 [junit] ------------- ---------------- --------------- [junit] Testcase: test(org.apache.lucene.index.TestStressNRT): FAILED [junit] info=_fu(4.0):C11/1 isn't live [junit] junit.framework.AssertionFailedError: info=_fu(4.0):C11/1 isn't live [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57) [junit] at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] at org.apache.lucene.index.IndexWriter$ReaderPool.infoIsLive(IndexWriter.java:663) [junit] at org.apache.lucene.index.IndexWriter$ReaderPool.dropAll(IndexWriter.java:717) [junit] at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:1137) [junit] at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1069) [junit] at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1033) [junit] at org.apache.lucene.index.RandomIndexWriter.close(RandomIndexWriter.java:408) [junit] at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:386) [junit] at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743) [junit] at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538) [junit] at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600) [junit] [junit] I also separately added a SOP to ConcurrentMergeScheduler.handleMergeException and we are calling that... yet something is not then reporting this exception. However: I made a silly small test case that spawns a thread that throws an exception from its run method, and when I run that indeed I see the "unhandled exception from thread". So I'm not sure why exceptions in CMS threads in particular are not being reported...
        Hide
        Dawid Weiss added a comment -

        I'll fix this, Mike.

        Show
        Dawid Weiss added a comment - I'll fix this, Mike.
        Hide
        Dawid Weiss added a comment -

        And by "this" I mean LUCENE-3857.

        Show
        Dawid Weiss added a comment - And by "this" I mean LUCENE-3857 .
        Hide
        Michael McCandless added a comment -

        Thanks Dawid! I'm not sure LUCENE-3857 is what I'm hitting (this test doesn't have a @beforeClass).

        One more piece of data: sometimes the CMS exception is printed in the "unhandled exceptions" output... so it's somehow intermittant. Hmm, it could be... the main thread threw its exc before CMS thread did? Odd, though, because IW closes CMS first (which should join to all outstanding threads), before hitting the exc in main thread. Still baffled...

        Anyway it's not a blocker for me... I'm printing the exc in CMS.handleExc.

        Show
        Michael McCandless added a comment - Thanks Dawid! I'm not sure LUCENE-3857 is what I'm hitting (this test doesn't have a @beforeClass). One more piece of data: sometimes the CMS exception is printed in the "unhandled exceptions" output... so it's somehow intermittant. Hmm, it could be... the main thread threw its exc before CMS thread did? Odd, though, because IW closes CMS first (which should join to all outstanding threads), before hitting the exc in main thread. Still baffled... Anyway it's not a blocker for me... I'm printing the exc in CMS.handleExc.
        Hide
        Dawid Weiss added a comment -

        I'm not sure LUCENE-3857 is what I'm hitting (this test doesn't have a @beforeClass).

        No, I don't think it is. But I'll fix that issue anyway.

        One more piece of data: sometimes the CMS exception is printed in the "unhandled exceptions" output... so it's somehow intermittant.

        This is really messy in the current LTC. I'll try to do something about it.

        Show
        Dawid Weiss added a comment - I'm not sure LUCENE-3857 is what I'm hitting (this test doesn't have a @beforeClass). No, I don't think it is. But I'll fix that issue anyway. One more piece of data: sometimes the CMS exception is printed in the "unhandled exceptions" output... so it's somehow intermittant. This is really messy in the current LTC. I'll try to do something about it.
        Hide
        Hoss Man added a comment -

        attached file was generated using trunk r1298470 with the command...

        X=0; while ant test-core -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8"; do X=$(($X+1)); echo "Finished Loop $X"; done; echo "TOTAL LOOPS: $X"
        

        the failure occured on loop #52

        junit-sequential:
            [junit] Testsuite: org.apache.lucene.index.TestStressNRT
            [junit] Tests run: 1, Failures: 0, Errors: 1, Time elapsed: 5.082 sec
            [junit] 
            [junit] ------------- Standard Error -----------------
            [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8"
            [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Asia/Thimphu
            [junit] NOTE: all tests run in this JVM:
            [junit] [TestStressNRT]
            [junit] NOTE: Linux 2.6.31-23-generic amd64/Sun Microsystems Inc. 1.6.0_24 (64-bit)/cpus=2,threads=1,free=192293192,total=256966656
            [junit] ------------- ---------------- ---------------
            [junit] Testcase: test(org.apache.lucene.index.TestStressNRT):	Caused an ERROR
            [junit] MockDirectoryWrapper: cannot close: there are still open files: {_47.frq=1, _47.tis=1, _47.fdx=1, _47.fdt=1}
            [junit] java.lang.RuntimeException: MockDirectoryWrapper: cannot close: there are still open files: {_47.frq=1, _47.tis=1, _47.fdx=1, _47.fdt=1}
            [junit] 	at org.apache.lucene.store.MockDirectoryWrapper.close(MockDirectoryWrapper.java:555)
            [junit] 	at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:385)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639)
            [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57)
            [junit] 	at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21)
            [junit] 	at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22)
            [junit] Caused by: java.lang.RuntimeException: unclosed IndexInput: _47.tis
            [junit] 	at org.apache.lucene.store.MockDirectoryWrapper.addFileHandle(MockDirectoryWrapper.java:479)
            [junit] 	at org.apache.lucene.store.MockDirectoryWrapper.openInput(MockDirectoryWrapper.java:504)
            [junit] 	at org.apache.lucene.codecs.lucene3x.TermInfosReader.<init>(TermInfosReader.java:112)
            [junit] 	at org.apache.lucene.codecs.lucene3x.Lucene3xFields.<init>(Lucene3xFields.java:84)
            [junit] 	at org.apache.lucene.codecs.lucene3x.PreFlexRWPostingsFormat$1.<init>(PreFlexRWPostingsFormat.java:51)
            [junit] 	at org.apache.lucene.codecs.lucene3x.PreFlexRWPostingsFormat.fieldsProducer(PreFlexRWPostingsFormat.java:51)
            [junit] 	at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:108)
            [junit] 	at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:51)
            [junit] 	at org.apache.lucene.index.IndexWriter$ReadersAndLiveDocs.getMergeReader(IndexWriter.java:521)
            [junit] 	at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3587)
            [junit] 	at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382)
            [junit] 	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451)
            [junit] 
            [junit] 
            [junit] Test org.apache.lucene.index.TestStressNRT FAILED
        
        BUILD FAILED
        /home/hossman/lucene/dev/lucene/build.xml:43: The following error occurred while executing this line:
        /home/hossman/lucene/dev/lucene/common-build.xml:688: The following error occurred while executing this line:
        /home/hossman/lucene/dev/lucene/common-build.xml:677: Tests failed!
        
        Total time: 8 seconds
        TOTAL LOOPS: 52
        
        Show
        Hoss Man added a comment - attached file was generated using trunk r1298470 with the command... X=0; while ant test-core -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8"; do X=$(($X+1)); echo "Finished Loop $X"; done; echo "TOTAL LOOPS: $X" the failure occured on loop #52 junit-sequential: [junit] Testsuite: org.apache.lucene.index.TestStressNRT [junit] Tests run: 1, Failures: 0, Errors: 1, Time elapsed: 5.082 sec [junit] [junit] ------------- Standard Error ----------------- [junit] NOTE: reproduce with: ant test -Dtestcase=TestStressNRT -Dtestmethod=test -Dtests.seed=69468941c1bbf693:19e66d58475da929:69e9d2f81769b6d0 -Dargs="-Dfile.encoding=UTF-8" [junit] NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=false): {}, locale=ro, timezone=Asia/Thimphu [junit] NOTE: all tests run in this JVM: [junit] [TestStressNRT] [junit] NOTE: Linux 2.6.31-23-generic amd64/Sun Microsystems Inc. 1.6.0_24 (64-bit)/cpus=2,threads=1,free=192293192,total=256966656 [junit] ------------- ---------------- --------------- [junit] Testcase: test(org.apache.lucene.index.TestStressNRT): Caused an ERROR [junit] MockDirectoryWrapper: cannot close: there are still open files: {_47.frq=1, _47.tis=1, _47.fdx=1, _47.fdt=1} [junit] java.lang.RuntimeException: MockDirectoryWrapper: cannot close: there are still open files: {_47.frq=1, _47.tis=1, _47.fdx=1, _47.fdt=1} [junit] at org.apache.lucene.store.MockDirectoryWrapper.close(MockDirectoryWrapper.java:555) [junit] at org.apache.lucene.index.TestStressNRT.test(TestStressNRT.java:385) [junit] at org.apache.lucene.util.LuceneTestCase$SubclassSetupTeardownRule$1.evaluate(LuceneTestCase.java:743) [junit] at org.apache.lucene.util.LuceneTestCase$InternalSetupTeardownRule$1.evaluate(LuceneTestCase.java:639) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] at org.apache.lucene.util.LuceneTestCase$TestResultInterceptorRule$1.evaluate(LuceneTestCase.java:538) [junit] at org.apache.lucene.util.LuceneTestCase$RememberThreadRule$1.evaluate(LuceneTestCase.java:600) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:164) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:57) [junit] at org.apache.lucene.util.StoreClassNameRule$1.evaluate(StoreClassNameRule.java:21) [junit] at org.apache.lucene.util.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:22) [junit] Caused by: java.lang.RuntimeException: unclosed IndexInput: _47.tis [junit] at org.apache.lucene.store.MockDirectoryWrapper.addFileHandle(MockDirectoryWrapper.java:479) [junit] at org.apache.lucene.store.MockDirectoryWrapper.openInput(MockDirectoryWrapper.java:504) [junit] at org.apache.lucene.codecs.lucene3x.TermInfosReader.<init>(TermInfosReader.java:112) [junit] at org.apache.lucene.codecs.lucene3x.Lucene3xFields.<init>(Lucene3xFields.java:84) [junit] at org.apache.lucene.codecs.lucene3x.PreFlexRWPostingsFormat$1.<init>(PreFlexRWPostingsFormat.java:51) [junit] at org.apache.lucene.codecs.lucene3x.PreFlexRWPostingsFormat.fieldsProducer(PreFlexRWPostingsFormat.java:51) [junit] at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:108) [junit] at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:51) [junit] at org.apache.lucene.index.IndexWriter$ReadersAndLiveDocs.getMergeReader(IndexWriter.java:521) [junit] at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3587) [junit] at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382) [junit] at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451) [junit] [junit] [junit] Test org.apache.lucene.index.TestStressNRT FAILED BUILD FAILED /home/hossman/lucene/dev/lucene/build.xml:43: The following error occurred while executing this line: /home/hossman/lucene/dev/lucene/common-build.xml:688: The following error occurred while executing this line: /home/hossman/lucene/dev/lucene/common-build.xml:677: Tests failed! Total time: 8 seconds TOTAL LOOPS: 52
        Hide
        Dawid Weiss added a comment -

        Mike, would it help if we dumped a linear sequence of each thread's ops on indexwriter/ segmentinfos, whatever else? If you can tell me which classes and methods would be of interest then I can provide such dumps with relative ease (using an aspect or even hardcoded printlns).

        Alternatively, can you express certain assertions that should always hold wrt multi-threaded access? I mean something that I could try to weave into the code so that we can catch an abnormal interaction pattern while it's happening (as opposed just seing the result)?

        Show
        Dawid Weiss added a comment - Mike, would it help if we dumped a linear sequence of each thread's ops on indexwriter/ segmentinfos, whatever else? If you can tell me which classes and methods would be of interest then I can provide such dumps with relative ease (using an aspect or even hardcoded printlns). Alternatively, can you express certain assertions that should always hold wrt multi-threaded access? I mean something that I could try to weave into the code so that we can catch an abnormal interaction pattern while it's happening (as opposed just seing the result)?
        Hide
        Michael McCandless added a comment -

        Mike, would it help if we dumped a linear sequence of each thread's ops on indexwriter/ segmentinfos, whatever else?

        Thanks Dawid!

        I actually know the root cause here:

        Uncaught exception by thread: Thread[Lucene Merge Thread #72,6,main]
        org.apache.lucene.index.MergePolicy$MergeException: java.lang.AssertionError
        	at org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeException(ConcurrentMergeScheduler.java:509)
        	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:480)
        Caused by: java.lang.AssertionError
        	at org.apache.lucene.index.IndexWriter.commitMergedDeletes(IndexWriter.java:3028)
        	at org.apache.lucene.index.IndexWriter.commitMerge(IndexWriter.java:3137)
        	at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3718)
        	at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257)
        	at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382)
        	at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451)
        

        After that assert trips all kinds of crazy other exceptions can happen (not-closed files, not-live SegmentInfo, etc.).

        After the merge finishes, which can take a long time, in commitMergedDeletes we revisit each segment so we can "carry forward" any new deletions recorded against that segment, to the newly merged segment. In an active NRT app there can be many deletes to carry forward...

        That tripped assert was to verify the ReadersAndLiveDocs (RLD) was still present in IW's ReaderPool; it's supposed to remain present throughout merging because we had incRef'd the SegmentReader we opened for merging.

        But, it can in fact be dropped (the bug here) by another thread opening a reader and applying deletes and decRef'ing the reader all after the merge thread 1) acquired the RLD but 2) before it opened the mergeReader from it.

        I (accidentally!!) caused this with LUCENE-3631, where we moved writeable deletes from SegmentReader into IndexWriter. I suspect we need to add a separate refCount to RLD to fix this... I'm working on that.

        Show
        Michael McCandless added a comment - Mike, would it help if we dumped a linear sequence of each thread's ops on indexwriter/ segmentinfos, whatever else? Thanks Dawid! I actually know the root cause here: Uncaught exception by thread: Thread[Lucene Merge Thread #72,6,main] org.apache.lucene.index.MergePolicy$MergeException: java.lang.AssertionError at org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeException(ConcurrentMergeScheduler.java:509) at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:480) Caused by: java.lang.AssertionError at org.apache.lucene.index.IndexWriter.commitMergedDeletes(IndexWriter.java:3028) at org.apache.lucene.index.IndexWriter.commitMerge(IndexWriter.java:3137) at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3718) at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3257) at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:382) at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:451) After that assert trips all kinds of crazy other exceptions can happen (not-closed files, not-live SegmentInfo, etc.). After the merge finishes, which can take a long time, in commitMergedDeletes we revisit each segment so we can "carry forward" any new deletions recorded against that segment, to the newly merged segment. In an active NRT app there can be many deletes to carry forward... That tripped assert was to verify the ReadersAndLiveDocs (RLD) was still present in IW's ReaderPool; it's supposed to remain present throughout merging because we had incRef'd the SegmentReader we opened for merging. But, it can in fact be dropped (the bug here) by another thread opening a reader and applying deletes and decRef'ing the reader all after the merge thread 1) acquired the RLD but 2) before it opened the mergeReader from it. I (accidentally!!) caused this with LUCENE-3631 , where we moved writeable deletes from SegmentReader into IndexWriter. I suspect we need to add a separate refCount to RLD to fix this... I'm working on that.
        Hide
        Michael McCandless added a comment -

        Patch, fixing the issue. I think it's ready...

        Basically I added a refCount to ReadersAndLiveDocs, and
        incRef/decRef'd in the right places. I also pulled out
        ReadersAndLiveDocs to its own source, and tried to simplify
        it a bit (separate method calls to dropChanges,
        drop, release).

        Show
        Michael McCandless added a comment - Patch, fixing the issue. I think it's ready... Basically I added a refCount to ReadersAndLiveDocs, and incRef/decRef'd in the right places. I also pulled out ReadersAndLiveDocs to its own source, and tried to simplify it a bit (separate method calls to dropChanges, drop, release).
        Hide
        Robert Muir added a comment -

        I also pulled out
        ReadersAndLiveDocs to its own source

        +1

        Show
        Robert Muir added a comment - I also pulled out ReadersAndLiveDocs to its own source +1
        Hide
        Dawid Weiss added a comment -

        I'm no longer able to reproduce this with the patch applied. I think this should be committed in as soon as possible?

        Show
        Dawid Weiss added a comment - I'm no longer able to reproduce this with the patch applied. I think this should be committed in as soon as possible?

          People

          • Assignee:
            Michael McCandless
            Reporter:
            Dawid Weiss
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development