After deleting an entity lucene index updating fails due to NullPointerException

Description

When entities are deleted, I noticed an exception with a rather large stack trace (below), which appears to be caused by the fact that Lucene is told to remove from the index a document with a null id.

After (quite) a bit of digging, I believe the source is the top of this stack trace:

DocumentBuilderIndexedEntity<T>.getId(Object) line: 662	
WorkPlan$PerClassWork<T>.extractProperId(Work<T>) line: 233	
WorkPlan$PerClassWork<T>.addWork(Work<T>) line: 205	
WorkPlan.addWork(Work<T>) line: 79	
WorkQueue.add(Work) line: 73	
BatchedQueueingProcessor.add(Work, WorkQueue) line: 115	
PostTransactionWorkQueueSynchronization.add(Work) line: 70	
TransactionalWorker.performWork(Work<?>, TransactionContext) line: 81	
FullTextIndexEventListener.processWork(T, Serializable, WorkType, AbstractEvent, boolean) line: 215	
FullTextIndexEventListener.processCollectionEvent(AbstractCollectionEvent) line: 262	
FullTextIndexEventListener.onPostRemoveCollection(PostCollectionRemoveEvent) line: 227	
CollectionRemoveAction.postRemove() line: 146	
CollectionRemoveAction.execute() line: 119	
ActionQueue.execute(Executable) line: 273	
ActionQueue.executeActions(List) line: 265	
ActionQueue.executeActions() line: 186	
EJB3FlushEventListener(AbstractFlushingEventListener).performExecutions(EventSource) line: 321	
EJB3FlushEventListener(DefaultFlushEventListener).onFlush(FlushEvent) line: 51	
SessionImpl.flush() line: 1216	
SessionImpl.managedFlush() line: 383	
JDBCTransaction.commit() line: 133
TransactionImpl.commit() line: 76
[only application-specific lines below here, omitted]

Specifically, org.hibernate.search.engine.DocumentBuilderIndexedEntity.getId(Object) does:

Object unproxiedEntity = HibernateHelper.unproxy( entity );
return (Serializable) ReflectionHelper.getMemberValue( unproxiedEntity, idGetter );

As far as I can tell, unproxy(entity) will return an entity with a null id if called during postRemove; the returned result is null, although the debugger says that entity.id actually contains the correct (non-null, pre-deletion) value.

org.hibernate.search.engine.WorkPlan.PerClassWork.extractProperId(Work<T>), right below the top of the stack, does:

if ( entity == null || documentBuilder.requiresProvidedId() ||
	( work.isIdentifierWasRolledBack() && documentBuilder.isIdMatchingJpaId() )) {
		return work.getId();
} else {
	return documentBuilder.getId( entity );
}

This condition fails and goes into the "else" block, which is unfortunate, because work.getId() actually contains the correct value.

The error doesn't occur right away: org.hibernate.search.engine.WorkPlan.PerClassWork.addWork(Work<T>) (a bit below the top of the stack) calls "entityById.put( id, entityWork );", with id=null due to the above.

A while later the following happens (the bottom two items are the same as the stack trace above):

DocumentBuilderIndexedEntity<T>.addWorkToQueue(Class<T>, T, Serializable, boolean, boolean, boolean, List<LuceneWork>) line: 355	
WorkPlan$PerEntityWork<T>.enqueueLuceneWork(Class<T>, Serializable, AbstractDocumentBuilder<T>, List<LuceneWork>) line: 449	
WorkPlan$PerClassWork<T>.enqueueLuceneWork(List<LuceneWork>) line: 250	
WorkPlan.getPlannedLuceneWork() line: 150	
WorkQueue.prepareWorkPlan() line: 134	
BatchedQueueingProcessor.prepareWorks(WorkQueue) line: 124	
PostTransactionWorkQueueSynchronization.beforeCompletion() line: 89	
EventSourceTransactionContext$DelegateToSynchronizationOnBeforeTx.doBeforeTransactionCompletion(SessionImplementor) line: 172	
ActionQueue$BeforeTransactionCompletionProcessQueue.beforeTransactionCompletion() line: 543	
ActionQueue.beforeTransactionCompletion() line: 216	
SessionImpl.beforeTransactionCompletion(Transaction) line: 571	
JDBCContext.beforeTransactionCompletion(Transaction) line: 250	
JDBCTransaction.commit() line: 138	
TransactionImpl.commit() line: 76

The entry at the top belongs to

public void addWorkToQueue(Class<T> entityClass, T entity, Serializable id, boolean delete, boolean add, boolean batch, List<LuceneWork> queue) {
	String idInString = objectToString( idBridge, idKeywordName, id );
	if ( delete ) {
		queue.add( new DeleteLuceneWork( id, idInString, entityClass ) );
	}
	if ( add ) {
		queue.add( createAddWork( entityClass, entity, id, idInString, HibernateStatelessInitializer.INSTANCE, batch ) );
	}
}

