Possible EJB persistent timer bug?
scotto Jun 15, 2006 12:42 AMHello.
I am using JBossAs 4.0.4.GA with EJB3.0 RC8 and Postgres, and have implemented a jBPM timer service as a SLSB in a similar way to this post:
http://www.jboss.com/index.html?module=bb&op=viewtopic&t=74691
However, after running for some time I get this exception:
2006-06-14 19:52:18,328 ERROR [org.jboss.ejb.txtimer.TimerServiceImpl] Cannot create txtimer
java.lang.IllegalStateException: Unable to persist timer
at org.jboss.ejb.txtimer.DatabasePersistencePolicy.insertTimer(DatabasePersistencePolicy.java:126)
at jrockit.reflect.VirtualNativeMethodInvoker.invoke(Ljava.lang.Object;[Ljava.lang.Object;)Ljava.lang.Object;(Unknown Source)
at java.lang.reflect.Method.invoke(Ljava.lang.Object;[Ljava.lang.Object;I)Ljava.lang.Object;(Unknown Source)
at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:155)
at org.jboss.mx.server.Invocation.dispatch(Invocation.java:94)
at org.jboss.mx.server.Invocation.invoke(Invocation.java:86)
at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:659)
at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:210)
at $Proxy26.insertTimer(Ljava.lang.String;Lorg.jboss.ejb.txtimer.TimedObjectId;Ljava.util.Date;JLjava.io.Serializable;)V(Unknown Source)
at org.jboss.ejb.txtimer.TimerServiceImpl.createTimer(TimerServiceImpl.java:256)
at org.jboss.ejb.txtimer.TimerServiceImpl.createTimer(TimerServiceImpl.java:202)
at com.vieo.ccs.server.bean.JbpmSchedulerBean.timeoutHandler(JbpmSchedulerBean.java:107)
at jrockit.reflect.VirtualNativeMethodInvoker.invoke(Ljava.lang.Object;[Ljava.lang.Object;)Ljava.lang.Object;(Unknown Source)
at java.lang.reflect.Method.invoke(Ljava.lang.Object;[Ljava.lang.Object;I)Ljava.lang.Object;(Unknown Source)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112)
at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166)
at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54)
Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key violates unique constraint "timers_pk"
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:1512)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1297)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:188)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:430)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:346)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:300)
at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:251)
at org.jboss.ejb.txtimer.GeneralPurposeDatabasePersistencePlugin.insertTimer(GeneralPurposeDatabasePersistencePlugin.java:186)
at org.jboss.ejb.txtimer.DatabasePersistencePolicy.insertTimer(DatabasePersistencePolicy.java:122)
at jrockit.reflect.VirtualNativeMethodInvoker.invoke(Ljava.lang.Object;[Ljava.lang.Object;)Ljava.lang.Object;(Unknown Source)
at java.lang.reflect.Method.invoke(Ljava.lang.Object;[Ljava.lang.Object;I)Ljava.lang.Object;(Unknown Source)
at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:155)
at org.jboss.mx.server.Invocation.dispatch(Invocation.java:94)
at org.jboss.mx.server.Invocation.invoke(Invocation.java:86)
at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:659)
at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:210)
at $Proxy26.insertTimer(Ljava.lang.String;Lorg.jboss.ejb.txtimer.TimedObjectId;Ljava.util.Date;JLjava.io.Serializable;)V(Unknown Source)
at org.jboss.ejb.txtimer.TimerServiceImpl.createTimer(TimerServiceImpl.java:256)
at org.jboss.ejb.txtimer.TimerServiceImpl.createTimer(TimerServiceImpl.java:202)
at com.vieo.ccs.server.bean.JbpmSchedulerBean.timeoutHandler(JbpmSchedulerBean.java:107)
Other people seem to be having a similar problem too:
http://www.jboss.com/index.html?module=bb&op=viewtopic&t=84439
http://www.jboss.com/index.html?module=bb&op=viewtopic&t=76127
http://www.jboss.com/index.html?module=bb&op=viewtopic&t=60741
I have spent some time investigating this and there definitely seems to be a conflict with old timers not being cleared from the database:
My test server is up and down all the time during development (not always shutdown cleanly) and as a result there are 3 'stale' entries in the Timer database table (some a few days old even). The above exception occurs as a result of a new timer being created with the same ID as one of these stale database entries.
I see two related causes for this:
1. The TimerIdGenerator implementation (BigIntegerTimerIdGenerator.java) always initialises its count to 0 at system start.
2. For some reason, the old/obsolete timers are not being cleaned from the database at startup.
The combination of these two factors ensures that if there are stale timer entries it is only a matter of time until the new timer ID increments until it reaches the ID of an existing timer!
It seems to me that the code causing factor 1 is inherently unsafe in a persistent environment - I would have expected the TimerIdGenerator implementation to make some kind of 'get next value' or sequence call on the database? Isn't having a transient counter like this asking for trouble in a persisted environment?
Also, after debugging the server startup and application deployment, for some reason it appears that EJBTimerServiceImpl.restoreTimers() is never being called. The only place I can see that might invoke this are when the EntityContainer and SessionContainer classes are started, yet this does not appear to happen (possibly because I am looking at JBossAS source code only?) I don't have the EJB3 source but maybe the EJB3 container does not make this call?
This seems to me to be a critical problem with EJB timers and I hope what I have said makes sense and can be fixed.
Thanks
Scott