Exceptions when using the Mass Indexer

tunderwood89 · **Joined:** Mon Nov 26, 2012 2:34 pm **Posts:** 6

Hi,

I've been developing a hibernate search system for the last few months and we are beginning to test it in a production like environment (it has been fully tested on my local environment).

When we first indexed the database in the test environement everything seemed to work fine. We recently had to reindex from scratch and now we are seeing a lot of errors we have not seen before.

We are using Hibernate Search 3.4.0.Final with Hibernate Core 3.6.3.Final and we are using a Master/Slave indexing strategy with ActiveMQ as our JMS provider (using a Resin 4 webserver).

Here are the exceptions we are seeing.

Code:

[2013-02-12 13:56:28.308] [2013-02-12 13:56:28,290] ERROR FSMasterDirectoryProvider.java:232 pool-2-thread-1 ) Unable to synchronize source of /var/tmp/rb-software/lucene/index/model.SoftwareDownload
                          java.io.FileNotFoundException: /var/tmp/rb-software/lucene/index/model.SoftwareDownload/_n.fdt (No such file or directory)
                             at java.io.FileInputStream.open(Native Method)
                             at java.io.FileInputStream.<init>(FileInputStream.java:120)
                             at org.hibernate.search.util.FileHelper.copyFile(FileHelper.java:156)
                             at org.hibernate.search.util.FileHelper.synchronize(FileHelper.java:147)
                             at org.hibernate.search.util.FileHelper.synchronize(FileHelper.java:131)
                             at org.hibernate.search.store.FSMasterDirectoryProvider$CopyDirectory.run(FSMasterDirectoryProvider.java:227)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                             at java.lang.Thread.run(Thread.java:662)

[2013-02-12 14:15:34.568] [2013-02-12 14:15:34,565] ERROR LogErrorHandler.java:82 Hibernate Search: Directory writer-1 ) Exception occurred org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: SimpleFSLock@/var/tmp/rb-software/lucene/index/model.Company/write.lock
                          Primary Failure:
                             Entity model.Company  Id 10269934  Work Type  org.hibernate.search.backend.DeleteLuceneWork
                          Subsequent failures:
                             Entity model.Company  Id 10269934  Work Type  org.hibernate.search.backend.AddLuceneWork
                          
                          org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: SimpleFSLock@/var/tmp/rb-software/lucene/index/model.Company/write.lock
                             at org.apache.lucene.store.Lock.obtain(Lock.java:84)
                             at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1097)
                             at org.hibernate.search.backend.Workspace.createNewIndexWriter(Workspace.java:202)
                             at org.hibernate.search.backend.Workspace.getIndexWriter(Workspace.java:180)
                             at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:103)
                             at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
                             at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
                             at java.util.concurrent.FutureTask.run(FutureTask.java:138)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                             at java.lang.Thread.run(Thread.java:662)
[2013-02-12 14:15:34.573] [2013-02-12 14:15:34,571] ERROR PerDPQueueProcessor.java:118 Hibernate Search: Directory writer-1 ) Unexpected error in Lucene Backend: 
                          org.hibernate.search.SearchException: Unable to remove class .model.Company#10269934 from index.
                             at org.hibernate.search.backend.impl.lucene.works.DeleteExtWorkDelegate.performWork(DeleteExtWorkDelegate.java:77)
                             at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:106)
                             at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
                             at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
                             at java.util.concurrent.FutureTask.run(FutureTask.java:138)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                             at java.lang.Thread.run(Thread.java:662)
                          Caused by: java.lang.NullPointerException
                             at org.hibernate.search.backend.impl.lucene.works.DeleteExtWorkDelegate.performWork(DeleteExtWorkDelegate.java:72)
                             ... 7 more
[2013-02-12 14:15:34.577] [2013-02-12 14:15:34,574] ERROR LogErrorHandler.java:82 Hibernate Search: Directory writer-1 ) Exception occurred org.hibernate.search.SearchException: Unable to remove class model.Company#10269934 from index.
                          Primary Failure:
                             Entity model.Company  Id 10269934  Work Type  org.hibernate.search.backend.DeleteLuceneWork
                          Subsequent failures:
                             Entity model.Company  Id 10269934  Work Type  org.hibernate.search.backend.AddLuceneWork
                             Entity model.Company  Id 10269934  Work Type  org.hibernate.search.backend.AddLuceneWork
                          
                          org.hibernate.search.SearchException: Unable to remove class model.Company#10269934 from index.
                             at org.hibernate.search.backend.impl.lucene.works.DeleteExtWorkDelegate.performWork(DeleteExtWorkDelegate.java:77)
                             at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:106)
                             at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
                             at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
                             at java.util.concurrent.FutureTask.run(FutureTask.java:138)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                             at java.lang.Thread.run(Thread.java:662)
                          Caused by: java.lang.NullPointerException
                             at org.hibernate.search.backend.impl.lucene.works.DeleteExtWorkDelegate.performWork(DeleteExtWorkDelegate.java:72)
                             ... 7 more


