Lucene Index Error Relate to Database Close command.

[Jing Chen]

Hi Enrico and the OrientDB team,

We are seeing some Lucene index errors in our application. Our application was trying to close a database connection when it caught an OLockException. Then the graph database shutdown function OrientBaseGraph.shutdown() seems to trigger a Lucene Index error "this Index Writer is closed". The full stack trace is attached bellow:

2015-01-03 14:54:14:758 INFO Account b9ae0914-9398-11e4-8b3e-000c29202374 does not exist for class: user [OrientdbDAO]Error during context close for db plo
cal:/opt/ndex/orientdb/databases/ndex
com.orientechnologies.orient.core.exception.OTransactionException: Transaction was rolled back more times than it was started.
    at com.orientechnologies.orient.core.tx.OTransactionOptimistic.rollback(OTransactionOptimistic.java:177)
    at com.orientechnologies.orient.core.db.record.ODatabaseRecordTx.commit(ODatabaseRecordTx.java:152)
    at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.commit(ODatabaseDocumentTx.java:511)
    at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.commit(ODatabaseDocumentTx.java:503)
    at com.tinkerpop.blueprints.impls.orient.OrientBaseGraph.removeContext(OrientBaseGraph.java:1540)
    at com.tinkerpop.blueprints.impls.orient.OrientBaseGraph.shutdown(OrientBaseGraph.java:900)
    at org.ndexbio.common.models.dao.orientdb.UserDAO.close(UserDAO.java:1043)
    at org.ndexbio.rest.services.UserService.getTasks(UserService.java:522)
    at sun.reflect.GeneratedMethodAccessor101.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:137)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:296)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:250)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:237)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:356)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179)
    at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:220)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1070)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
org.apache.lucene.store.AlreadyClosedException: this IndexWriter is closed
    at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:645)
    at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:659)
    at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:2988)
    at com.orientechnologies.lucene.manager.OLuceneIndexManagerAbstract.commit(OLuceneIndexManagerAbstract.java:118)
    at com.orientechnologies.lucene.OLuceneIndexEngine.closeDb(OLuceneIndexEngine.java:139)
    at com.orientechnologies.orient.core.index.OIndexAbstract.onClose(OIndexAbstract.java:802)
    at com.orientechnologies.orient.core.db.record.ODatabaseRecordAbstract.callOnCloseListeners(ODatabaseRecordAbstract.java:1536)
    at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTxPooled.close(ODatabaseDocumentTxPooled.java:112)
    at org.ndexbio.rest.services.NetworkAService.searchNetwork(NetworkAService.java:805)
    at sun.reflect.GeneratedMethodAccessor103.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:137)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:296)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:250)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:237)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:356)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179)
    at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:220)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1070)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
Error on releasing database 'ndex' in pool
com.orientechnologies.orient.core.tx.ORollbackException: Given transaction was rolled back and can not be used.
    at com.orientechnologies.orient.core.tx.OTransactionOptimistic.doCommit(OTransactionOptimistic.java:450)
    at com.orientechnologies.orient.core.tx.OTransactionOptimistic.commit(OTransactionOptimistic.java:148)
    at com.orientechnologies.orient.core.db.record.ODatabaseRecordTx.commit(ODatabaseRecordTx.java:142)
    at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.commit(ODatabaseDocumentTx.java:511)
    at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTxPooled.close(ODatabaseDocumentTxPooled.java:103)
    at com.tinkerpop.blueprints.impls.orient.OrientBaseGraph.removeContext(OrientBaseGraph.java:1550)
    at com.tinkerpop.blueprints.impls.orient.OrientBaseGraph.shutdown(OrientBaseGraph.java:900)
    at org.ndexbio.common.models.dao.orientdb.UserDAO.close(UserDAO.java:1043)
    at org.ndexbio.rest.services.UserService.getTasks(UserService.java:522)
    at sun.reflect.GeneratedMethodAccessor101.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:137)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:296)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:250)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:237)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:356)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179)
    at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:220)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1070)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
