@Schedule does not consider timing declaration

[hanseichelpilz]

Hi,

i'm currently creating a timing application that makes use of the @Schedule annotation.

I created a singleton bean as followed:

@Singleton
@Startup
@ConcurrencyManagement( ConcurrencyManagementType.BEAN )
public class MailSender {

    @Inject
    Logger log;

    @Schedule( minute = "*" )
    public void sendUnsentMails() {
        log.info( "tick tick tick" );
    }

}

I would assume that the method is executed every minute, but instead it runs, .. well, more often (see log dump)

15:01:15,038 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-1) tick tick tick
15:01:16,038 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-10) tick tick tick
15:01:17,037 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-2) tick tick tick
15:01:18,036 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-7) tick tick tick
15:01:19,044 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-9) tick tick tick
15:01:20,037 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-6) tick tick tick
15:01:20,070 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-5) tick tick tick
15:01:21,045 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-3) tick tick tick
15:01:22,044 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-4) tick tick tick
15:01:23,044 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-8) tick tick tick
15:01:24,052 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-1) tick tick tick
15:01:25,034 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-10) tick tick tick
15:01:26,034 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-2) tick tick tick
15:01:27,033 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-7) tick tick tick
15:01:28,033 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-9) tick tick tick
15:01:29,032 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-6) tick tick tick
15:01:30,040 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-3) tick tick tick
15:01:30,091 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-5) tick tick tick

The singleton is deployed inside an ejb->ear and runs on JBoss AS 7.1.0.Alpha2-SNAPSHOT "Ahoy!"

If i undeploy the ear, the JBoss keeps writing these logstatements in an infinite loop:

15:04:52,034 INFO  [org.jboss.as.ejb3.timerservice.mk2.task.TimerTask] (pool-4-thread-9) Timer: [id=1f36f92d-316f-4c41-ade4-d08a6c38315d timedObjectId=MailSender auto-timer?:true persistent?:true timerService=org.jboss.as.ejb3.timerservice.mk2.TimerServiceImpl@1a46a171 initialExpiration=Wed Oct 26 00:00:00 CEST 2011 intervalDuration(in milli sec)=0 nextExpiration=Wed Oct 26 15:04:53 CEST 2011 timerState=IN_TIMEOUT will be retried
15:04:52,035 INFO  [org.jboss.as.ejb3.timerservice.mk2.task.TimerTask] (pool-4-thread-9) Retrying timeout for timer: [id=1f36f92d-316f-4c41-ade4-d08a6c38315d timedObjectId=MailSender auto-timer?:true persistent?:true timerService=org.jboss.as.ejb3.timerservice.mk2.TimerServiceImpl@1a46a171 initialExpiration=Wed Oct 26 00:00:00 CEST 2011 intervalDuration(in milli sec)=0 nextExpiration=Wed Oct 26 15:04:53 CEST 2011 timerState=IN_TIMEOUT
15:04:52,066 ERROR [org.jboss.as.ejb3.timerservice.mk2.task.TimerTask] (pool-4-thread-9) Error during retyring timeout for timer: [id=1f36f92d-316f-4c41-ade4-d08a6c38315d timedObjectId=MailSender auto-timer?:true persistent?:true timerService=org.jboss.as.ejb3.timerservice.mk2.TimerServiceImpl@1a46a171 initialExpiration=Wed Oct 26 00:00:00 CEST 2011 intervalDuration(in milli sec)=0 nextExpiration=Wed Oct 26 15:04:53 CEST 2011 timerState=RETRY_TIMEOUT: java.lang.IllegalStateException: Component is stopped
 at org.jboss.as.ee.component.BasicComponent.waitForComponentStart(BasicComponent.java:98) [jboss-as-ee-7.1.0.Alpha2-SNAPSHOT.jar:7.1.0.Alpha2-SNAPSHOT]
 at org.jboss.as.ee.component.BasicComponent.createInstance(BasicComponent.java:77) [jboss-as-ee-7.1.0.Alpha2-SNAPSHOT.jar:7.1.0.Alpha2-SNAPSHOT]
 at org.jboss.as.ejb3.component.singleton.SingletonComponent.getComponentInstance(SingletonComponent.java:127) [jboss-as-ejb3-7.1.0.Alpha2-SNAPSHOT.jar:7.1.0.Alpha2-SNAPSHOT]
 at org.jboss.as.ejb3.timerservice.SingletonTimedObjectInvokerImpl.callTimeout(SingletonTimedObjectInvokerImpl.java:46) [jboss-as-ejb3-7.1.0.Alpha2-SNAPSHOT.jar:7.1.0.Alpha2-SNAPSHOT]
 at org.jboss.as.ejb3.timerservice.mk2.task.CalendarTimerTask.callTimeout(CalendarTimerTask.java:73) [jboss-as-ejb3-7.1.0.Alpha2-SNAPSHOT.jar:7.1.0.Alpha2-SNAPSHOT]
 at org.jboss.as.ejb3.timerservice.mk2.task.TimerTask.run(TimerTask.java:119) [jboss-as-ejb3-7.1.0.Alpha2-SNAPSHOT.jar:7.1.0.Alpha2-SNAPSHOT]
 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) [:1.6.0_26]
 at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) [:1.6.0_26]
 at java.util.concurrent.FutureTask.run(FutureTask.java:138) [:1.6.0_26]
 at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [:1.6.0_26]
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [:1.6.0_26]
 at java.lang.Thread.run(Thread.java:662) [:1.6.0_26]
 at org.jboss.threads.JBossThread.run(JBossThread.java:122) [jboss-threads-2.0.0.GA.jar:2.0.0.GA]

I don't know if these two issues are related or not. Anyone an idea?

[jaikiran]

Martin Heinemann wrote:

 
    @Schedule( minute = "*" )
    public void sendUnsentMails() {
        log.info( "tick tick tick" );
    }
 
}
 