[2013-02-12 14:58:25.810] [2013-02-12 14:58:25,773] ERROR JDBCTransaction.java:228 Hibernate Search: collectionsloader-2 ) Could not toggle autocommit
                          com.mysql.jdbc.exceptions.MySQLNonTransientConnectionException: Connection.close() has already been called. Invalid operation in this state.
                             at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:888)
                             at com.mysql.jdbc.Connection.getMutex(Connection.java:3588)
                             at com.mysql.jdbc.Connection.setAutoCommit(Connection.java:5185)
                             at com.caucho.sql.ManagedConnectionImpl.setAutoCommit(ManagedConnectionImpl.java:637)
                             at com.caucho.sql.UserConnection.setAutoCommit(UserConnection.java:802)
                             at org.hibernate.transaction.JDBCTransaction.toggleAutoCommit(JDBCTransaction.java:224)
                             at org.hibernate.transaction.JDBCTransaction.commitAndResetAutoCommit(JDBCTransaction.java:169)
                             at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:142)
                             at org.hibernate.search.batchindexing.EntityConsumerLuceneworkProducer.run(EntityConsumerLuceneworkProducer.java:100)
                             at org.hibernate.search.batchindexing.OptionallyWrapInJTATransaction.run(OptionallyWrapInJTATransaction.java:107)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                             at java.lang.Thread.run(Thread.java:662)

[2013-02-12 14:58:25.827] [2013-02-12 14:58:25,814] ERROR SessionImpl.java:608 Hibernate Search: entityloader-2 ) exception in interceptor afterTransactionCompletion()
                          org.hibernate.HibernateException: No Hibernate Session bound to thread, and configuration does not allow creation of non-transactional one here
                             at org.springframework.orm.hibernate3.SpringSessionContext.currentSession(SpringSessionContext.java:63)
                             at org.hibernate.impl.SessionFactoryImpl.getCurrentSession(SessionFactoryImpl.java:687)
                             at service.builder.BuilderServiceImpl.sessionClosed(BuilderServiceImpl.java:191)
                             at service.builder.BuilderServiceImpl$$FastClassByCGLIB$$6d251a5.invoke(<generated>)
                             at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:149)
                             at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:617)
                             at service.builder.BuilderServiceImpl$$EnhancerByCGLIB$$2f6c4942.sessionClosed(<generated>)
                             at persistance.softwareHibernateInterceptor.afterTransactionCompletion(softwareHibernateInterceptor.java:196)
                             at org.hibernate.impl.SessionImpl.afterTransactionCompletion(SessionImpl.java:605)
                             at org.hibernate.jdbc.JDBCContext.afterTransactionCompletion(JDBCContext.java:273)
                             at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:146)
                             at org.hibernate.search.batchindexing.IdentifierConsumerEntityProducer.run(IdentifierConsumerEntityProducer.java:88)
                             at org.hibernate.search.batchindexing.OptionallyWrapInJTATransaction.run(OptionallyWrapInJTATransaction.java:107)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                             at java.lang.Thread.run(Thread.java:662)





[2013-02-12 14:58:25.831] [2013-02-12 14:58:25,807] ERROR EntityConsumerLuceneworkProducer.java:103 Hibernate Search: collectionsloader-4 ) error during batch indexing: 
                          org.hibernate.TransactionException: JDBC commit failed
                             at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:157)
                             at org.hibernate.search.batchindexing.EntityConsumerLuceneworkProducer.run(EntityConsumerLuceneworkProducer.java:100)
                             at org.hibernate.search.batchindexing.OptionallyWrapInJTATransaction.run(OptionallyWrapInJTATransaction.java:107)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                             at java.lang.Thread.run(Thread.java:662)
                          Caused by: com.mysql.jdbc.exceptions.MySQLNonTransientConnectionException: Communications link failure during commit(). Transaction resolution unknown.
                             at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:888)
                             at com.mysql.jdbc.Connection.commit(Connection.java:2246)
                             at com.caucho.sql.UserConnection.commit(UserConnection.java:822)
                             at org.hibernate.transaction.JDBCTransaction.commitAndResetAutoCommit(JDBCTransaction.java:166)
                             at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:142)
                             ... 5 more






2013-02-12 15:00:02.940] [2013-02-12 15:00:02,939] ERROR LogErrorHandler.java:82 Hibernate Search: Directory writer-1 ) Exception occurred org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: SimpleFSLock@/var/tmp/rb-software/lucene/index/model.SoftwareDownload/write.lock
                          Primary Failure:
                             Entity model.SoftwareDownload  Id 10019223  Work Type  org.hibernate.search.backend.DeleteLuceneWork
                          Subsequent failures:
                             Entity model.SoftwareDownload  Id 10019223  Work Type  org.hibernate.search.backend.AddLuceneWork
                          
                          org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: SimpleFSLock@/var/tmp/rb-software/lucene/index/model.SoftwareDownload/write.lock
                             at org.apache.lucene.store.Lock.obtain(Lock.java:84)
                             at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1097)
                             at org.hibernate.search.backend.Workspace.createNewIndexWriter(Workspace.java:202)
                             at org.hibernate.search.backend.Workspace.getIndexWriter(Workspace.java:180)
                             at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:103)
                             at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
                             at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
                             at java.util.concurrent.FutureTask.run(FutureTask.java:138)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                             at java.lang.Thread.run(Thread.java:662)


