Exceptions When Updating Indexed Entities

jnadler · **Posted:** Mon Apr 19, 2010 3:45 pm

HSearch has been working very very well in our app for some time. We have a batch job that updates lots of user entities, these are very simple User is indexed and each User has one UserDetails entity which is @IndexedEmbedded and @ContainedIn.

Since upgrading to 3.2, (currently 3.2.0.CR1) we are seeing loads of errors like the one below as the process runs and updates existing User entities:

Code:

[2010-04-19 11:56:17.017,118854]ERROR[Hibernate Search: Directory writer-1](LogErrorHandler.java:83) - Exception occurred org.hibernate.search.SearchException: Unable to open IndexWriter
Primary Failure:
   Entity com.attensa.core.entity.User  Id 2  Work Type  org.hibernate.search.backend.DeleteLuceneWork
Subsequent failures:
   Entity com.attensa.core.entity.User  Id 2  Work Type  org.hibernate.search.backend.AddLuceneWor

org.hibernate.search.SearchException: Unable to open IndexWriter
   at org.hibernate.search.backend.Workspace.getIndexWriter(Workspace.java:159)
   at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:103)
   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:619)
Caused by: org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: SimpleFSLock@\usr\local\attensa\index\Party\lucene-79932a48b4576913b5d1b58198038cfd-write.lock
   at org.apache.lucene.store.Lock.obtain(Lock.java:85)
   at org.apache.lucene.index.IndexWriter.init(IndexWriter.java:1550)
   at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1079)
   at org.hibernate.search.backend.Workspace.getIndexWriter(Workspace.java:152)
   ... 4 more
[2010-04-19 11:56:17.031,118868]WARN [Hibernate Search: Directory writer-1](Workspace.java:221) - going to force release of the IndexWriter lock

We saw a similar error in other areas of our app in our initial tests of 3.2, but now that 3.2.0.CR1 is out this is the only remaining problem we are seeing.

jnadler · **Posted:** Tue Apr 20, 2010 1:09 pm

Hey, no spamming on my thread!

sanne.grinovero · **Posted:** Tue Apr 20, 2010 4:29 pm

jnadler wrote:

Hey, no spamming on my thread!

right, deleted and banned. please use the reporting tool

Quote:

Caused by: org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out

means you either had a stale lock in the directory even before Search was started (you can check the list of files to see if there is a file lock), or it means that you're starting more than one instance of Hibernate Search.

How is your batch job designed? please consider that the directory should be used exclusively by one Hibernate Search instance.
Also consider that a bug in previous versions of Search prevented it to log this kind of exceptions; you might have had the same error before but not have noticed it.

jnadler · **Posted:** Tue Apr 20, 2010 5:46 pm

Thanks for the reply Sanne!

The other error that I see is below. Indeed the directory is used by only one instance of Hibernate Search.

The batch job is single threaded, loops across thousands of User entities, updates the UserDetails (which is @IndexedEmbedded) for each. It does all the updates in one big transaction. It's very straightforward. Could updating too many indexed records in a single TX cause this issue?

Code:

[2010-04-20 02:39:08.254,440346]ERROR[Hibernate Search: Directory writer-1](PerDPQueueProcessor.java:118) - Unexpected error in Lucene Backend: 
org.hibernate.search.SearchException: Unable to remove class com.attensa.core.entity.User#1378 from index.
   at org.hibernate.search.backend.impl.lucene.works.DeleteWorkDelegate.performWork(DeleteWorkDelegate.java:83)
   at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:106)
   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:619)
Caused by: org.apache.lucene.store.AlreadyClosedException: this IndexWriter is closed
   at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:801)
   at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:806)
   at org.apache.lucene.index.IndexWriter.deleteDocuments(IndexWriter.java:2561)
   at org.hibernate.search.backend.impl.lucene.works.DeleteWorkDelegate.performWork(DeleteWorkDelegate.java:79)
   ... 4 more
