[jboss-user] [EJB/JBoss] - EJBTimerService persistent timers intermittently lost

Fri Nov 17 14:30:09 EST 2006

We are using EJBTimerService w/database persistence policy as provided in the distribution in ejb-deployer.xml.  The system generally works, with timers persisted and recovered over many server restarts and timer expirations.

[Versions we are using: JBoss 4.0.5.GA, Hibernate 3.2.0, EJB 2.1, Oracle 9.2]  

Over various trials, we have observed all of the TIMER table rows deleted after a random amount of time, from 10 minutes to several hours.  All of the timers are deleted, even though many of them are weekly, and were nowhere near expiration.  The timers vanish from the TIMERS table while the server is still running.  Calling javax.ejb.TimerService.getTimers in the running server still shows the timers, but listing the contents of TIMERS table shows nothing.  When the server is restarted, because the timers have dropped out of the table, they are not instantiated in the newly started server.

We added this to log4j.xml:

   <category name="org.jboss.ejb.txtimer">
  |       <priority value="TRACE"/>
  |    </category>
  | 
No timer-related exceptions shown in the log.  During the time period shown in the log below, the timer rows were deleted from the TIMERS table.  The log shows no variation in TimerImpl activity.

Have others reported an issue like this?  Is there a way to get more logging from Timer code?

TIA,
Vick

