0 Replies Latest reply on Nov 17, 2006 2:30 PM by Vickj Fisherboss

    EJBTimerService persistent timers intermittently lost

    Vickj Fisherboss Newbie

      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@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@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