[2010-04-20 02:39:08.254,440346]ERROR[Hibernate Search: Directory writer-1](LogErrorHandler.java:83) - Exception occurred org.hibernate.search.SearchException: Unable to remove class com.attensa.core.entity.User#1378 from index.
Primary Failure:
   Entity com.attensa.core.entity.User  Id 1378  Work Type  org.hibernate.search.backend.DeleteLuceneWork
Subsequent failures:
   Entity com.attensa.core.entity.User  Id 1378  Work Type  org.hibernate.search.backend.AddLuceneWork

org.hibernate.search.SearchException: Unable to remove class com.attensa.core.entity.User#1378 from index.
   at org.hibernate.search.backend.impl.lucene.works.DeleteWorkDelegate.performWork(DeleteWorkDelegate.java:83)
   at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:106)
   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:619)
Caused by: org.apache.lucene.store.AlreadyClosedException: this IndexWriter is closed
   at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:801)
   at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:806)
   at org.apache.lucene.index.IndexWriter.deleteDocuments(IndexWriter.java:2561)
   at org.hibernate.search.backend.impl.lucene.works.DeleteWorkDelegate.performWork(DeleteWorkDelegate.java:79)
   ... 4 more

sanne.grinovero · **Posted:** Tue Apr 20, 2010 5:50 pm

isn't there a first error different from the others? In case of exceptions the indexwriter might be closed, for example in case of an outofmemory

jnadler · **Posted:** Wed Apr 21, 2010 1:29 am

I don't see any other exceptions. I just did a run with debug logging enabled and I get (remember that I'm looping across thousands of Users, updating UserDetails for each):

1. hundreds of lines like this, with an optimize every 100 updates as expected, it ran for over a minute like this:

Code:

[2010-04-20 10:21:59.286,211153]DEBUG[Hibernate Search: Directory writer-1](PerDPQueueProcessor.java:99) - Opening an IndexWriter for update
[2010-04-20 10:21:59.468,211335]DEBUG[Hibernate Search: Directory writer-1](PerDPQueueProcessor.java:99) - Opening an IndexWriter for update
[2010-04-20 10:21:59.578,211445]DEBUG[Hibernate Search: Directory writer-1](PerDPQueueProcessor.java:99) - Opening an IndexWriter for update

2. then I start seeing some updates on 'backend queueing processor' threads:

Code:

[2010-04-20 10:21:59.833,211700]DEBUG[Hibernate Search: backend queueing processor-2](PerDPQueueProcessor.java:99) - Opening an IndexWriter for update
[2010-04-20 10:21:59.860,211727]DEBUG[Hibernate Search: Directory writer-1](PerDPQueueProcessor.java:99) - Opening an IndexWriter for update
[2010-04-20 10:21:59.933,211800]DEBUG[Hibernate Search: backend queueing processor-1](PerDPQueueProcessor.java:99) - Opening an IndexWriter for update
[2010-04-20 10:22:00.020,211887]DEBUG[Hibernate Search: backend queueing processor-2](PerDPQueueProcessor.java:99) - Opening an IndexWriter for update
[2010-04-20 10:22:00.225,212092]DEBUG[Hibernate Search: backend queueing processor-2](PerDPQueueProcessor.java:99) - Opening an IndexWriter for update
[2010-04-20 10:22:00.373,212240]DEBUG[Hibernate Search: Directory writer-1](PerDPQueueProcessor.java:99) - Opening an IndexWriter for update
[2010-04-20 10:22:00.594,212461]DEBUG[Hibernate Search: Directory writer-1](PerDPQueueProcessor.java:99) - Opening an IndexWriter for update
[2010-04-20 10:22:00.594,212461]DEBUG[Hibernate Search: backend queueing processor-1](PerDPQueueProcessor.java:99) - Opening an IndexWriter for update
[2010-04-20 10:22:00.933,212800]DEBUG[Hibernate Search: backend queueing processor-2](PerDPQueueProcessor.java:99) - Opening an IndexWriter for update
[2010-04-20 10:22:01.112,212979]DEBUG[Hibernate Search: backend queueing processor-2](PerDPQueueProcessor.java:99) - Opening an IndexWriter for update