I would assume that the method is executed every minute, but instead it runs, .. well, more often (see log dump)

Actually, that doesn't mean every minute. The hour, minute and second attributes by default are "0". So in your case, this expression means, run the timer every minute when the hour is 0 (midnight) and second is (0). So it's supposed to be triggred at mid-night and be triggered 60 times before re-triggering the mid night of next day.

But even then, I wouldn't expect the output that you are seeing. Are you sure it's picking the right bean/schedule?

[dev0]

The following code will run every minute:

@Schedule(minute="*/1",hour="*", persistent=false)
public void doWork(){
     System.out.println("MyTimer: =========== DO WORK! ===========");
     LOGGER.info(">>>>> TIMERSERVICE= " + Calendar.getInstance().getTime());
}

And the output - after a few minutes:

15:04:00,010 INFO  [stdout] (pool-7-thread-1) MyTimer: =========== DO WORK! ===========
15:04:00,011 INFO  [com.company.MyTimer] (pool-7-thread-1) >>>>> TIMERSERVICE= Fri Oct 28 15:04:00 CEST 2011
15:05:00,004 INFO  [stdout] (pool-7-thread-1) MyTimer: =========== DO WORK! ===========
15:05:00,005 INFO  [com.company.MyTimer] (pool-7-thread-1) >>>>> TIMERSERVICE= Fri Oct 28 15:05:00 CEST 2011
15:06:00,004 INFO  [stdout] (pool-7-thread-1) MyTimer: =========== DO WORK! ===========
15:06:00,005 INFO  [com.company.MyTimer] (pool-7-thread-1) >>>>> TIMERSERVICE= Fri Oct 28 15:06:00 CEST 2011
15:07:00,004 INFO  [stdout] (pool-7-thread-1) MyTimer: =========== DO WORK! ===========
15:07:00,004 INFO  [com.company.MyTimer] (pool-7-thread-1) >>>>> TIMERSERVICE= Fri Oct 28 15:07:00 CEST 2011
15:08:00,004 INFO  [stdout] (pool-7-thread-1) MyTimer: =========== DO WORK! ===========
15:08:00,005 INFO  [com.company.MyTimer] (pool-7-thread-1) >>>>> TIMERSERVICE= Fri Oct 28 15:08:00 CEST 2011

[hanseichelpilz]

Hell yeah.

Must have been the "wrong" time format.

Is used

@Schedule( second = "*/5", minute = "*/1", hour = "*", persistent = false )

And now it runs every 5 seconds. And even with

@Schedule( second = "*/5", minute = "*", hour = "*", persistent = false )

Strange. Thanks alot!