tcl script fails to run (%HA-HA_EM-6-FMS_POLICY_TIMEOUT)

[vangelischr]

Hello,

Im facing the below issue with event manager and script execution. 

RP/0/RSP0/CPU0:Dec 1 14:32:43.051 UTC: eem_server[262]: %HA-HA_EM-6-FMS_POLICY_TIMEOUT : Policy 'LINK_DOWN_20249725.tcl' has hit its maximum execution time of 80.000000000 seconds, and so has been halted

Im using the event manager in order to shutdown a subinterface when a track is down. The script is working properly working on a cisco ASR-9001 Version 6.7.1 whilst is not working on a Cisco ASR-9901 (asr9k-x64) Version 7.0.2. Please find below the script and the router configuration:

Router config:

event manager environment _syslog_pattern .*(syslog reading)
event manager directory user policy disk0:scripts
no event manager policy LINK_UP_.tcl username eem persist-time 3600
no event manager policy LINK_DOWN_.tcl username eem persist-time 3600

aaa authorization eventmanager default local

username eem
 group root-system (group root-lr on ASR-9901)
 group cisco-support

Scripts Attached

[tkarnani]

Here is an example of a script that searches the logs for a match.

you can use this as a template. it was created by one of our TAC engineers @vyashin 

This TCL script should be scheduled for execution on IOS XR router.
It will automatically collect a few "show" commands outputs and save them into
a text file for offline analysis.

The script is triggered by a syslog message matching the following expression:
LINK-3-UPDOWN.*TenGigE0/1/0/0.*Down

Outputs being collected by the script:
terminal length 0
admin show install active summary
admin show platform
admin show inventory
dir harddisk:/dumper
sh proc cpu loc 0/0/cpu0 | ex "   0%   "
show run
show log

Here is how to install the script:

- Check whether you already have a script directory to store the event
manager scripts:

dir harddisk:/scripts location 0/RSP0/CPU0
dir harddisk:/scripts location 0/RSP1/CPU0

If the directories do not exist, create them:

mkdir harddisk:/scripts location 0/RSP0/CPU0
mkdir harddisk:/scripts location 0/RSP1/CPU0

- Copy the script from your tftp or ftp server into this directory (or the one which was already configured) on
each RSP:

copy tftp://server/path/script.tcl harddisk:/scripts location 0/RSP0/CPU0
copy tftp://server/path/script.tcl harddisk:/scripts location 0/RSP1/CPU0

- Verify that the script directory is already configured:

show run | i event manager directory

If it's not configured yet:

config t
event manager directory user policy harddisk:/scripts
commit
end

- Set all environment variables (if any are used by the script and instructed by Cisco)

conf t
event manager environment _cron_entry 0-59/2 0-23/1 * * 0-7
commit
end

- Configure authentication for EEM

config t

username event_manager_user
  group root-system
  group cisco-support

aaa authorization eventmanager default local
aaa authorization commands eem-method none

vty-pool eem 100 105 line-template eem-template

line template eem-template
  authorization commands eem-method
  !
commit

- Enable the script:

conf t
event manager policy script.tcl username event_manager_user
commit

- Once the scripts are enabled, you should monitor your syslog for strings like:

RP/0/RSP0/CPU0:Dec 15 10:01:25.863 : tclsh[65894]: %HA-HA_EEM-6-ACTION_SYSLOG_LOG_INFO : script.tcl: EEM script was triggered 
RP/0/RSP0/CPU0:Dec 15 10:01:26.984 : tclsh[65894]: %HA-HA_EEM-6-ACTION_SYSLOG_LOG_INFO : script.tcl: Opened /harddisk:/script-log-2014121526.txt 
RP/0/RSP0/CPU0:Dec 15 10:01:26.985 : tclsh[65894]: %HA-HA_EEM-6-ACTION_SYSLOG_LOG_INFO : script.tcl: Executing: terminal length 0 
RP/0/RSP0/CPU0:Dec 15 10:01:27.551 : tclsh[65894]: %HA-HA_EEM-6-ACTION_SYSLOG_LOG_INFO : script.tcl: Executing: admin show install active summary 
RP/0/RSP0/CPU0:Dec 15 10:01:31.560 : tclsh[65894]: %HA-HA_EEM-6-ACTION_SYSLOG_LOG_INFO : script.tcl: Executing: admin show platform 
RP/0/RSP0/CPU0:Dec 15 10:01:32.091 : tclsh[65894]: %HA-HA_EEM-6-ACTION_SYSLOG_LOG_INFO : script.tcl: Executing: admin show inventory 
RP/0/RSP0/CPU0:Dec 15 10:01:34.838 : tclsh[65894]: %HA-HA_EEM-6-ACTION_SYSLOG_LOG_INFO : script.tcl: Executing: dir harddisk:/dumper 
RP/0/RSP0/CPU0:Dec 15 10:01:35.239 : tclsh[65894]: %HA-HA_EEM-6-ACTION_SYSLOG_LOG_INFO : script.tcl: Executing: show run 
RP/0/RSP0/CPU0:Dec 15 10:01:37.343 : tclsh[65894]: %HA-HA_EEM-6-ACTION_SYSLOG_LOG_INFO : script.tcl: Executing: show log 
RP/0/RSP0/CPU0:Dec 15 10:03:52.053 : tclsh[65894]: %HA-HA_EEM-6-ACTION_SYSLOG_LOG_INFO : script.tcl: File closed, script execution has finished.

