'TokenStream contract violation: close() call missing' error for .jar files

[ahornace]

Test output:

Mar 05, 2018 12:28:35 PM org.opensolaris.opengrok.index.Indexer prepareIndexer
INFO: Scanning for repositories...
Mar 05, 2018 12:28:35 PM org.opensolaris.opengrok.index.Indexer prepareIndexer
INFO: Done scanning for repositories (0s)
Mar 05, 2018 12:28:35 PM org.opensolaris.opengrok.index.Indexer doIndexerExecution
INFO: Starting indexing
Mar 05, 2018 12:28:36 PM org.opensolaris.opengrok.analysis.Ctags$1 run
WARNING: Error from ctags: ctags: Warning: Language "pascal" already defined
Mar 05, 2018 12:28:36 PM org.opensolaris.opengrok.analysis.Ctags$1 run
WARNING: Error from ctags: ctags: Warning: Language "pascal" already defined
Mar 05, 2018 12:28:36 PM org.opensolaris.opengrok.analysis.Ctags$1 run
WARNING: Error from ctags: ctags: Warning: Language "pascal" already defined
Mar 05, 2018 12:28:36 PM org.opensolaris.opengrok.analysis.Ctags$1 run
WARNING: Error from ctags: ctags: Warning: Language "pascal" already defined
Mar 05, 2018 12:28:36 PM org.opensolaris.opengrok.analysis.Ctags$1 run
WARNING: Error from ctags: ctags: Warning: Language "pascal" already defined
Mar 05, 2018 12:28:36 PM org.opensolaris.opengrok.index.IndexDatabase lambda$indexParallel$1
WARNING: ERROR addFile(): /private/var/folders/b7/t9s65dpx1blcklnlfvy1__340000gn/T/source14347768915021023503opengrok/java/Main.class
java.lang.IllegalStateException: TokenStream contract violation: close() call missing
	at org.apache.lucene.analysis.Tokenizer.setReader(Tokenizer.java:90)
	at org.apache.lucene.analysis.Analyzer$TokenStreamComponents.setReader(Analyzer.java:412)
	at org.apache.lucene.analysis.Analyzer.tokenStream(Analyzer.java:202)
	at org.apache.lucene.document.Field.tokenStream(Field.java:505)
	at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:730)
	at org.apache.lucene.index.DefaultIndexingChain.processField(DefaultIndexingChain.java:430)
	at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:392)
	at org.apache.lucene.index.DocumentsWriterPerThread.updateDocument(DocumentsWriterPerThread.java:240)
	at org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:496)
	at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1729)
	at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1464)
	at org.opensolaris.opengrok.index.IndexDatabase.addFile(IndexDatabase.java:719)
	at org.opensolaris.opengrok.index.IndexDatabase.lambda$indexParallel$1(IndexDatabase.java:1018)
	at java.base/java.util.stream.Collectors.lambda$groupingByConcurrent$55(Collectors.java:1245)
	at java.base/java.util.stream.ReferencePipeline.lambda$collect$1(ReferencePipeline.java:508)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184)
	at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1494)
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
	at java.base/java.util.stream.ForEachOps$ForEachTask.compute(ForEachOps.java:291)
	at java.base/java.util.concurrent.CountedCompleter.exec(CountedCompleter.java:747)
	at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:283)
	at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1603)
	at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:175)

