EEM Cron timer triggering twice on the same event

Unanswered Question
Apr 14th, 2009
User Badges:

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

  • 1
  • 2
  • 3
  • 4
  • 5
Overall Rating: 0 (0 ratings)
Loading.
Joe Clarke Tue, 04/14/2009 - 10:16
User Badges:
  • Cisco Employee,
  • Hall of Fame,

    Founding Member

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
User Badges:

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 - 11:54
User Badges:
  • Cisco Employee,
  • Hall of Fame,

    Founding Member

Please post the full show run and show ver from this router.

Joe Clarke Tue, 04/14/2009 - 17:14
User Badges:
  • Cisco Employee,
  • Hall of Fame,

    Founding Member

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
User Badges:

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
User Badges:
  • Cisco Employee,
  • Hall of Fame,

    Founding Member

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