org.apache.lucene.store.AlreadyClosedException: this IndexWriter is closed
    at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:645)
    at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:659)
    at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:2988)
    at com.orientechnologies.lucene.manager.OLuceneIndexManagerAbstract.commit(OLuceneIndexManagerAbstract.java:118)
    at com.orientechnologies.lucene.OLuceneIndexEngine.closeDb(OLuceneIndexEngine.java:139)
    at com.orientechnologies.orient.core.index.OIndexAbstract.onClose(OIndexAbstract.java:802)
    at com.orientechnologies.orient.core.db.record.ODatabaseRecordAbstract.callOnCloseListeners(ODatabaseRecordAbstract.java:1536)
    at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTxPooled.close(ODatabaseDocumentTxPooled.java:112)
    at org.ndexbio.rest.filters.BasicAuthenticationFilter.filter(BasicAuthenticationFilter.java:75)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:264)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:250)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:237)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:356)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179)
    at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:220)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1070)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
Error during context close for db plocal:/opt/ndex/orientdb/databases/ndex
com.orientechnologies.common.concur.lock.OLockException: Timeout (30000ms) on acquiring resource '#18:277' because is locked from another thread
    at com.orientechnologies.common.concur.lock.OLockManager.acquireLock(OLockManager.java:104)
    at com.orientechnologies.common.concur.lock.OLockManager.acquireLock(OLockManager.java:71)
    at com.orientechnologies.orient.core.storage.impl.local.paginated.OLocalPaginatedStorage.commit(OLocalPaginatedStorage.java:1075)
    at com.orientechnologies.orient.core.tx.OTransactionOptimistic.doCommit(OTransactionOptimistic.java:469)
    at com.orientechnologies.orient.core.tx.OTransactionOptimistic.commit(OTransactionOptimistic.java:148)
    at com.orientechnologies.orient.core.db.record.ODatabaseRecordTx.commit(ODatabaseRecordTx.java:142)
    at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.commit(ODatabaseDocumentTx.java:511)
    at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.commit(ODatabaseDocumentTx.java:503)
    at com.tinkerpop.blueprints.impls.orient.OrientBaseGraph.removeContext(OrientBaseGraph.java:1540)
    at com.tinkerpop.blueprints.impls.orient.OrientBaseGraph.shutdown(OrientBaseGraph.java:900)
    at org.ndexbio.common.models.dao.orientdb.GroupDAO.close(GroupDAO.java:749)
    at org.ndexbio.rest.services.GroupService.closeDatabase(GroupService.java:602)
    at org.ndexbio.rest.services.GroupService.findGroups(GroupService.java:245)
    at sun.reflect.GeneratedMethodAccessor109.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:137)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:296)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:250)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:237)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:356)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179)
    at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:220)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1070)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)


After this error happens, we start getting this error bellow and the Lucene search doesn't work any more. Bellow is the stack trace of the error

2015-01-05 10:07:37:385 INFO Account undefined does not exist for class: user [OrientdbDAO]java.lang.IllegalArgumentException: targetGen=14871 was never re
turned by the ReferenceManager instance (current gen=2593)
    at org.apache.lucene.search.ControlledRealTimeReopenThread.waitForGeneration(ControlledRealTimeReopenThread.java:160)
    at org.apache.lucene.search.ControlledRealTimeReopenThread.waitForGeneration(ControlledRealTimeReopenThread.java:135)
    at com.orientechnologies.lucene.manager.OLuceneIndexManagerAbstract.getSearcher(OLuceneIndexManagerAbstract.java:318)
    at com.orientechnologies.lucene.manager.OLuceneFullTextIndexManager.getResults(OLuceneFullTextIndexManager.java:145)
    at com.orientechnologies.lucene.manager.OLuceneFullTextIndexManager.get(OLuceneFullTextIndexManager.java:112)
    at com.orientechnologies.lucene.OLuceneIndexEngine.get(OLuceneIndexEngine.java:155)
    at com.orientechnologies.lucene.index.OLuceneFullTextIndex.get(OLuceneFullTextIndex.java:111)
    at com.orientechnologies.lucene.index.OLuceneFullTextIndex.get(OLuceneFullTextIndex.java:38)
    at com.orientechnologies.orient.core.index.OIndexAbstractDelegate.get(OIndexAbstractDelegate.java:57)
    at com.orientechnologies.orient.core.index.OIndexTxAwareMultiValue.get(OIndexTxAwareMultiValue.java:275)
    at com.orientechnologies.orient.core.index.OIndexTxAwareMultiValue.get(OIndexTxAwareMultiValue.java:43)
    at org.ndexbio.common.models.dao.orientdb.NetworkSearchDAO.findNetworksV2(NetworkSearchDAO.java:206)
    ....