Mar 05, 2018 12:28:36 PM org.opensolaris.opengrok.index.IndexDatabase addFile
INFO: Skipped file '/bug3430/truncated' because the analyzer didn't understand it.
Mar 05, 2018 12:28:36 PM org.opensolaris.opengrok.analysis.Ctags$1 run
WARNING: Error from ctags: ctags: Warning: Language "pascal" already defined
Mar 05, 2018 12:28:36 PM org.opensolaris.opengrok.analysis.Ctags$1 run
WARNING: Error from ctags: ctags: Warning: Language "pascal" already defined
Mar 05, 2018 12:28:36 PM org.opensolaris.opengrok.analysis.Ctags$1 run
WARNING: Error from ctags: ctags: Warning: Language "pascal" already defined
Mar 05, 2018 12:28:36 PM org.opensolaris.opengrok.index.IndexDatabase indexParallel
WARNING: 1 failures (1.6%) while parallel-indexing
Mar 05, 2018 12:28:37 PM org.opensolaris.opengrok.index.IndexDatabase optimize
INFO: Optimizing the index ... 
Mar 05, 2018 12:28:37 PM org.opensolaris.opengrok.index.IndexDatabase optimize
INFO: done
Mar 05, 2018 12:28:37 PM org.opensolaris.opengrok.util.Statistics report
INFO: Done indexing data of all repositories (took 1.804 seconds)

java.lang.AssertionError: Search for main~ in testdata sources 
Expected :9
Actual   :8
 <Click to see difference>


	at org.junit.Assert.fail(Assert.java:88)
	at org.junit.Assert.failNotEquals(Assert.java:834)
	at org.junit.Assert.assertEquals(Assert.java:645)
	at org.opensolaris.opengrok.search.SearchTest.testSearch(SearchTest.java:155)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
	at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47)
	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242)
	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70)

Notice: sometimes the test passes and sometimes it does not -> probably race condition

Setup:

• macOS High Sierra
• CPU: Intel Core i7-7700HQ 2.80GHz

[tarzanek]

I can try to repro on the same setup ...

[ahornace]

I think I should have mentioned that I'm using Java 9.

I was looking into it but was not able to produce a solution :/

This answer seems to be helpful: https://stackoverflow.com/questions/39920564/tokenstream-contract-violation-close-call-missing-when-calling-adddocument

What seems to be the problem that we are not using proper workflow as mentioned here:
https://lucene.apache.org/core/7_2_1/core/org/apache/lucene/analysis/TokenStream.html (This can also be deduced from the exception message which is thrown very occasionally: "TokenStream contract violation: reset()/close() call missing, reset() called multiple times, or subclass does not call super.reset(). Please see Javadocs of TokenStream class for more information about the correct consuming workflow.")

The problem is related to the FileAnalyzer#createComponents method and only in the case when it takes field REFS as a parameter. This method is called twice in the test and it returns new TokenStreamComponents(symbolTokenizer); upon which the Analyzer class calls setReader method. If this setReader is called before the first one was closed then exception is thrown. I tried creating a copy of symbolTokenizer in FileAnalyzer#createComponents but it did not work (different exception was thrown).

Hope this helps at least a little.

[tarzanek]

this is good info
it means that the test should be fixed ...
honestly a lot of tests might be a bit dated (and the lucene compatibility tests are not even turned on)

[vladak]

I have just hit this on Travis Linux build too: https://travis-ci.org/vladak/OpenGrok/jobs/366215912 (Oracle JDK 8) however in different place:

[ERROR] Tests run: 8, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 3.483 s <<< FAILURE! - in org.opensolaris.opengrok.search.SearchEngineTest
[ERROR] testSearch(org.opensolaris.opengrok.search.SearchEngineTest)  Time elapsed: 0.371 s  <<< FAILURE!
java.lang.AssertionError: expected:<8> but was:<7>
	at org.opensolaris.opengrok.search.SearchEngineTest.testSearch(SearchEngineTest.java:276)

[vladak]

Given how often this now fails in Travis I think this is a stopper candidate.

[tarzanek]

@vladak that test is dumb from the point of view, that when it will not add to index one of the files in repo, the count will just be less ...
the test itself should be split to check analyzer after analyzer and not give a "summary" count.
Since then you would be able to see immediately what analyser is broken (and from above it seems like bcel - so jar/class analyser again)

[vladak]

So maybe we can disable/remove the test now and replace it (or that code behind) with something better later.

[vladak]

commented out the failing test piece in 496029d and 2f0d40e and ca20911

[vladak]

For some reason I've started getting these exceptions (with WARNING level) for some jar files in one project out of many. Currently running 1.1-rc33.