MMapDirectory still has pending deleted files; cannot initialize IndexWriter #4323

Goyal981 · 2017-11-15T10:34:52Z

Goyal981
Nov 15, 2017

Hi, I'm using Opengrok version: 1.1-rc13
when reindexing, I get this error

.
.
Nov 15, 2017 2:59:19 PM org.opensolaris.opengrok.index.DefaultIndexChangedListener fileAdd
INFO: Add: /Users-Prashant/AppManagement/Main/Deployment/MigrationTool/kickme.txt (FileAnalyzer)
Nov 15, 2017 2:59:20 PM org.opensolaris.opengrok.index.IndexDatabase optimize
INFO: Optimizing the index ...
Nov 15, 2017 2:59:20 PM org.opensolaris.opengrok.index.IndexDatabase$2 run
SEVERE: Problem updating lucene index database:
java.lang.IllegalArgumentException: Directory MMapDirectory@C:\wcodeIssue\data\index\Users-Prashant lockFactory=org.apache.lucene.store.NoLockFactory@7f5d1ae4 still has pending deleted files; cannot initialize IndexWriter
        at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:791)
        at org.opensolaris.opengrok.index.IndexDatabase.optimize(IndexDatabase.java:536)
        at org.opensolaris.opengrok.index.IndexDatabase.update(IndexDatabase.java:477)
        at org.opensolaris.opengrok.index.IndexDatabase$2.run(IndexDatabase.java:188)
        at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
        at java.util.concurrent.FutureTask.run(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)

Nov 15, 2017 2:59:20 PM org.opensolaris.opengrok.util.Statistics report
INFO: Done indexing data of all repositories (took 0:02:28)
Nov 15, 2017 2:59:20 PM org.opensolaris.opengrok.index.Indexer writeConfigToFile
INFO: Writing configuration to C:\wcodeIssue\configuration.xml
Nov 15, 2017 2:59:20 PM org.opensolaris.opengrok.index.Indexer writeConfigToFile
INFO: Done...
Nov 15, 2017 2:59:20 PM org.opensolaris.opengrok.util.Statistics report
INFO: Total time: 0:02:28
Nov 15, 2017 2:59:20 PM org.opensolaris.opengrok.util.Statistics report
INFO: Final Memory: 90M/633M

OS: Windows 10
tomcat: 8.5.16/8.5.23
No other indexer is running.

Index command i used: java -jar .\opengrok\lib\opengrok.jar -W C:\wcodeIssue\configuration.xml -c C:\wcodeIssue\ctags.exe -P -S -v -s C:\wcodeIssue\src -d C:\wcodeIssue\data

steps I followed:

Run tomcat
indexed files inside src folder with that command.
Open a new tab and searched for something though UI ( successful)
Close the tab
At this point i see following files _1.fdt, _1.ndt, _1_Lucene50_0.doc, _1_Lucene50_0.pos, _1_Lucene50_0.tim, _1_Lucene54_0.dvd still opened under tomcat though process explorer
Added around 4000 files and modified some files.
Kept tomcat running (Required for me)
ran above command again

what I don't get is why these 6 files were open in tomcat even after the tab is closed is that's normal?
can you please help me out here?

Goyal981 · 2017-11-16T08:07:07Z

Goyal981
Nov 16, 2017
Author

steps I followed today to recreate this error again: (tried 5-6 times and even on a new machine result into same error)

1.created testFile.txt under c:\wwwcode\src\test\ with content:
test

indexed it with command
java -jar .\opengrok\lib\opengrok.jar -W C:\wwwcode\configuration.xml -c C:\wwwcode\ctags.exe -P -S -v -s C:\wwwcode\src -d C:\wwwcode\data\
(Successful)
started tomcat
went to http://localhost:8080/source/xref/test/testFile1.txt kept this link open and tomcat running
(Successful, keeping tomcat running because I'm running indexer task frequently and don't want to shutdown tomcat every time before it reindex as a lot of people will be using it)
updated file content to:
test
dur
reindex again with above command

Step 2 Output:
c:\wwwcode>java -jar .\opengrok\lib\opengrok.jar -W C:\wwwcode\configuration.xml -c C:\wwwcode\ctags.exe -P -S -v -s C:\wwwcode\src -d C:\wwwcode\data
Logging filehandler pattern: %h/java%u.log
Nov 16, 2017 3:45:32 PM org.opensolaris.opengrok.index.Indexer prepareIndexer
INFO: Scanning for repositories...
Nov 16, 2017 3:45:32 PM org.opensolaris.opengrok.index.Indexer prepareIndexer
INFO: Done scanning for repositories (0s)
Nov 16, 2017 3:45:32 PM org.opensolaris.opengrok.index.Indexer doIndexerExecution
INFO: Starting indexing
Nov 16, 2017 3:45:32 PM org.opensolaris.opengrok.index.DefaultIndexChangedListener fileAdd
INFO: Add: /test/testFile1.txt (PlainAnalyzer)
Nov 16, 2017 3:45:33 PM org.opensolaris.opengrok.index.IndexDatabase optimize
INFO: Optimizing the index ...
Nov 16, 2017 3:45:33 PM org.opensolaris.opengrok.index.IndexDatabase optimize
INFO: done
Nov 16, 2017 3:45:33 PM org.opensolaris.opengrok.util.Statistics report
INFO: Done indexing data of all repositories (took 1.484 seconds)
Nov 16, 2017 3:45:33 PM org.opensolaris.opengrok.index.Indexer writeConfigToFile
INFO: Writing configuration to C:\wwwcode\configuration.xml
Nov 16, 2017 3:45:33 PM org.opensolaris.opengrok.index.Indexer writeConfigToFile
INFO: Done...
Nov 16, 2017 3:45:33 PM org.opensolaris.opengrok.util.Statistics report
INFO: Total time: 1.922 seconds
Nov 16, 2017 3:45:33 PM org.opensolaris.opengrok.util.Statistics report
INFO: Final Memory: 70M/116M