Do we need to do special things to close a connection, which is acquired from a connection pool, when we use Lucene? What should we do to avoid this error? We are using Orientdb 1.7.10 with Orient-Lucene 1.7.9-snapshot. Our application is a tomcat application using Orientdb as an embedded server. OS is Linux.

Thank you very much for your help.

Jing

[Jing Chen]

Hi Enrico,

Could you take a look of this problem? What could be the cause of it and is there anything we can do in our application to avoid this? This error failed all the search functions on our production server.

Thanks,
Jing

[Enrico Risa]

Hi Jing 

I see that seems that somehow the index was closed ad then start to give the second error.
i'm trying to replicate it any hint on how can replicate it?

--

---
You received this message because you are subscribed to the Google Groups "OrientDB" group.
To unsubscribe from this group and stop receiving emails from it, send an email to orient-databa...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Jing Chen]

Hi Enrico,

Thanks for looking into this. I couldn't create a test case to reproduce this this error yet. It seems to happen when we try to call a rollback() (in the graph API) in a connection and then close the connection.  This can trigger the error sometimes.

Thanks,
Jing

[Jing Chen]

Hi Enrico,

This error came out again and completely brought the search function down in our production site. It becomes a very critical issue for us, and we really appreciate if you can help us to resolve this issue.

Here are some more information I found from our tomcat log. Hope it can provide some hints for you to reproduce the problem. Basically we saw a few errors happened before the "targetGen=14871" happened. This time it is not doing bulk inserts.

One of them is this exception:

com.orientechnologies.orient.core.exception.ODatabaseException: Database instance has been released to the pool. Get another database instance from the pool with the right username and password
        at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTxPooled.checkOpeness(ODatabaseDocumentTxPooled.java:133)
        at com.orientechnologies.orient.core.db.ODatabaseWrapperAbstract.getClusterNameById(ODatabaseWrapperAbstract.java:190)
        at com.orientechnologies.orient.core.metadata.schema.OClassImpl.readableClusters(OClassImpl.java:122)
        at com.orientechnologies.orient.core.iterator.ORecordIteratorClass.<init>(ORecordIteratorClass.java:71)
        at com.orientechnologies.orient.core.iterator.ORecordIteratorClass.<init>(ORecordIteratorClass.java:56)
        at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.browseClass(ODatabaseDocumentTx.java:209)
        at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.browseClass(ODatabaseDocumentTx.java:197)
        ...

Another exception was

com.orientechnologies.orient.core.index.OIndexException: Error parsing lucene query
        at com.orientechnologies.lucene.manager.OLuceneFullTextIndexManager.get(OLuceneFullTextIndexManager.java:114)

        at com.orientechnologies.lucene.OLuceneIndexEngine.get(OLuceneIndexEngine.java:155)
        at com.orientechnologies.lucene.index.OLuceneFullTextIndex.get(OLuceneFullTextIndex.java:111)
        at com.orientechnologies.lucene.index.OLuceneFullTextIndex.get(OLuceneFullTextIndex.java:38)
        at com.orientechnologies.orient.core.index.OIndexAbstractDelegate.get(OIndexAbstractDelegate.java:57)
        at com.orientechnologies.orient.core.index.OIndexTxAwareMultiValue.get(OIndexTxAwareMultiValue.java:275)
        at com.orientechnologies.orient.core.index.OIndexTxAwareMultiValue.get(OIndexTxAwareMultiValue.java:43)
        at org.ndexbio.common.models.dao.orientdb.NetworkSearchDAO.findNetworksV2(NetworkSearchDAO.java:206)

        at org.ndexbio.common.models.dao.orientdb.NetworkSearchDAO.findNetworks(NetworkSearchDAO.java:73)
        at org.ndexbio.rest.services.NetworkAService.searchNetwork(NetworkAService.java:802)

        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)

