1:56 p.m.
NPE in org.hibernate.search.backend.WorkQueue.clear()
-----------------------------------------------------
Key: HSEARCH-399
URL:
http://opensource.atlassian.com/projects/hibernate/browse/HSEARCH-399
Project: Hibernate Search
Issue Type: Bug
Affects Versions: 3.1.1.GA
Reporter: Dobes Vandermeer
Our server blew up, and we're seeing a continuous stream of:
[#|2009-09-17T06:24:02.169-0700|SEVERE|sun-appserver9.1|books.db.search.SafeBatchedQueueingProcessor|_ThreadID=40;_Threa
dName=httpSSLWorkerThread-8080-19;_RequestID=97e3df6c-2fc7-4f54-a47a-e77ba48d1a07;|RuntimeException
during cancelWorks()
java.lang.NullPointerException
at org.hibernate.search.backend.WorkQueue.clear(WorkQueue.java:58)
at
org.hibernate.search.backend.impl.BatchedQueueingProcessor.cancelWorks(BatchedQueueingProcessor.java:180)
at
org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization.afterCompletion(PostTransactionWorkQueueSynchronization.java:56)
at
com.sun.enterprise.distributedtx.J2EETransaction.commit(J2EETransaction.java:491)
The method body for this is:
public void clear() {
queue.clear(); // <---- queue is null
if (sealedQueue != null) sealedQueue.clear();
}
It appears that queue may be set null by the setSealedQueue method above:
public void setSealedQueue(List<LuceneWork> sealedQueue) {
//invalidate the working queue for serializability
queue = null;
this.sealedQueue = sealedQueue;
}
The only change I've made recently that I thought could cause this was to change the
search system to run in a separate thread. My hibernate search options are:
<exclude-unlisted-classes>true</exclude-unlisted-classes>
<properties>
<property name="hibernate.dialect"
value="org.hibernate.dialect.PostgreSQLDialect"/>
<property name="hibernate.show_sql" value="false"/>
<property name="hibernate.cache.provider_class"
value="net.sf.ehcache.hibernate.EhCacheProvider"/>
<property name="hibernate.cache.use_query_cache"
value="true"/>
<property name="hibernate.cache.use_second_level_cache"
value="true"/>
<property name="hibernate.bytecode.provider"
value="javassist"/>
<property name="hibernate.search.default.directory_provider"
value="org.hibernate.search.store.FSDirectoryProvider"/>
<property name="hibernate.search.default.indexBase"
value="../search-indexes"/>
<property name="hibernate.search.worker.scope"
value="books.db.search.SafeWorkerImpl"/>
<property name="hibernate.search.worker.backend"
value="books.db.search.SafeBackendQueueProcessorFactory"/>
<property name="hibernate.search.worker.execution"
value="async"/> <!-- sync or async -->
<property name="hibernate.search.worker.buffer_queue.max"
value="5"/>
<property name="hibernate.search.worker.thread_pool.size"
value="5"/>
</properties>
Note that books.db.search.Safe* are classes I wrote that wrap the default implementation
with an exception handler; sometimes RuntimeExceptions were thrown and glassfish would
just silently eat them and fail, now they are noisily eaten and the transaction commits
anyway.
This was probably (to some degree) triggered by the exception logged just prior:
[#|2009-09-17T06:23:56.498-0700|SEVERE|sun-appserver9.1|org.hibernate.event.def.AbstractFlushingEventListener|_ThreadID=40;_ThreadName=httpSSLWorkerThread-8080-19;_RequestID=97e3df6c-2fc7-4f54-a47a-e77ba48d1a07;|Could
not synchronize database state with session
org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction
(or unsaved-value mapping was incorrect): [books.db.Business#5617057]
at
org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1782)
at
org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2425)
at
org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2325)
at
org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2625)
at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:115)
at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:263)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:168)
at
org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
at
org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1028)
at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:366)
at
org.hibernate.ejb.AbstractEntityManagerImpl$1.beforeCompletion(AbstractEntityManagerImpl.java:504)
at
com.sun.enterprise.distributedtx.J2EETransaction.commit(J2EETransaction.java:419)
Figuring out under which conditions the queue became null but shouldn't have been
might be nearly impossible at this point, although I'll watch out for repeats of this
issue.
The NPE itself might be easier to fix, if you just check for null before calling clear().
For now I'll try implementing a workaround in my safe subclass like this:
@Override
public void cancelWorks(WorkQueue workQueue) {
try {
super.cancelWorks(workQueue);
} catch (RuntimeException e) {
logger.error("RuntimeException during cancelWorks()", e);
try {
if(workQueue.getQueue() != null)
workQueue.getQueue().clear();
else
workQueue.getSealedQueue().clear();
} catch(org.hibernate.annotations.common.AssertionFailure t) {
// sealedQueue was null too
}
}
}
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://opensource.atlassian.com/projects/hibernate/secure/Administrators....
-
For more information on JIRA, see: http://www.atlassian.com/software/jira