Step 4 output:
c:\wwwcode>java -jar .\opengrok\lib\opengrok.jar -W C:\wwwcode\configuration.xml -c C:\wwwcode\ctags.exe -P -S -v -s C:\wwwcode\src -d C:\wwwcode\data
Logging filehandler pattern: %h/java%u.log
Nov 16, 2017 3:46:36 PM org.opensolaris.opengrok.index.Indexer prepareIndexer
INFO: Scanning for repositories...
Nov 16, 2017 3:46:36 PM org.opensolaris.opengrok.index.Indexer prepareIndexer
INFO: Done scanning for repositories (0s)
Nov 16, 2017 3:46:36 PM org.opensolaris.opengrok.index.Indexer doIndexerExecution
INFO: Starting indexing
Nov 16, 2017 3:46:37 PM org.opensolaris.opengrok.index.DefaultIndexChangedListener fileRemove
INFO: Remove file:/test/testFile1.txt
Nov 16, 2017 3:46:37 PM org.opensolaris.opengrok.index.DefaultIndexChangedListener fileAdd
INFO: Add: /test/testFile1.txt (PlainAnalyzer)
Nov 16, 2017 3:46:37 PM org.opensolaris.opengrok.index.IndexDatabase optimize
INFO: Optimizing the index ...
Nov 16, 2017 3:46:37 PM org.opensolaris.opengrok.index.IndexDatabase$2 run
SEVERE: Problem updating lucene index database:
java.lang.IllegalArgumentException: Directory MMapDirectory@C:\wwwcode\data\index\test lockFactory=org.apache.lucene.store.NoLockFactory@3c320add still has pending deleted files; cannot initialize IndexWriter
at org.apache.lucene.index.IndexWriter.(IndexWriter.java:791)
at org.opensolaris.opengrok.index.IndexDatabase.optimize(IndexDatabase.java:536)
at org.opensolaris.opengrok.index.IndexDatabase.update(IndexDatabase.java:477)
at org.opensolaris.opengrok.index.IndexDatabase$2.run(IndexDatabase.java:188)
at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
at java.util.concurrent.FutureTask.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

Nov 16, 2017 3:46:37 PM org.opensolaris.opengrok.util.Statistics report
INFO: Done indexing data of all repositories (took 1.656 seconds)
Nov 16, 2017 3:46:37 PM org.opensolaris.opengrok.index.Indexer writeConfigToFile
INFO: Writing configuration to C:\wwwcode\configuration.xml
Nov 16, 2017 3:46:37 PM org.opensolaris.opengrok.index.Indexer writeConfigToFile
INFO: Done...
Nov 16, 2017 3:46:37 PM org.opensolaris.opengrok.util.Statistics report
INFO: Total time: 2.187 seconds
Nov 16, 2017 3:46:38 PM org.opensolaris.opengrok.util.Statistics report
INFO: Final Memory: 69M/160M

0 replies

tarzanek · 2017-11-16T09:46:10Z

tarzanek
Nov 16, 2017

tomcat shouldn't really influence this, since it's read only
it looks like one of the indexer broke for you ... what java version do you use?

0 replies

Goyal981 · 2017-11-16T11:10:14Z

Goyal981
Nov 16, 2017
Author

Hi tarzanek,

I'm using
java version "1.8.0_131"
Java(TM) SE Runtime Environment (build 1.8.0_131-b11)
Java HotSpot(TM) 64-Bit Server VM (build 25.131-b11, mixed mode)

I see CANNOT DELETE result on files like _1_Lucene50_0.doc in procmon and when I closed the tomcat ran it then it worked so I thought it might be because of opengrok webapp in there.

0 replies

Goyal981 · 2017-11-16T17:08:52Z

Goyal981
Nov 16, 2017
Author

Hi @tarzanek ,
I added -U localhost:2424 option in the command after adding it at least got reindexed without any error but when I try to delete these indexed files it doesn't allow me _1.fdt, _1.ndt, _1_Lucene50_0.doc, _1_Lucene50_0.pos, _1_Lucene50_0.tim, _1_Lucene54_0.dvd blocks it. Even for a newly indexed tree once I open it in the browser and close it.