[2013-02-12 15:00:02.943] [2013-02-12 15:00:02,940] ERROR PerDPQueueProcessor.java:118 Hibernate Search: Directory writer-1 ) Unexpected error in Lucene Backend: 
                          org.hibernate.search.SearchException: Unable to remove class model.SoftwareDownload#10019223 from index.
                             at org.hibernate.search.backend.impl.lucene.works.DeleteExtWorkDelegate.performWork(DeleteExtWorkDelegate.java:77)
                             at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:106)
                             at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
                             at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
                             at java.util.concurrent.FutureTask.run(FutureTask.java:138)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                             at java.lang.Thread.run(Thread.java:662)
                          Caused by: java.lang.NullPointerException
                             at org.hibernate.search.backend.impl.lucene.works.DeleteExtWorkDelegate.performWork(DeleteExtWorkDelegate.java:72)
                             ... 7 more


[2013-02-12 15:00:02.944] [2013-02-12 15:00:02,943] ERROR LogErrorHandler.java:82 Hibernate Search: Directory writer-1 ) Exception occurred org.hibernate.search.SearchException: Unable to remove class model.SoftwareDownload#10019223 from index.
                          Primary Failure:
                             Entity model.SoftwareDownload  Id 10019223  Work Type  org.hibernate.search.backend.DeleteLuceneWork
                          Subsequent failures:
                             Entity model.SoftwareDownload  Id 10019223  Work Type  org.hibernate.search.backend.AddLuceneWork
                             Entity model.SoftwareDownload  Id 10019223  Work Type  org.hibernate.search.backend.AddLuceneWork
                          
                          org.hibernate.search.SearchException: Unable to remove class model.SoftwareDownload#10019223 from index.
                             at org.hibernate.search.backend.impl.lucene.works.DeleteExtWorkDelegate.performWork(DeleteExtWorkDelegate.java:77)
                             at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:106)
                             at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
                             at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
                             at java.util.concurrent.FutureTask.run(FutureTask.java:138)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                             at java.lang.Thread.run(Thread.java:662)
                          Caused by: java.lang.NullPointerException
                             at org.hibernate.search.backend.impl.lucene.works.DeleteExtWorkDelegate.performWork(DeleteExtWorkDelegate.java:72)
                             ... 7 more

For the most part I have never seen the above exceptions before and have had little luck finding a solution to them.

I have an index monitor running that says that all 2.1M entities were indexed however when I download the index files from the server and use Luke to examine them only one of the three classes we are indexing has the correct number of documents (the two classes that are incorrect only have 2 documents where there should be several hundred thousand).

Any help that can be provided would be very appreciated and I will be glad to provide any additional information that may be needed.

Thanks!

sanne.grinovero · **Posted:** Wed Feb 13, 2013 8:54 am

Hi,
it looks like you have a horrible pile of related but different exceptions. Having to guess, I think the cause is the LockObtainFailedException : seems your master node was attempting to work on a locked index.

Make sure your index is not locked when Search is started: locked is acceptable but only for read-only operations, while you're attempting to write to the index.
I don't know why it might have been locked, you might have killed a previous run? Normally locks are cleaned up automatically even on killed processes, but your stack mentions SimpleFSLock which is not cleaned up. The framework will automatically pick locking depending on your filesystem and OS capabilities; since you are using SimpleFSLock I'm guessing you are using something unreliable like NFS for index writes.

If it's not a left-over lock from a killed instance, you might want to check you don't have multiple Search instances running in your application which are contending for the index write.

sanne.grinovero · **Posted:** Wed Feb 13, 2013 8:55 am

also: Hibernate Search 3.4 is quite old, you should upgrade. Besides many bugfixes we also improved error messages, reporting and logs to better identify such corner cases.

tunderwood89 · **Joined:** Mon Nov 26, 2012 2:34 pm **Posts:** 6

Thanks for the reply Sanne.

We looked at a few options and found a simple solution for the time being. We have several processes that add/modify entities automatically as cron jobs and it appears that since these processes were running while we were trying to index we ran into some issues. Our solution was to temporarily disable auto indexing and then we went back through and manually and indexed any entities that were modified or added while the index process was running (about 30 entries total).

Also upgrading to a 4.x version of Hibernate search is a priority but is being hindered by our version of Hibernate Core which we are currently working on upgrading.

Thanks again!