The argument delete is true and id is null (it's the value of WorkPlan$PerClassWork<T>.enqueueLuceneWork(List<LuceneWork>) gets it from the documentBuilder.getId(entity) call mentioned above). A little while later the actual exception is triggered:

java.lang.NullPointerException
	at org.apache.lucene.index.Term.compareTo(Term.java:115)
	at org.apache.lucene.index.TermInfosReader.getIndexOffset(TermInfosReader.java:189)
	at org.apache.lucene.index.TermInfosReader.get(TermInfosReader.java:268)
	at org.apache.lucene.index.TermInfosReader.get(TermInfosReader.java:208)
	at org.apache.lucene.index.SegmentTermDocs.seek(SegmentTermDocs.java:57)
	at org.apache.lucene.index.BufferedDeletes.applyDeletes(BufferedDeletes.java:312)
	at org.apache.lucene.index.BufferedDeletes.applyDeletes(BufferedDeletes.java:289)
	at org.apache.lucene.index.BufferedDeletes.applyDeletes(BufferedDeletes.java:191)
	at org.apache.lucene.index.IndexWriter.doFlush(IndexWriter.java:3358)
	at org.apache.lucene.index.IndexWriter.flush(IndexWriter.java:3296)
	at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:1836)
	at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1800)
	at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1764)
	at org.hibernate.search.backend.Workspace.closeIndexWriter(Workspace.java:244)
	at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:113)
	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)
ERROR o.h.s.e.i.LogErrorHandler - Exception occurred java.lang.NullPointerException
Primary Failure:
	Entity com.dragg.server.model.Walk  Id null  Work Type  org.hibernate.search.backend.DeleteLuceneWork
Subsequent failures:
	Entity com.dragg.server.model.Walk  Id null  Work Type  org.hibernate.search.backend.AddLuceneWork
	Entity com.dragg.server.model.Walk  Id 5552  Work Type  org.hibernate.search.backend.DeleteLuceneWork

java.lang.NullPointerException
	at org.apache.lucene.index.Term.compareTo(Term.java:115)
	at org.apache.lucene.index.TermInfosReader.getIndexOffset(TermInfosReader.java:189)
	at org.apache.lucene.index.TermInfosReader.get(TermInfosReader.java:268)
	at org.apache.lucene.index.TermInfosReader.get(TermInfosReader.java:208)
	at org.apache.lucene.index.SegmentTermDocs.seek(SegmentTermDocs.java:57)
	at org.apache.lucene.index.BufferedDeletes.applyDeletes(BufferedDeletes.java:312)
	at org.apache.lucene.index.BufferedDeletes.applyDeletes(BufferedDeletes.java:289)
	at org.apache.lucene.index.BufferedDeletes.applyDeletes(BufferedDeletes.java:191)
	at org.apache.lucene.index.IndexWriter.doFlush(IndexWriter.java:3358)
	at org.apache.lucene.index.IndexWriter.flush(IndexWriter.java:3296)
	at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:1836)
	at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1800)
	at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1764)
	at org.hibernate.search.backend.Workspace.closeIndexWriter(Workspace.java:244)
	at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:113)
	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)

org.apache.lucene.index.Term.compareTo fails because this.id is null, having received its value a bit earlier from the null document id above. (Technically, I think this also a bug in lucene; surrounding code, for example Term.equals, does test for null, so either Term.compareTo should do it, or the Term should have been checked for null quite a while earlier. Anyway, the results would have been the same, except for easier debugging.)

Attachments

17 Aug 2011, 08:52 PM

Activity

Show:

Emmanuel Bernard November 4, 2011 at 12:06 PM

Removing fix version as we could not reproduce the issue and are awaiting a test case.

Sanne Grinovero August 22, 2011 at 11:38 PM

Hi Pablo,
thank you very much for the patch. I would really need a test to make sure I can fix this in newer versions and prevent future regressions; could you please try to simplify your entities as much as possible so that we can understand in which conditions this is happening?

Pablo Lillia August 17, 2011 at 8:52 PM

We had this problem with hibernate-search-3.1.1.GA (w/Seam 2.1.1.GA).
We are using this patch as workaround.
We face this NPE with an update of two complex associated entities in the same transaction.

Hardy Ferentschik August 10, 2011 at 2:56 PM

I think your scenario is too simple (incomplete)

org.hibernate.Session s = ...;
s.get(ClassA.class, ida);
ClassB value = s.get(ClassB.class, idb);
s.delete(value);

I tried to create a test case based on these steps and it works fine -
https://github.com/hferentschik/hibernate-search/commit/28b0a5eeb5ec0b06a443c095a327d239b30a07c6

Obviously these are very simple entities. Maybe you can help to extend this test. How do your annotated
entities look like and what exactly happens within the transaction? Feel free to use my test setup
as a starting ground.

Bogdan Butnaru August 10, 2011 at 11:30 AM
Edited

I don’t have a test case separate from my application (I did the debugging believing it was my app’s fault somehow), though I could probably try building one if it’s still needed.