2006-11-17 10:58:49,807 DEBUG http-0.0.0.0-18080-1 [EJBTimerServiceImpl] createTimerService: org.jboss.ejb.txtimer.TimerServiceImpl at 11e8e72
2006-11-17 10:58:50,010 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: created
2006-11-17 10:58:50,026 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: started_in_tx
2006-11-17 10:58:50,057 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: created
2006-11-17 10:58:50,057 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: started_in_tx
2006-11-17 10:58:50,073 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: created
2006-11-17 10:58:50,088 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: started_in_tx
2006-11-17 10:58:50,104 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: created
2006-11-17 10:58:50,104 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: started_in_tx
2006-11-17 10:58:50,104 DEBUG http-0.0.0.0-18080-1 [TimerImpl] commit: [id=1,target=[target=jboss.j2ee:jndiName=cc/NotificationController,service=EJB],remaining=223269896,periode=604800000,started_in_tx]
2006-11-17 10:58:50,104 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: active
2006-11-17 10:58:50,104 DEBUG http-0.0.0.0-18080-1 [TimerImpl] commit: [id=2,target=[target=jboss.j2ee:jndiName=cc/NotificationController,service=EJB],remaining=313269896,periode=604800000,started_in_tx]
2006-11-17 10:58:50,104 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: active
2006-11-17 10:58:50,104 DEBUG http-0.0.0.0-18080-1 [TimerImpl] commit: [id=3,target=[target=jboss.j2ee:jndiName=cc/NotificationController,service=EJB],remaining=518469896,periode=604800000,started_in_tx]
2006-11-17 10:58:50,104 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: active
2006-11-17 10:58:50,104 DEBUG http-0.0.0.0-18080-1 [TimerImpl] commit: [id=4,target=[target=jboss.j2ee:jndiName=cc/NotificationController,service=EJB],remaining=838869896,periode=1209600000,started_in_tx]
2006-11-17 10:58:50,104 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: active
2006-11-17 10:58:50,166 DEBUG http-0.0.0.0-18080-1 [EJBTimerServiceImpl] createTimerService: org.jboss.ejb.txtimer.TimerServiceImpl at 9b5b2f
2006-11-17 10:58:50,166 INFO  http-0.0.0.0-18080-1 [TimerManager] [ com.teoco.cc.services.timer.TimerManager.initializeTimers(TimerManager.java:92) ] ENTER
2006-11-17 10:58:50,166 INFO  http-0.0.0.0-18080-1 [TimerManager] [ com.teoco.cc.services.timer.TimerManager.initializeTimers(TimerManager.java:96) ] Found 0 timers in DB.
2006-11-17 10:58:50,166 INFO  http-0.0.0.0-18080-1 [TimerManager] [ com.teoco.cc.services.timer.TimerManager.initializeTimers(TimerManager.java:97) ] Found 1 timers in config.
2006-11-17 10:58:50,182 INFO  http-0.0.0.0-18080-1 [TimerManager] [ com.teoco.cc.services.timer.TimerManager.initializeTimers(TimerManager.java:172) ] Creating timer: Name: CorrespondenceTimer, Period name: Minute, Period count: 1, Day of Week Name: null, Day of Week Int: 0, Hour of Day: 0, First Expiration Date: Fri Nov 17 10:59:50 EST 2006, Most Recent Expiration Date: None, Period (Minutes): 1
2006-11-17 10:58:50,182 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: created
2006-11-17 10:58:50,229 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: started_in_tx
2006-11-17 10:58:50,307 DEBUG http-0.0.0.0-18080-1 [TimerImpl] commit: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=59844,periode=60000,started_in_tx]
2006-11-17 10:58:50,307 DEBUG http-0.0.0.0-18080-1 [TimerImpl] setTimerState: active
2006-11-17 10:59:50,152 DEBUG Timer-7 [TimerImpl] run: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=-1,periode=60000,active]
2006-11-17 10:59:50,152 DEBUG Timer-7 [TimerImpl] setTimerState: in_timeout
2006-11-17 10:59:51,808 DEBUG Timer-7 [TimerImpl] commit: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=58343,periode=60000,in_timeout]
2006-11-17 10:59:51,808 DEBUG Timer-7 [TimerImpl] setTimerState: active
2006-11-17 11:00:50,152 DEBUG Timer-7 [TimerImpl] run: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=-1,periode=60000,active]
2006-11-17 11:00:50,152 DEBUG Timer-7 [TimerImpl] setTimerState: in_timeout
2006-11-17 11:00:50,965 DEBUG Timer-7 [TimerImpl] commit: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=59186,periode=60000,in_timeout]
2006-11-17 11:00:50,965 DEBUG Timer-7 [TimerImpl] setTimerState: active
2006-11-17 11:01:50,153 DEBUG Timer-7 [TimerImpl] run: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=-2,periode=60000,active]
2006-11-17 11:01:50,153 DEBUG Timer-7 [TimerImpl] setTimerState: in_timeout
2006-11-17 11:01:51,325 DEBUG Timer-7 [TimerImpl] commit: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=58826,periode=60000,in_timeout]
2006-11-17 11:01:51,325 DEBUG Timer-7 [TimerImpl] setTimerState: active
2006-11-17 11:02:50,154 DEBUG Timer-7 [TimerImpl] run: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=-3,periode=60000,active]
2006-11-17 11:02:50,154 DEBUG Timer-7 [TimerImpl] setTimerState: in_timeout
2006-11-17 11:02:50,966 DEBUG Timer-7 [TimerImpl] commit: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=59185,periode=60000,in_timeout]
2006-11-17 11:02:50,966 DEBUG Timer-7 [TimerImpl] setTimerState: active
2006-11-17 11:03:50,155 DEBUG Timer-7 [TimerImpl] run: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=-4,periode=60000,active]
2006-11-17 11:03:50,155 DEBUG Timer-7 [TimerImpl] setTimerState: in_timeout
2006-11-17 11:03:51,326 DEBUG Timer-7 [TimerImpl] commit: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=58825,periode=60000,in_timeout]
2006-11-17 11:03:51,326 DEBUG Timer-7 [TimerImpl] setTimerState: active
2006-11-17 11:04:50,155 DEBUG Timer-7 [TimerImpl] run: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=-4,periode=60000,active]
2006-11-17 11:04:50,155 DEBUG Timer-7 [TimerImpl] setTimerState: in_timeout
2006-11-17 11:04:51,171 DEBUG Timer-7 [TimerImpl] commit: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=58980,periode=60000,in_timeout]
2006-11-17 11:04:51,171 DEBUG Timer-7 [TimerImpl] setTimerState: active
2006-11-17 11:05:50,156 DEBUG Timer-7 [TimerImpl] run: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=-5,periode=60000,active]
2006-11-17 11:05:50,156 DEBUG Timer-7 [TimerImpl] setTimerState: in_timeout
2006-11-17 11:05:51,016 DEBUG Timer-7 [TimerImpl] commit: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=59135,periode=60000,in_timeout]
2006-11-17 11:05:51,016 DEBUG Timer-7 [TimerImpl] setTimerState: active
2006-11-17 11:06:50,157 DEBUG Timer-7 [TimerImpl] run: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=-6,periode=60000,active]
2006-11-17 11:06:50,157 DEBUG Timer-7 [TimerImpl] setTimerState: in_timeout
2006-11-17 11:06:51,157 DEBUG Timer-7 [TimerImpl] commit: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=58994,periode=60000,in_timeout]
2006-11-17 11:06:51,157 DEBUG Timer-7 [TimerImpl] setTimerState: active
2006-11-17 11:07:50,158 DEBUG Timer-7 [TimerImpl] run: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=-7,periode=60000,active]
2006-11-17 11:07:50,158 DEBUG Timer-7 [TimerImpl] setTimerState: in_timeout
2006-11-17 11:07:51,314 DEBUG Timer-7 [TimerImpl] commit: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=58837,periode=60000,in_timeout]
2006-11-17 11:07:51,314 DEBUG Timer-7 [TimerImpl] setTimerState: active
2006-11-17 11:08:50,158 DEBUG Timer-7 [TimerImpl] run: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=-7,periode=60000,active]
2006-11-17 11:08:50,158 DEBUG Timer-7 [TimerImpl] setTimerState: in_timeout
2006-11-17 11:08:51,158 DEBUG Timer-7 [TimerImpl] commit: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=58993,periode=60000,in_timeout]
2006-11-17 11:08:51,158 DEBUG Timer-7 [TimerImpl] setTimerState: active
2006-11-17 11:09:50,456 DEBUG Timer-7 [TimerImpl] run: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=-305,periode=60000,active]
2006-11-17 11:09:50,456 DEBUG Timer-7 [TimerImpl] setTimerState: in_timeout
2006-11-17 11:09:51,722 DEBUG Timer-7 [TimerImpl] commit: [id=5,target=[target=jboss.j2ee:jndiName=cc/ClaimCorrespondenceController,service=EJB],remaining=58429,periode=60000,in_timeout]
2006-11-17 11:09:51,722 DEBUG Timer-7 [TimerImpl] setTimerState: active

View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=3986971#3986971

Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=3986971