3. three seconds after it started with those backend queueing processor threads:

Code:

[2010-04-20 10:22:03.588,215455]ERROR[Hibernate Search: backend queueing processor-1](PerDPQueueProcessor.java:118) - Unexpected error in Lucene Backend: 
org.apache.lucene.store.AlreadyClosedException: this IndexWriter is closed
   at org.apache.lucene.index.DocumentsWriter.waitReady(DocumentsWriter.java:868)
   at org.apache.lucene.index.DocumentsWriter.getThreadState(DocumentsWriter.java:705)
   at org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:771)
   at org.apache.lucene.index.DocumentsWriter.addDocument(DocumentsWriter.java:759)
   at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:2477)
   at org.hibernate.search.backend.impl.lucene.works.AddWorkDelegate.performWork(AddWorkDelegate.java:77)
   at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:106)
   at java.util.concurrent.ThreadPoolExecutor$CallerRunsPolicy.rejectedExecution(ThreadPoolExecutor.java:1746)
   at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:767)
   at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:658)
   at org.hibernate.search.backend.impl.lucene.QueueProcessors.runAllAsync(QueueProcessors.java:85)
   at org.hibernate.search.backend.impl.lucene.QueueProcessors.runAll(QueueProcessors.java:73)
   at org.hibernate.search.backend.impl.lucene.LuceneBackendQueueProcessor.run(LuceneBackendQueueProcessor.java:81)
   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:619)
[2010-04-20 10:22:03.592,215459]ERROR[Hibernate Search: backend queueing processor-1](LogErrorHandler.java:83) - Exception occurred org.apache.lucene.store.AlreadyClosedException: this IndexWriter is closed
Primary Failure:
   Entity com.attensa.core.entity.User  Id 1299  Work Type  org.hibernate.search.backend.AddLuceneWork

org.apache.lucene.store.AlreadyClosedException: this IndexWriter is closed
   at org.apache.lucene.index.DocumentsWriter.waitReady(DocumentsWriter.java:868)
   at org.apache.lucene.index.DocumentsWriter.getThreadState(DocumentsWriter.java:705)

sanne.grinovero · **Posted:** Wed Apr 21, 2010 1:48 am

could you post the configuration properties relating to Search?
Is there only one type being indexed?
(and this was working on 3.1.1 right?)

jnadler · **Posted:** Wed Apr 21, 2010 1:58 am

All the errors above were running async. I switched to sync and it ran fine. Slow but fine:

Code:

hibernate.search.worker.execution=sync

jnadler · **Posted:** Wed Apr 21, 2010 1:59 am

One entity (User) is indexed, it has a OneToOne with a second entity (UserDetails) that is included via @IndexedEmbedded

My config is pretty basic:

Code:

hibernate.search.default.directory_provider=org.hibernate.search.store.FSDirectoryProvider
hibernate.search.worker.execution=sync
hibernate.search.default.optimizer.transaction_limit.max=100

Yes, it ran on 3.1.1. It's a fairly new process, and you mentioned that errors like these were not being thrown in older versions, so I guess it's possible that it was happening 'under the covers' and I just didn't notice?

sanne.grinovero · **Posted:** Wed Apr 21, 2010 3:30 am

Quote:

so I guess it's possible that it was happening 'under the covers' and I just didn't notice?

yes that's possible.

Could you post your Lucene version and a more detailed log?
I'm missing some parts which I need to see, please post a longer part of the log and set the logger at trace level for
org.hibernate.search.backend

jnadler · **Posted:** Wed Apr 21, 2010 2:34 pm

Thank you very much for your continued assistance Sanne.

Lucene is 2.9.2 (via Maven dependency from hibernate-search)

I have posted a log file to http://www.attensa.com/download/files/attensa.log the first exception is at timestamp [2010-04-21 11:23:45.992,236829]

jnadler · **Posted:** Fri Apr 23, 2010 3:46 pm

Opened a Jira here:

http://opensource.atlassian.com/project ... SEARCH-515

sanne.grinovero · **Posted:** Fri Apr 23, 2010 4:51 pm

thanks, well done