Caused by: org.apache.lucene.queryparser.classic.ParseException: Cannot parse '*hoxd3': '*' or '?' not allowed as first character in WildcardQuery
        at org.apache.lucene.queryparser.classic.QueryParserBase.parse(QueryParserBase.java:125)
        at com.orientechnologies.lucene.OLuceneIndexType.getQueryParser(OLuceneIndexType.java:126)
        at com.orientechnologies.lucene.OLuceneIndexType.createFullQuery(OLuceneIndexType.java:112)
        at com.orientechnologies.lucene.manager.OLuceneFullTextIndexManager.get(OLuceneFullTextIndexManager.java:107)
        ... 42 more
Caused by: org.apache.lucene.queryparser.classic.ParseException: '*' or '?' not allowed as first character in WildcardQuery
        at org.apache.lucene.queryparser.classic.QueryParserBase.getWildcardQuery(QueryParserBase.java:734)
        at org.apache.lucene.queryparser.classic.MultiFieldQueryParser.getWildcardQuery(MultiFieldQueryParser.java:200)
        at org.apache.lucene.queryparser.classic.MultiFieldQueryParser.getWildcardQuery(MultiFieldQueryParser.java:195)
        at org.apache.lucene.queryparser.classic.QueryParserBase.handleBareTokenQuery(QueryParserBase.java:832)
        at org.apache.lucene.queryparser.classic.QueryParser.Term(QueryParser.java:358)
        at org.apache.lucene.queryparser.classic.QueryParser.Clause(QueryParser.java:257)
        at org.apache.lucene.queryparser.classic.QueryParser.Query(QueryParser.java:181)
        at org.apache.lucene.queryparser.classic.QueryParser.TopLevelQuery(QueryParser.java:170)
        at org.apache.lucene.queryparser.classic.QueryParserBase.parse(QueryParserBase.java:120)
        ... 45 more

Then we got this error:

2015-01-12 16:22:58:555 INFO Account 80421cb7-39f3-11e4-a848-000c29202374 does not exist for class: user [OrientdbDAO]com.orientechnologies.orient.core.exception.ODatabaseException: Error on retrieving record #14:507243 (cluster: ndexproperty)
        at com.orientechnologies.orient.core.db.raw.ODatabaseRaw.read(ODatabaseRaw.java:257)
        at com.orientechnologies.orient.core.db.record.ODatabaseRecordAbstract.executeReadRecord(ODatabaseRecordAbstract.java:1005)
        at com.orientechnologies.orient.core.tx.OTransactionOptimistic.loadRecord(OTransactionOptimistic.java:227)
        at com.orientechnologies.orient.core.db.record.ODatabaseRecordTx.load(ODatabaseRecordTx.java:251)
        at com.orientechnologies.orient.core.db.record.ODatabaseRecordTx.load(ODatabaseRecordTx.java:40)
        at com.orientechnologies.orient.core.id.ORecordId.getRecord(ORecordId.java:298)
        at com.orientechnologies.orient.core.db.record.ridbag.embedded.OEmbeddedRidBag$EntriesIterator.next(OEmbeddedRidBag.java:414)
        at com.orientechnologies.orient.core.db.record.ridbag.embedded.OEmbeddedRidBag$EntriesIterator.next(OEmbeddedRidBag.java:385)
        at com.orientechnologies.orient.core.command.traverse.OTraverseMultiValueProcess.process(OTraverseMultiValueProcess.java:36)
        at com.orientechnologies.orient.core.command.traverse.OTraverseMultiValueProcess.process(OTraverseMultiValueProcess.java:24)
        at com.orientechnologies.orient.core.command.traverse.OTraverse.next(OTraverse.java:101)
        at com.orientechnologies.orient.core.command.traverse.OTraverse.hasNext(OTraverse.java:71)
        at org.ndexbio.common.models.dao.orientdb.NetworkDAO.getPropertiesFromDocument(NetworkDAO.java:723)
        at org.ndexbio.common.models.dao.orientdb.NetworkDAO.setNetworkSummary(NetworkDAO.java:1318)
        at org.ndexbio.common.models.dao.orientdb.NetworkDAO.getNetworkSummary(NetworkDAO.java:1326)
        at org.ndexbio.common.models.dao.orientdb.NetworkSearchDAO.findAllNetworks(NetworkSearchDAO.java:121)
        at org.ndexbio.common.models.dao.orientdb.NetworkSearchDAO.findNetworks(NetworkSearchDAO.java:71)
        at org.ndexbio.rest.services.NetworkAService.searchNetwork(NetworkAService.java:802)

        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)