The script should be shown as registered in the system with corresponding trigger:

RP/0/RSP0/CPU0:kasos#show event manager policy registered 
Mon Dec 15 10:10:05.828 UTC
No.  Class     Type    Event Type          Trap  Time Registered           Name
1    script    user    syslog              Off   Mon Dec 15 10:01:22 2014  script.tcl
 pattern {%MGBL-CONFIG-6-DB_COMMIT}
 nice 0 queue-priority normal maxrun 600.000 scheduler rp_primary Secu none
 persist_time: 3600 seconds,  username: event_manager_user

- Each time the script is called, there will be a new debug file under the harddisk:

RP/0/RSP0/CPU0:lan-9000-2#dir harddisk: | i script-log
179299      -rw-  38220       Tue Jan 10 18:12:22 2012  script-log-2012011022.txt
179300      -rw-  38221       Tue Jan 10 18:15:56 2012  script-log-2012011056.txt
179301      -rw-  39178       Tue Jan 10 18:23:20 2012  script-log-2012011020.txt
RP/0/RSP0/CPU0:lan-9000-2#

- Please refer to a configuration guide for EEM if you need more information:
http://www.cisco.com/c/en/us/td/docs/routers/asr9000/software/asr9k_r5-2/system_monitoring/configuration/guide/b_sysmon_cg52xasr9k/b_sysmon_cg52xasr9k_chapter_011.html

==== File script.tcl: ====

::cisco::eem::event_register_syslog pattern "LINK-3-UPDOWN.*TenGigE0/1/0/0.*Down" maxrun_sec 600

namespace import ::cisco::eem::*
namespace import ::cisco::lib::*

set commands [ list \
"terminal length 0" \
"admin show install active summary" \
"admin show platform" \
"admin show inventory" \
"dir harddisk:/dumper" \
"sh proc cpu loc 0/0/cpu0 | ex \"   0%   \"" \
"show run" \
"show log" \
 ]

# Script body
# tkarnani@cisco.com

#
# errorInf gets set by namespace if any of the auto_path directories do not
# contain a valid tclIndex file.  It is not an error just left over stuff.
# So we set the errorInfo value to null so that we don't have left
# over errors in it.
#
set errorInfo ""

action_syslog priority info msg "EEM script was triggered"

# Open CLI
#
if [catch {cli_open} result] {
    error $result $errorInfo
} else {
    array set cli $result
}

#Run cmds

set tdate [clock format [clock seconds] -format %Y%m%d%H%M%S]
set filename  [format "/harddisk:/script-log-%s.txt" $tdate]
set outfile [open $filename w]
action_syslog priority info msg "Opened $filename"

foreach cmd $commands {
    action_syslog priority info msg "Executing: $cmd"
    puts $outfile "
+===============================================+
"
    puts $outfile [ cli_exec $cli(fd) $cmd ]
}

# Close the CLI connection
cli_close $cli(fd) $cli(tty_id)
close $outfile

action_syslog priority info msg "File closed, script execution has finished."

[vangelischr]

Hi @tkarnani ,

Thanks for your reply. As i mentioned i have successfully tested the script on an ASR-9001 Version 6.7.1. The issue is appearing on the Cisco ASR-9901 (asr9k-x64) Version 7.0.2 which is newer version and 64 bit architecture. Also note that there is no option for group root-system but group root-lr on ASR-9901. After some tests i noticed that the script stops at the commit command. Seems that the event manager is somehow has no permissions to execute the commit command. Also after some reading of the event manager logs i also found the below error:

eem/pd/evt 0/RSP0/CPU0 t30233 jobid:95769, fh_c_main_iox.c-610, Got reply for msg:, FH_MSG_EVENT_REGISTER_CHKPT, 'Embedded Event Manager' detected the 'fatal' condition 'could not find key' (err:-1345057280)