When I get through to the call you mention the stack has this as the top:

WorkPlan$PerClassWork<T>.extractProperId(Work<T>) line: 186
WorkPlan$PerClassWork<T>.addWork(Work<T>) line: 167
WorkPlan.addWork(Work<T>) line: 73
WorkQueue.add(Work) line: 73
BatchedQueueingProcessor.add(Work, WorkQueue) line: 115
PostTransactionWorkQueueSynchronization.add(Work) line: 70
TransactionalWorker.performWork(Work<?>, TransactionContext) line: 81
FullTextIndexEventListener.processWork(T, Serializable, WorkType, AbstractEvent, boolean) line: 215
FullTextIndexEventListener.processCollectionEvent(AbstractCollectionEvent) line: 262
FullTextIndexEventListener.onPostRemoveCollection(PostCollectionRemoveEvent) line: 227
CollectionRemoveAction.postRemove() line: 146
CollectionRemoveAction.execute() line: 119
ActionQueue.execute(Executable) line: 273
ActionQueue.executeActions(List) line: 265
ActionQueue.executeActions() line: 186
EJB3FlushEventListener(AbstractFlushingEventListener).performExecutions(EventSource) line: 321
EJB3FlushEventListener(DefaultFlushEventListener).onFlush(FlushEvent) line: 51
SessionImpl.flush() line: 1216
SessionImpl.managedFlush() line: 383
JDBCTransaction.commit() line: 133
TransactionImpl.commit() line: 76
[application-specific stack elements below here, omitted]

As far as I can tell, the entire transaction that is committed can be summarized as:

org.hibernate.Session s = ...;
s.get(ClassA.class, ida);
ClassB value = s.get(ClassB.class, idb);
s.delete(value);

At that point:

“entity” is not null, but the value I am deleting (though its id is already null, unlike what I mentioned above);
“documentBuilder” is an instance of org.hibernate.search.engine.DocumentBuilderIndexedEntity<T>, and its requiresProvidedId() method returns “this.idProvided”, which is false.
“work.isIdentifierWasRolledBack” return “this.identifierWasRolledBack”, which is false, so the conjunction is also false (“documentBuilder.isIdMatchingJpaId()” would have returned true if it were evaluated).

I’m not sure if “work.isIdentifierWasRolledBack” is intended to be set only for rolled back transactions or in case of deletion too (I can’t quite figure out when the entity id is unset).

For the record, I replaced the content of the “else” clause in the snippet you mentioned with:

Serializable dbId = documentBuilder.getId(entity);
if (dbId == null) return work.getId();
else return dbId;

and my problem at least went away, though I didn’t do enough testing yet to be sure I didn’t break anything else.

Cannot Reproduce

Details
Assignee
Hardy Ferentschik
Reporter
Bogdan Butnaru
Components
engine
Affects versions
3.4.0.Final
3.4.1.Final
4.0.0.Alpha1
4.0.0.Alpha2
Priority
Critical

Created August 9, 2011 at 8:02 PM

Updated July 9, 2012 at 6:35 PM

Resolved July 9, 2012 at 6:35 PM

After deleting an entity lucene index updating fails due to NullPointerException

Description

Attachments

Activity

Emmanuel Bernard November 4, 2011 at 12:06 PM

Sanne Grinovero August 22, 2011 at 11:38 PM

Pablo Lillia August 17, 2011 at 8:52 PM

Hardy Ferentschik August 10, 2011 at 2:56 PM

Bogdan Butnaru August 10, 2011 at 11:30 AM
Edited

Details
Assignee
Hardy Ferentschik
Reporter
Bogdan Butnaru
Components
engine
Affects versions
3.4.0.Final
3.4.1.Final
4.0.0.Alpha1
4.0.0.Alpha2
Priority
Critical

Details

Assignee

Reporter

Components

Affects versions

Priority

Flag notifications

Something's gone wrong

After deleting an entity lucene index updating fails due to NullPointerException

Description

Attachments

Activity

Emmanuel Bernard November 4, 2011 at 12:06 PM

Sanne Grinovero August 22, 2011 at 11:38 PM

Pablo Lillia August 17, 2011 at 8:52 PM

Hardy Ferentschik August 10, 2011 at 2:56 PM

Bogdan Butnaru August 10, 2011 at 11:30 AMEdited

DetailsAssigneeHardy FerentschikHardy FerentschikReporterBogdan ButnaruBogdan ButnaruComponentsengineAffects versions3.4.0.Final3.4.1.Final4.0.0.Alpha14.0.0.Alpha2PriorityCritical

Details

Assignee

Reporter

Components

Affects versions

Priority

Flag notifications

Something's gone wrong

Bogdan Butnaru August 10, 2011 at 11:30 AM
Edited

Details
Assignee
Hardy Ferentschik
Reporter
Bogdan Butnaru
Components
engine
Affects versions
3.4.0.Final
3.4.1.Final
4.0.0.Alpha1
4.0.0.Alpha2
Priority
Critical