Caused by: com.orientechnologies.common.concur.lock.OLockException: Cannot unlock a never acquired lock
        at com.orientechnologies.orient.core.tx.OTransactionAbstract.unlockRecord(OTransactionAbstract.java:119)
        at com.orientechnologies.orient.core.id.ORecordId.unlock(ORecordId.java:272)
        at com.orientechnologies.orient.core.storage.impl.local.paginated.OLocalPaginatedStorage.readRecord(OLocalPaginatedStorage.java:1498)
        at com.orientechnologies.orient.core.storage.impl.local.paginated.OLocalPaginatedStorage.readRecord(OLocalPaginatedStorage.java:754)
        at com.orientechnologies.orient.core.db.raw.ODatabaseRaw.read(ODatabaseRaw.java:250)
        ... 50 more

Error during context close for db plocal:/opt/ndex/orientdb/databases/ndex

com.orientechnologies.orient.core.exception.OTransactionException: Transaction was rolled back more times than it was started.
        at com.orientechnologies.orient.core.tx.OTransactionOptimistic.rollback(OTransactionOptimistic.java:177)
        at com.orientechnologies.orient.core.db.record.ODatabaseRecordTx.commit(ODatabaseRecordTx.java:152)
        at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.commit(ODatabaseDocumentTx.java:511)
        at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.commit(ODatabaseDocumentTx.java:503)
        at com.tinkerpop.blueprints.impls.orient.OrientBaseGraph.removeContext(OrientBaseGraph.java:1540)
        at com.tinkerpop.blueprints.impls.orient.OrientBaseGraph.shutdown(OrientBaseGraph.java:900)
        at org.ndexbio.common.models.dao.orientdb.UserDAO.close(UserDAO.java:1043)

        at org.ndexbio.rest.services.UserService.getPendingRequests(UserService.java:501)
        at sun.reflect.GeneratedMethodAccessor161.invoke(Unknown Source)

        at sun.reflect.GeneratedMethodAccessor109.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:137)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:296)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:250)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:237)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:356)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179)

   ...

[Enrico Risa]

Hi Jing

i see this error:

Caused by: org.apache.lucene.queryparser.classic.ParseException: Cannot parse '*hoxd3': '*' or '?' not allowed as first character in WildcardQuery

is not a valid syntax syntax 

But after this error you got
"targetGen=14871" right?

We have done a ton of fixes on lucene indexing in 2.0 as it was the target for the stable plugin

I see if we can backports these fixes and if resolves you this problem

Enrico

[Dexter Pratt]

Hi Enrico and OrientDB team,

I just wanted to comment on the implications of this issue: after the error occurs, all subsequent operations that invoke search will fail. 

Our only solution is to restart the server!

Moreover, the error has happened several times on our production server that - so far - has relatively light use.  

We are concerned that it might become very frequent under heavier use.

We were initially hoping it was an infrequent issue that we could work around for a while, but it now has become a blocker for our entire project - we can't invite users to our production server if its going to fall into this error on a regular basis.

Dexter

On Monday, January 5, 2015 at 11:32:12 AM UTC-8, Jing Chen wrote:

[Jing Chen]

Hi Enrico,

I did more tests and it seems the ParseException won't cause the closure of Lucene index. It is more likely to be the other error:

2015-01-12 16:22:58:555 INFO Account 80421cb7-39f3-11e4-a848-

