[hibernate-issues] [Hibernate-JIRA] Issue Comment Edited: (HSEARCH-841) after deleting an entity lucene index updating fails due to NullPointerException
Bogdan Butnaru (JIRA)
noreply at atlassian.com
Wed Aug 10 05:37:02 EDT 2011
[ http://opensource.atlassian.com/projects/hibernate/browse/HSEARCH-841?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=43206#comment-43206 ]
Bogdan Butnaru edited comment on HSEARCH-841 at 8/10/11 4:35 AM:
-----------------------------------------------------------------
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:
{quote}
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]
{quote}
As far as I can tell, the entire transaction that is committed can be summarized as:
{code}
org.hibernate.Session s = ...;
s.get(ClassA.class, ida);
ClassB value = s.get(ClassB.class, idb);
s.delete(value);
{code}
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 “else” clause in the snippet you mentioned with:
{code}
Serializable dbId = documentBuilder.getId(entity);
if (dbId == null) return work.getId();
else return dbId;
{code}
and my problem at least went away, though I didn’t do enough testing yet to be sure I didn’t break anything else.
was (Author: bogdanb2):
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 it’s 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 “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.
(PS. Sorry for the lack of formatting, for some reason I can’t seem to make the wiki syntax previewed.)
> after deleting an entity lucene index updating fails due to NullPointerException
> --------------------------------------------------------------------------------
>
> Key: HSEARCH-841
> URL: http://opensource.atlassian.com/projects/hibernate/browse/HSEARCH-841
> Project: Hibernate Search
> Issue Type: Bug
> Components: engine
> Affects Versions: 3.4.0.Final
> Environment: Hibernate 3.4.0 (on MySQL 5.1.54, but any database is affected AFAIK)
> Reporter: Bogdan Butnaru
> Priority: Critical
> Fix For: 3.4.1, 4.0.0.Alpha1
>
>
> 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.)
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the hibernate-issues
mailing list