0 replies

vladak · 2017-11-20T14:13:45Z

vladak
Nov 20, 2017
Maintainer

In http://lucene.472066.n3.nabble.com/LockFactory-issue-observed-in-lucene-while-getting-instance-of-indexWriter-td4282571.html Mike McCandless says: just be sure the "release" happens in a finally clause.

The code in IndexDatabase.java#update() looks like this:

try {
            Analyzer analyzer = AnalyzerGuru.getAnalyzer();
            IndexWriterConfig iwc = new IndexWriterConfig(analyzer);
            iwc.setOpenMode(OpenMode.CREATE_OR_APPEND);
            iwc.setRAMBufferSizeMB(env.getRamBufferSize());
            writer = new IndexWriter(indexDirectory, iwc);
            writer.commit(); // to make sure index exists on the disk

...

        } finally {
            if (writer != null) {
                try {
                    writer.prepareCommit();
                    writer.commit();
                    writer.close();
                } catch (IOException e) {
                    LOGGER.log(Level.WARNING, "An error occured while closing writer", e);
                }
            }

...
        }

Now, I don't know if prepareCommit() or commit() can throw any exception however it might be better if the writer was used in a try-with-resources block to make sure it will always be closed.

0 replies

Goyal981 · 2017-11-21T11:45:20Z

Goyal981
Nov 21, 2017
Author

Hi @vladak ,
Thanks for looking into this. Can you please suggest the appropriate code changes so that I can try to rebuild and test it as I want to put my machine in production but I keep getting this error frequently.
Any help you can offer is greatly appreciated

0 replies

vladak · 2017-11-21T19:46:05Z

vladak
Nov 21, 2017
Maintainer

I'd just change the last above mentioned try block to:

try (writer) {
    writer.prepareCommit();
    writer.commit();
} catch ...

if this makes sense. Otherwise I'd just move the close() call to finally.

0 replies

tarzanek · 2017-11-25T21:32:53Z

tarzanek
Nov 25, 2017

I have one more hypothesis - this is windows - and I saw very weird blocking of open files by windows ... so this might be also it (sometimes windows just blocks a file and doesn't release even after process is stopped, restart is needed) ... but let's start with Vlads suggestion
both those commands can throw IOException (but I guess then something bad is going on with your disk) so we can start there ...

0 replies

Goyal981 · 2017-12-08T09:15:19Z

Goyal981
Dec 8, 2017
Author

@tarzanek @vladak
I did what Vlads had suggested but that didn't resolve it.

I started using the older version of Opengrok and on a test machine running windows realized this issue starts showing up with 0.13rc-1 as with 0.12 you were not reusing these indexed files to serve or some other logic so these files were never left open or show up in tomcat though process monitor.
With newer version looks like on Windows when I've to reindex -U localhost:2424 is required otherwise it won't be able to send "indexed" or Refresh search manager message to the webapp and since files were still open under tomcat it won't allow deleting these files and "pendingDeletions" will always return true but with Linux that's isn't the case it will always succeed.

Lucene code:
public IndexWriter(Directory d, IndexWriterConfig conf) throws IOException {
if (d instanceof FSDirectory && ((FSDirectory) d).checkPendingDeletions()) {
throw new IllegalArgumentException("Directory " + d + " still has pending deleted files; cannot initialize IndexWriter");
}

Let me know if this logic is correct because now it doesn't throw optimize error frequently but it still shows up with a different scenario.

0 replies

MMapDirectory still has pending deleted files; cannot initialize IndexWriter #4323

Uh oh!

Uh oh!

Goyal981 Nov 15, 2017

Index command i used: java -jar .\opengrok\lib\opengrok.jar -W C:\wcodeIssue\configuration.xml -c C:\wcodeIssue\ctags.exe -P -S -v -s C:\wcodeIssue\src -d C:\wcodeIssue\data

Replies: 9 comments

Uh oh!

Goyal981 Nov 16, 2017 Author

Uh oh!

tarzanek Nov 16, 2017

Uh oh!

Goyal981 Nov 16, 2017 Author

Uh oh!

Goyal981 Nov 16, 2017 Author

Uh oh!

Uh oh!

vladak Nov 20, 2017 Maintainer

Uh oh!

Uh oh!

Goyal981 Nov 21, 2017 Author

Uh oh!

vladak Nov 21, 2017 Maintainer

Uh oh!

tarzanek Nov 25, 2017

Uh oh!

Goyal981 Dec 8, 2017 Author

Goyal981
Nov 15, 2017

Goyal981
Nov 16, 2017
Author

tarzanek
Nov 16, 2017

Goyal981
Nov 16, 2017
Author

Goyal981
Nov 16, 2017
Author

vladak
Nov 20, 2017
Maintainer

Goyal981
Nov 21, 2017
Author

vladak
Nov 21, 2017
Maintainer

tarzanek
Nov 25, 2017

Goyal981
Dec 8, 2017
Author