NullPointerException in EstimateResultTracker.doQuery(LuceneDatabase.java:493)

[tombech]

This is with a record linkage (master/candidate) setup and appears to happen after a certain number of record have been processed and will then happend with any record posted after that. There is nothing special with the record before/after this as far as I can see. The linkage database is a Virtuoso server, if that matters.

The full traceback is:

Server Error

Caused by:

java.lang.NullPointerException
at no.priv.garshol.duke.databases.LuceneDatabase$EstimateResultTracker.doQuery(LuceneDatabase.java:493)
at no.priv.garshol.duke.databases.LuceneDatabase$EstimateResultTracker.doQuery(LuceneDatabase.java:483)
at no.priv.garshol.duke.databases.LuceneDatabase.findCandidateMatches(LuceneDatabase.java:284)
at no.priv.garshol.duke.Processor.match(Processor.java:485)
at no.priv.garshol.duke.Processor.linkBatch(Processor.java:418)
at no.priv.garshol.duke.Processor.link(Processor.java:341)
at no.bouvet.sesam.sdshare.receiver.duke.DukeRecordLinkageConfig.processRecord(DukeRecordLinkageConfig.java:43)
at no.bouvet.sesam.sdshare.receiver.duke.PushReceiverServlet.doPost(PushReceiverServlet.java:82)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:215)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:110)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
at org.eclipse.jetty.server.Server.handle(Server.java:499)\n\tat org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
at java.lang.Thread.run(Thread.java:745)
            

[larsga]

I looked into this a bit, and it seems that the problem is that the searcher is null.

The findCandidateMatches method begins:

    if (directory == null)
      init();

The init() call will set searcher before returning, and there is no other code that sets searcher to null. So either you are not using the Duke version that's in the master branch, or the problem is that searcher.search(query, filter, thislimit) is returning null (causing .scoreDocs to fail), or something's really, really weird.

So the question becomes, can IndexSearcher.search return null, and the javadoc doesn't say. I'm pretty sure I've never seen this before, though.

That's as far as I've gotten.

[tombech]

Would it help at all to get the Lucene index in question? (and/or the duke config)? I don't think it contains anything sensitive. I can put either or both up somewhere for you to download and inspect. I will check which version of Duke is packaged.

[larsga]

Would it help at all to get the Lucene index in question?

It might. The config might be relevant, too.

However, it strikes me that this could happen if init() throws an exception after the directory has been set. So you might want to look for an exception that has init() in the trace higher up in the log. Alternatively, you can try adding directory = null to the catch blocks in the code to make sure we don't wind up in an inconsistent state where we later don't call init(), but the searcher is null.

The best thing might be for you to either use a debugger or add some logging to see if you can gather a little more information about what's actually going on.

[tombech]

Looking further into the problem, earlier at startup I see:

HTTP ERROR 500

Problem accessing /address/2. Reason:

Server Error

Caused by:

no.priv.garshol.duke.DukeException: org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: NativeFSLock@/sesam/data/lucene-indexes/address-master/write.lock
    at no.priv.garshol.duke.databases.LuceneDatabase.openIndexes(LuceneDatabase.java:351)
    at no.priv.garshol.duke.databases.LuceneDatabase.init(LuceneDatabase.java:314)
    at no.priv.garshol.duke.databases.LuceneDatabase.findCandidateMatches(LuceneDatabase.java:259)
    at no.priv.garshol.duke.Processor.match(Processor.java:485)
    at no.priv.garshol.duke.Processor.linkBatch(Processor.java:418)
    at no.priv.garshol.duke.Processor.link(Processor.java:341)
    at no.bouvet.sesam.sdshare.receiver.duke.DukeRecordLinkageConfig.processRecord(DukeRecordLinkageConfig.java:43)
    at no.bouvet.sesam.sdshare.receiver.duke.PushReceiverServlet.doPost(PushReceiverServlet.java:82)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
    at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:215)
    at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:110)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
    at org.eclipse.jetty.server.Server.handle(Server.java:499)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
    at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
    at java.lang.Thread.run(Thread.java:745)
Caused by: org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: NativeFSLock@/sesam/data/lucene-indexes/address-master/write.lock
    at org.apache.lucene.store.Lock.obtain(Lock.java:84)
    at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:602)
    at no.priv.garshol.duke.databases.LuceneDatabase.openIndexes(LuceneDatabase.java:341)
    ... 29 more

Caused by:

org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: NativeFSLock@/sesam/data/lucene-indexes/address-master/write.lock
    at org.apache.lucene.store.Lock.obtain(Lock.java:84)
    at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:602)
    at no.priv.garshol.duke.databases.LuceneDatabase.openIndexes(LuceneDatabase.java:341)
    at no.priv.garshol.duke.databases.LuceneDatabase.init(LuceneDatabase.java:314)
    at no.priv.garshol.duke.databases.LuceneDatabase.findCandidateMatches(LuceneDatabase.java:259)
    at no.priv.garshol.duke.Processor.match(Processor.java:485)
    at no.priv.garshol.duke.Processor.linkBatch(Processor.java:418)
    at no.priv.garshol.duke.Processor.link(Processor.java:341)
    at no.bouvet.sesam.sdshare.receiver.duke.DukeRecordLinkageConfig.processRecord(DukeRecordLinkageConfig.java:43)
    at no.bouvet.sesam.sdshare.receiver.duke.PushReceiverServlet.doPost(PushReceiverServlet.java:82)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
    at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:215)
    at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:110)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
    at org.eclipse.jetty.server.Server.handle(Server.java:499)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
    at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
    at java.lang.Thread.run(Thread.java:745)

[larsga]

Yeah, that explains it. So directory != null, but searcher == null and you get the wrong error message.

So the first step is to harden init() so that we don't wind up in an inconsistent state. I can take care of that.

The second step is to figure out why the index is locked.

[larsga]

Fixed by commit 6bd07f7.