EEM Cron timer triggering twice on the same event

Unanswered Question
Apr 14th, 2009

I am using 12.4(15)T7 on a Cisco 871. I have a timer based policy registered with the event manager:

3 script user timer cron Off Thu Feb 28 19:00:33 2002 tm_oobs

la.tcl

name {OOB SLA Timer} cron entry {0,5,10,15,20,25,30,35,40,45,50,55 * * * *}

nice 0 queue-priority normal maxrun 20.000

So this event is supposed to trigger every 5 minutes, which it does. The problem is it does it twice most of the time. Here is the event history:

22 Tue Apr14 13:50:00 2009 timer cron script: tm_oobsla.tcl

23 Tue Apr14 13:55:00 2009 timer cron script: tm_oobsla.tcl

24 Tue Apr14 13:55:59 2009 timer cron script: tm_oobsla.tcl

25 Tue Apr14 14:00:00 2009 timer cron script: tm_oobsla.tcl

As you can see the event triggered at 13:55:00 and then again at 13:55:59. Is there anything that can prevent that?

Thanks

-Heiko

I have this problem too.
0 votes
  • 1
  • 2
  • 3
  • 4
  • 5
Overall Rating: 0 (0 ratings)
Loading.
Joe Clarke Tue, 04/14/2009 - 10:16

This was reported once before. See:

http://forum.cisco.com/eforum/servlet/NetProf?page=netprof&forum=Network%20Infrastructure&topic=Network%20Management&topicID=.ee71a02&CommCmd=MB%3Fcmd%3Dpass_through%26location%3Doutline%40%5E1%40%40.2cc250de/7#selected_message

That user simply rebooted, and I had since upgraded off of 12.4(15)T. I still can't find a bug on this, but I believe one may exist. I would need to see the output from debug event manager detector timer when the problem is occurring.

hmaiwald Tue, 04/14/2009 - 10:43

Here is the debug output.

Apr 14 14:35:00: fh_fd_timer_process_async

Apr 14 14:35:00: cron_tick: subscriber(0)=0x85022FE8

Apr 14 14:35:00: cron_tick info publish: re=0x85022FE8 reg q_size=2

Apr 14 14:35:00: cron_tick: num_matches 1

Apr 14 14:35:00: fh_send_timer_fd_msg: msg_type=62

Apr 14 14:35:00: fh_send_timer_fd_msg: sval=0

Apr 14 14:35:01: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:35:01: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:35:02: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:35:02: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:35:02: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:35:03: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:35:03: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:35:04: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:35:04: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:35:04: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:35:05: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:35:59: fh_fd_timer_process_async

Apr 14 14:35:59: cron_tick: subscriber(0)=0x85022FE8

Apr 14 14:35:59: cron_tick info publish: re=0x85022FE8 reg q_size=2

Apr 14 14:35:59: cron_tick: num_matches 1

Apr 14 14:35:59: fh_send_timer_fd_msg: msg_type=62

Apr 14 14:35:59: fh_send_timer_fd_msg: sval=0

Apr 14 14:36:00: fh_fd_timer_process_async

Apr 14 14:36:00: cron_tick: num_matches 0

Apr 14 14:36:01: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:36:01: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:36:02: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:36:02: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:36:02: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:36:03: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:36:03: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:36:04: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:36:04: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:36:04: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 14 14:36:05: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Joe Clarke Tue, 04/14/2009 - 17:14

How often is the duplicate firing occurring? Can you correlate this to SNTP updates which move the clock backwards (e.g. with "debug sntp adjust")?

hmaiwald Wed, 04/15/2009 - 05:40

It happens about 7 times out of ten. Yes it seems to be related to sntp adjusting the clock.

Apr 15 09:35:00: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Apr 15 09:35:51: Delay calculated, offset FFFFFFFF.FB138A48

Apr 15 09:35:51: Clock slewed.

Apr 15 09:36:00: %PARSER-5-CFGLOG_LOGGEDCMD: User:unknown user logged command:!exec: enable

Joe Clarke Wed, 04/15/2009 - 12:08

I filed CSCsz12460 to track this. In the meantime, you can convert the cron timer to a watchdog timer which runs every 300 seconds. It won't necessarily run at the 00 second, but it will be guaranteed to only run one time per minute.

Actions

This Discussion