[hibernate-issues] [Hibernate-JIRA] Updated: (HSEARCH-841) After deleting an entity lucene index updating fails due to NullPointerException

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, 3.4.1.Final, 4.0.0.Alpha1, 4.0.0.Alpha2 Environment: Hibernate 3.4.0 (on MySQL 5.1.54, but any database is affected AFAIK) Reporter: Bogdan Butnaru Assignee: Hardy Ferentschik Priority: Critical Attachments: hibernate-search-3.1.1.GA.patch1 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: {noformat} 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] {noformat} Specifically, _org.hibernate.search.engine.DocumentBuilderIndexedEntity.getId(Object)_ does: {code} Object unproxiedEntity = HibernateHelper.unproxy( entity ); return (Serializable) ReflectionHelper.getMemberValue( unproxiedEntity, idGetter ); {code} 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: {code} if ( entity == null || documentBuilder.requiresProvidedId() || ( work.isIdentifierWasRolledBack() && documentBuilder.isIdMatchingJpaId() )) { return work.getId(); } else { return documentBuilder.getId( entity ); } {code} 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): {noformat} 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 {noformat} The entry at the top belongs to {code} 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 ) ); } } {code} 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: {noformat} 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) {noformat} _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.)