000c29202374 does not exist for class: user [OrientdbDAO]com.orientechnologies.orient.core.exception.ODatabaseException: Error on retrieving record #14:507243 (cluster: ndexproperty)
        at com.orientechnologies.orient.core.db.raw.ODatabaseRaw.read(ODatabaseRaw.java:257)
        at com.orientechnologies.orient.core.db.record.ODatabaseRecordAbstract.executeReadRecord(ODatabaseRecordAbstract.java:1005)
        at com.orientechnologies.orient.core.tx.OTransactionOptimistic.loadRecord(OTransactionOptimistic.java:227)
        at com.orientechnologies.orient.core.db.record.ODatabaseRecordTx.load(ODatabaseRecordTx.java:251)
        at com.orientechnologies.orient.core.db.record.ODatabaseRecordTx.load(ODatabaseRecordTx.java:40)
        at com.orientechnologies.orient.core.id.ORecordId.getRecord(ORecordId.java:298)
        at com.orientechnologies.orient.core.db.record.ridbag.embedded.OEmbeddedRidBag$EntriesIterator.next(OEmbeddedRidBag.java:414)
        at com.orientechnologies.orient.core.db.record.ridbag.embedded.OEmbeddedRidBag$EntriesIterator.next(OEmbeddedRidBag.java:385)
        at com.orientechnologies.orient.core.command.traverse.OTraverseMultiValueProcess.process(OTraverseMultiValueProcess.java:36)
        at com.orientechnologies.orient.core.command.traverse.OTraverseMultiValueProcess.process(OTraverseMultiValueProcess.java:24)
        at com.orientechnologies.orient.core.command.traverse.OTraverse.next(OTraverse.java:101)
        at com.orientechnologies.orient.core.command.traverse.OTraverse.hasNext(OTraverse.java:71)
        at org.ndexbio.common.models.dao.orientdb.NetworkDAO.getPropertiesFromDocument(NetworkDAO.java:723)
        at org.ndexbio.common.models.dao.orientdb.NetworkDAO.setNetworkSummary(NetworkDAO.java:1318)
        at org.ndexbio.common.models.dao.orientdb.NetworkDAO.getNetworkSummary(NetworkDAO.java:1326)
        at org.ndexbio.common.models.dao.orientdb.NetworkSearchDAO.findAllNetworks(NetworkSearchDAO.java:121)
        at org.ndexbio.common.models.dao.orientdb.NetworkSearchDAO.findNetworks(NetworkSearchDAO.java:71)
        at org.ndexbio.rest.services.NetworkAService.searchNetwork(NetworkAService.java:802)

- show quoted text -

        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)

Caused by: com.orientechnologies.common.concur.lock.OLockException: Cannot unlock a never acquired lock
        at com.orientechnologies.orient.core.tx.OTransactionAbstract.unlockRecord(OTransactionAbstract.java:119)
        at com.orientechnologies.orient.core.id.ORecordId.unlock(ORecordId.java:272)
        at com.orientechnologies.orient.core.storage.impl.local.paginated.OLocalPaginatedStorage.readRecord(OLocalPaginatedStorage.java:1498)
        at com.orientechnologies.orient.core.storage.impl.local.paginated.OLocalPaginatedStorage.readRecord(OLocalPaginatedStorage.java:754)
        at com.orientechnologies.orient.core.db.raw.ODatabaseRaw.read(ODatabaseRaw.java:250)
        ... 50 more

Error during context close for db plocal:/opt/ndex/orientdb/databases/ndex

com.orientechnologies.orient.core.exception.OTransactionException: Transaction was rolled back more times than it was started.
        at com.orientechnologies.orient.core.tx.OTransactionOptimistic.rollback(OTransactionOptimistic.java:177)
        at com.orientechnologies.orient.core.db.record.ODatabaseRecordTx.commit(ODatabaseRecordTx.java:152)
        at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.commit(ODatabaseDocumentTx.java:511)
        at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.commit(ODatabaseDocumentTx.java:503)
        at com.tinkerpop.blueprints.impls.orient.OrientBaseGraph.removeContext(OrientBaseGraph.java:1540)
        at com.tinkerpop.blueprints.impls.orient.OrientBaseGraph.shutdown(OrientBaseGraph.java:900)
        at org.ndexbio.common.models.dao.orientdb.UserDAO.close(UserDAO.java:1043)

        at org.ndexbio.rest.services.UserService.getPendingRequests(UserService.java:501)
        at sun.reflect.GeneratedMethodAccessor161.invoke(Unknown Source)

- show quoted text -

        at sun.reflect.GeneratedMethodAccessor109.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:137)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:296)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:250)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:237)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:356)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179)

[Enrico Risa]

Hi Jing

tomorrow i will roll a release with some backports from 2.0,

so you can try if resolve this issue. I will send you the link

[Jing Chen]

Great! Thanks.

[Enrico Risa]

Jing

here is the new releases compatible with 1.7.10
https://oss.sonatype.org/content/repositories/releases/com/orientechnologies/orientdb-lucene/1.7.10/orientdb-lucene-1.7.10-dist.jar

Try it and tell me if the issue still occurs

Enrico

[Jing Chen]

Thanks Enrico. We have downloaded the new release and will test it out today.