cancel
Showing results for 
Search instead for 
Did you mean: 
cancel
1500
Views
0
Helpful
7
Replies

EEM Cron timer triggering twice on the same event

hmaiwald
Level 1
Level 1

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

7 Replies 7

Joe Clarke
Cisco Employee
Cisco Employee

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.

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

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

Here you go.

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")?

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

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.

Getting Started

Find answers to your questions by entering keywords or phrases in the Search bar above. New here? Use these resources to familiarize yourself with the community: