Buy or Renew
Buy or Renew
cancel
Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
Showing results for 
Search instead for 
Did you mean: 
cancel
Start a conversation
1388
Views
0
Helpful
1
Replies

EEM Correlate not working when run again.

vingrove
Cisco Employee
Cisco Employee

‎10-17-2016 06:13 PM

Hi,

I have written an EEM TCL script for MC-LAG spilt brain scenario on ASR9k, whereby one device should shut down its' MC-LAG bundle in the event link between two ASR9ks have failed, but it shouldn't shut it's MC-LAG bundle interfaces in the event remote Chassis has gone down due to some reason,

Logic:

1) Object tracking is on the bundle ether 20 between two ASR9ks -- This is tagged as event e1

2) Check for syslog message as Remote Dying Gasp in the event other ASR9k is getting rebooted. -- This is tagged as event e2

3) correlate both events, if only event e1 happens alone shut down the local bundle interface, but if it happens along with e2 then no action is performed.

Config on Box, relted to script


track 100
 type line-protocol state
  interface Bundle-Ether20
 !

event manager environment _syslog_pattern REMOTE_DYING_GASP
event manager directory user policy disk0:
event manager policy Splitbrain_dying_gasp_t.tcl username eem persist-time 3600 type user
aaa authorization eventmanager default local

RP/0/RP0/CPU0:S3CW-E-901#show event manager policy registered
Tue Oct 18 00:51:27.527 UTC
No.  Class     Type    Event Type          Trap  Time Registered           Name
1    script    user    multiple            Off   Tue Oct 18 00:51:07 2016  Splitbrain_dying_gasp.tcl
 e1: track: track 100 state down
 e2: syslog: pattern {REMOTE_DYING_GASP}
 trigger
  correlate event e1 andnot event e2
 nice 0 queue-priority normal maxrun 20.000 scheduler rp_primary Secu none
 persist_time: 3600 seconds,  username: eem

TCL Script:

::cisco::eem::event_register_track 100 tag e1 state down
::cisco::eem::event_register_syslog tag e2 pattern $_syslog_pattern
  

::cisco::eem::trigger {
    ::cisco::eem::correlate event e1 andnot event e2
} 

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

array set arr_einfo [event_reqinfo]


if [catch {cli_open} result] {
    error $result $errorInfo
} else {
    array set cli1 $result
}

if [catch {cli_exec $cli1(fd) "config t"} _cli_result] {
    error $_cli_result $errorInfo
}

if [catch {cli_exec $cli1(fd) "int bundle-ether 2601"} _cli_result] {
    error $_cli_result $errorInfo
}

if [catch {cli_exec $cli1(fd) "shut"} _cli_result] {
    error $_cli_result $errorInfo
}

if [catch {cli_exec $cli1(fd) "commit"} _cli_result] {
    error $_cli_result $errorInfo
}

}
action_syslog msg "Split-Brain occurred, shut bundle interfaces"

# Close open cli before exit.
catch {cli_close $cli1(fd) $cli1(tty_id)} result

Problem:

1) First I pulled out both the fibers between ASR9k which triggered event e1 only , whereby bundle ether 20 line protocol goes down, script does its' job and shuts' down the specified bundle interface in the script.

2) Then I rebooted the other chassis, which triggered both event e1 and e2 together and script did not run as expected.

3) Then I re-run first scenario again, pulled out both the fibers between ASR9k to trigger event e1 only, but script did not shut the interfaces this time.

4) Once after syslog event has been recorded, not matter what I do like clear logs or events, script never functions again for the scenario 1.

Here are the logs recorded for all the three scenarios:

Scenario1 :    Pull out the links between two ASR9ks, script functions well. Please note the bold text

RP/0/RP0/CPU0:Oct 17 05:31:10.789 UTC: object_tracking[367]: %SERVICES-OT-6-TRACK_INFO : track 100 state Track_Down

RP/0/RP0/CPU0:Oct 17 05:31:10.798 UTC: eem_ed_generic[195]: FH_GENERIC_MSG_PUBLISH_EVENT recieved from OBJECT_TRACKING  
RP/0/RP0/CPU0:Oct 17 05:31:10.798 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:31:10.798 UTC: eem_ed_generic[195]: de-bulk event#1 of 1  event-id:372 spec-id:56
RP/0/RP0/CPU0:Oct 17 05:31:10.798 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:31:10.798 UTC: eem_ed_generic[195]: calling PAL publish bulk_len 0 event_keylen 44 event_datalen 36 len 474 space_left 2022  
RP/0/RP0/CPU0:Oct 17 05:31:10.799 UTC: eem_ed_generic[195]: fh_fd_msg_send_event: sending publish data:0:0
RP/0/RP0/CPU0:Oct 17 05:31:10.799 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:31:10.799 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:31:10.799 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:31:10.799 UTC: eem_server[207]: received async FH_MSG_EVENT_PUBLISH fdid:7
RP/0/RP0/CPU0:Oct 17 05:31:10.800 UTC: eem_server[207]: EEM: server processes multi events: esid=56
RP/0/RP0/CPU0:Oct 17 05:31:10.800 UTC: eem_server[207]: fms_chkpt_tbl_add: add chkpt obj 0x40002bf8 from table 0x40001100successful
RP/0/RP0/CPU0:Oct 17 05:31:10.800 UTC: eem_server[207]: EEM: server processes multi events: timewin=1, sync_flag=0, ec_index=0, cmp_occ=1
RP/0/RP0/CPU0:Oct 17 05:31:10.800 UTC: eem_server[207]: EEM: server processes multi events: get correlate result esid=56
RP/0/RP0/CPU0:Oct 17 05:31:10.800 UTC: eem_server[207]: EEM: ctx=24:(56,1,1)(57,0,0)
RP/0/RP0/CPU0:Oct 17 05:31:10.800 UTC: eem_server[207]: EEM: server processes multi events: corr_res=1, cur_tcnt=1, cmp_tcnt=1
RP/0/RP0/CPU0:Oct 17 05:31:10.800 UTC: eem_server[207]: fms_chkpt_tbl_add: add chkpt obj 0x40002bb8 from table 0x40004d00successful
RP/0/RP0/CPU0:Oct 17 05:31:10.801 UTC: eem_server[207]: fms_chkpt_tbl_add: add chkpt obj 0x40002b78 from table 0x40004e00successful
RP/0/RP0/CPU0:Oct 17 05:31:10.801 UTC: eem_server[207]: EEM: server processes multi events: schedule an event esid=56, corr_id=38, grpid=24
RP/0/RP0/CPU0:Oct 17 05:31:10.801 UTC: eem_server[207]: fms_chkpt_tbl_add: add chkpt obj 0x40002a18 from table 0x40001a00successful
RP/0/RP0/CPU0:Oct 17 05:31:10.801 UTC: eem_server[207]: fh_schedule_policy: prev_epc=0x0; epc=0x12222124
RP/0/RP0/CPU0:Oct 17 05:31:10.801 UTC: eem_server[207]: EEM server schedules scripts
RP/0/RP0/CPU0:Oct 17 05:31:10.801 UTC: eem_server[207]: fh_assign_scheduler_thread: cls: default in_use: 0 num: 1
RP/0/RP0/CPU0:Oct 17 05:31:10.801 UTC: eem_server[207]: EEM server schedules one event: policy_type=script epc=0x12222124.
RP/0/RP0/CPU0:Oct 17 05:31:10.801 UTC: eem_server[207]: starting ratelimit timer: sec=0, msec=0
RP/0/RP0/CPU0:Oct 17 05:31:10.801 UTC: eem_server[207]: EEM: server schedules a policy:0 policyname=/dev/rdsfs/etc/eem_rdsfs/Splitbrain_dying_gasp.tcl
RP/0/RP0/CPU0:Oct 17 05:31:10.802 UTC: eem_server[207]: spawn script /dev/rdsfs/etc/eem_rdsfs/Splitbrain_dying_gasp.tcl
RP/0/RP0/CPU0:Oct 17 05:31:10.811 UTC: eem_server[207]: EEM policy Splitbrain_dying_gasp.tcl has been scheduled to run
RP/0/RP0/CPU0:Oct 17 05:31:10.811 UTC: eem_server[207]: spawn program /pkg/bin/tclsh
RP/0/RP0/CPU0:Oct 17 05:31:10.811 UTC: eem_server[207]: arg[0] = /pkg/bin/tclsh
RP/0/RP0/CPU0:Oct 17 05:31:10.812 UTC: eem_server[207]: arg[1] = -FMRUN
RP/0/RP0/CPU0:Oct 17 05:31:10.812 UTC: eem_server[207]: arg[2] = -FMSAFE
RP/0/RP0/CPU0:Oct 17 05:31:10.812 UTC: eem_server[207]: arg[3] = /lib/tcl/base.tcl
RP/0/RP0/CPU0:Oct 17 05:31:10.812 UTC: eem_server[207]: arg[4] = /dev/rdsfs/etc/eem_rdsfs/Splitbrain_dying_gasp.tcl
RP/0/RP0/CPU0:Oct 17 05:31:10.812 UTC: eem_server[207]: no env specified
RP/0/RP0/CPU0:Oct 17 05:31:10.812 UTC: eem_server[207]: spawn on priority 10
RP/0/RP0/CPU0:Oct 17 05:31:10.812 UTC: eem_server[207]: progname /pkg/bin/tclsh vname N/A
RP/0/RP0/CPU0:Oct 17 05:31:10.815 UTC: eem_server[207]: pid for spawned process is 13672841. fdid: 7 sn: 0 jobid: 15
RP/0/RP0/CPU0:Oct 17 05:31:10.815 UTC: eem_server[207]: spawned process: pid:13672841, num_forkproc:1
RP/0/RP0/CPU0:Oct 17 05:31:10.816 UTC: eem_server[207]: Started timer for maxrun msec value 20000

RP/0/RP0/CPU0:Oct 17 05:31:11.959 UTC: eem_server[207]: received FH_MSG_API_INIT; jobid=65929, processid=13672841, threadid=0, client=93, job name=pkg/bin/tclsh
RP/0/RP0/CPU0:Oct 17 05:31:11.959 UTC: eem_server[207]: fms_chkpt_tbl_add: add chkpt obj 0x40002bf8 from table 0x40001e00successful
RP/0/RP0/CPU0:Oct 17 05:31:11.960 UTC: eem_server[207]: received msg FH_MSG_EVENT_REGISTER_CHKPT from client 93 (process:pkg/bin/tclsh) (pid/eph 13672841/65652)
RP/0/RP0/CPU0:Oct 17 05:31:11.961 UTC: eem_server[207]: received msg FH_MSG_APPL_PUBLISH_CHKPT from client 93 (process:pkg/bin/tclsh) (pid/eph 13672841/65652)
RP/0/RP0/CPU0:Oct 17 05:31:11.983 UTC: eem_server[207]: received msg FH_MSG_EVENT_REQINFO from client 93 (process:pkg/bin/tclsh) (pid/eph 13672841/65652)
RP/0/RP0/CPU0:Oct 17 05:31:11.988 UTC: eem_policy_dir[206]: fh_edm_get_fn: Invoked for item_name policy/Splitbrain_dying_gasp.tcl. vec_entries-> total: 4, valid 4
RP/0/RP0/CPU0:Oct 17 05:31:11.988 UTC: eem_policy_dir[206]: fh_edm_get_fn: Sending username eem for policy Splitbrain_dying_gasp.tcl
RP/0/RP0/CPU0:Oct 17 05:31:11.990 UTC: eem_policy_dir[206]: fh_edm_set_fn called with item_name user/Splitbrain_dying_gasp.tcl/eem pid value 13672841
RP/0/RP0/CPU0:Oct 17 05:31:11.990 UTC: eem_policy_dir[206]: Updated pid field (13672841) for policy Splitbrain_dying_gasp.tcl, user eem
RP/0/RP0/CPU0:Oct 17 05:31:14.345 UTC: BM-DISTRIB[1184]: %PKT_INFRA-ERRDIS-6-ERROR_DISABLE : TenGigE0/0/0/3/0: Error disabling due to reason: bundle-down
RP/0/RP0/CPU0:Oct 17 05:31:14.345 UTC: eem_ed_syslog[201]: syslog_scan: failed
LC/0/0/CPU0:Oct 17 05:31:14.347 UTC: ifmgr[209]: %PKT_INFRA-LINK-3-UPDOWN : Interface TenGigE0/0/0/3/0, changed state to Error Disabled
RP/0/RP0/CPU0:Oct 17 05:31:14.349 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:31:14.645 UTC: config[65933]: %MGBL-CONFIG-6-DB_COMMIT : Configuration committed by user 'eem'. Use 'show configuration commit changes 1000000514' to view the changes.
RP/0/RP0/CPU0:Oct 17 05:31:14.647 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:31:14.725 UTC: eem_server[207]: received msg FH_MSG_API_CLOSE from client 93 (process:pkg/bin/tclsh) (pid/eph 13672841/65652)
RP/0/RP0/CPU0:Oct 17 05:31:14.726 UTC: eem_server[207]: received FH_MSG_API_CLOSE client=93 pid:13672841 eph:65652
RP/0/RP0/CPU0:Oct 17 05:31:14.726 UTC: eem_server[207]: pid:13672841 free_client:pkg/bin/tclsh eph:65652
RP/0/RP0/CPU0:Oct 17 05:31:14.726 UTC: eem_server[207]: fms_chkpt_tbl_remove: delete chkpt obj 0x40002bf8 from table 0x40001e00successful
RP/0/RP0/CPU0:Oct 17 05:31:14.727 UTC: eem_server[207]: received XOS_IPC_CLIENT_DISCONNECTED, eph=65652
RP/0/RP0/CPU0:Oct 17 05:31:14.727 UTC: eem_server[207]: fh_eph_down_client Enter
RP/0/RP0/CPU0:Oct 17 05:31:15.755 UTC: eem_server[207]: received SIGCHLD pulse from child death pid=13672841
RP/0/RP0/CPU0:Oct 17 05:31:15.755 UTC: eem_server[207]: received pulse from child death code=2; si_code=1; si_status=1; epc=0x12222124
RP/0/RP0/CPU0:Oct 17 05:31:15.755 UTC: eem_server[207]: EEM policy Splitbrain_dying_gasp.tcl pid 13672841 has completed with abnormal exit status of 0x1 exec_status=2 event_completion=0
RP/0/RP0/CPU0:Oct 17 05:31:15.755 UTC: eem_server[207]: fms_chkpt_tbl_remove: delete chkpt obj 0x40002bd8 from table 0x40001200successful
RP/0/RP0/CPU0:Oct 17 05:31:15.755 UTC: eem_server[207]: EEM: server decrements in use thread: jobid=15 rule id=1 in use thread=0.
RP/0/RP0/CPU0:Oct 17 05:31:15.755 UTC: eem_server[207]: fh_schedule_policy: prev_epc=0x12222124; epc=0x0
RP/0/RP0/CPU0:Oct 17 05:31:15.755 UTC: eem_server[207]: EEM server schedules scripts
RP/0/RP0/CPU0:Oct 17 05:31:15.756 UTC: eem_server[207]: EEM server schedules sync same source events:fdid=7; sn=0.
RP/0/RP0/CPU0:Oct 17 05:31:15.756 UTC: eem_server[207]: fms_chkpt_tbl_remove: delete chkpt obj 0x40002a18 from table 0x40001a00successful
RP/0/RP0/CPU0:Oct 17 05:31:15.756 UTC: eem_server[207]: fms_chkpt_tbl_remove: delete chkpt obj 0x40002bb8 from table 0x40004d00successful
RP/0/RP0/CPU0:Oct 17 05:31:15.756 UTC: eem_server[207]: fms_chkpt_tbl_remove: delete chkpt obj 0x40002b78 from table 0x40004e00successful
RP/0/RP0/CPU0:Oct 17 05:31:15.756 UTC: eem_server[207]: fh_process_exit_hndlr:dead process pid:13672841, num_forkproc:0

Scenario2: Power off other chassis to trigger both event e1 and e2 together. Again note text in bold

RP/0/RP0/CPU0:Oct 17 05:37:50.263 UTC: eem_ed_syslog[201]: syslog_pubinfo_enqueue: matched pattern="REMOTE_DYING_GASP", matched message="LC/0/0/CPU0:Oct 17 2016 UTC 05:37:50.261 :ethernet_link_oam_daemon[172]: %L2-ELO-6-INTF_REMOTE_DYING_GASP : HundredGigE0/0/0/0: Remote dying gasp detected, with reason: Error-Disable "

RP/0/RP0/CPU0:Oct 17 05:37:50.263 UTC: eem_server[207]: received async FH_MSG_EVENT_PUBLISH fdid:9
RP/0/RP0/CPU0:Oct 17 05:37:50.263 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.263 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.263 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.263 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.264 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.264 UTC: object_tracking[367]: %SERVICES-OT-6-TRACK_INFO : track 100 state Track_Down
RP/0/RP0/CPU0:Oct 17 05:37:50.264 UTC: ospf[1018]: %ROUTING-OSPF-5-ADJCHG : Process 3, Nbr 144.133.160.42 on Bundle-Ether20 in area 3.0.0.2 from FULL to DOWN, Neighbor Down: interface down or detached, vrf default vrfid 0x60000000
LC/0/1/CPU0:Oct 17 05:37:50.264 UTC: bfd_agent[125]: %L2-BFD-6-SESSION_STATE_DOWN : BFD session to neighbor 172.16.1.3 on interface HundredGigE0/1/0/0 has gone down. Reason: Nbor signalled down
RP/0/RP0/CPU0:Oct 17 05:37:50.265 UTC: eem_server[207]: EEM: server processes multi events: esid=57
RP/0/RP0/CPU0:Oct 17 05:37:50.265 UTC: eem_server[207]: fms_chkpt_tbl_add: add chkpt obj 0x40002b78 from table 0x40001100successful
LC/0/0/CPU0:Oct 17 05:37:50.266 UTC: bfd_agent[125]: %L2-BFD-6-SESSION_STATE_DOWN : BFD session to neighbor 172.16.1.3 on interface HundredGigE0/0/0/0 has gone down. Reason: Nbor signalled down
RP/0/RP0/CPU0:Oct 17 05:37:50.266 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.266 UTC: eem_server[207]: EEM: server processes multi events: timewin=1, sync_flag=0, ec_index=1, cmp_occ=1
RP/0/RP0/CPU0:Oct 17 05:37:50.266 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.266 UTC: eem_server[207]: EEM: server processes multi events: get correlate result esid=57
RP/0/RP0/CPU0:Oct 17 05:37:50.266 UTC: eem_server[207]: EEM: ctx=24:(56,0,0)(57,1,1)
RP/0/RP0/CPU0:Oct 17 05:37:50.266 UTC: eem_server[207]: received async FH_MSG_EVENT_PUBLISH fdid:9
RP/0/RP0/CPU0:Oct 17 05:37:50.266 UTC: eem_server[207]: EEM: server processes multi events: esid=57
RP/0/RP0/CPU0:Oct 17 05:37:50.266 UTC: eem_server[207]: fms_chkpt_tbl_add: add chkpt obj 0x40002bb8 from table 0x40001100successful
RP/0/RP0/CPU0:Oct 17 05:37:50.267 UTC: eem_server[207]: fms_chkpt_tbl_remove: delete chkpt obj 0x40002b78 from table 0x40001100successful
RP/0/RP0/CPU0:Oct 17 05:37:50.267 UTC: bfd[1185]: %L2-BFD-6-SESSION_STATE_DOWN : BFD session to neighbor 172.16.1.3 on interface Bundle-Ether20 has gone down. Reason: Admin down
RP/0/RP0/CPU0:Oct 17 05:37:50.267 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.267 UTC: eem_server[207]: EEM: server processes multi events: timewin=1, sync_flag=0, ec_index=1, cmp_occ=1
RP/0/RP0/CPU0:Oct 17 05:37:50.267 UTC: eem_server[207]: EEM: server processes multi events: get correlate result esid=57
RP/0/RP0/CPU0:Oct 17 05:37:50.267 UTC: eem_server[207]: EEM: ctx=24:(56,0,0)(57,1,1)
RP/0/RP0/CPU0:Oct 17 05:37:50.268 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.268 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.271 UTC: eem_ed_generic[195]: generic_recvr_ipc_cb:got IPC_NOTIFY_INPUT_WAITING - GED process conn 1 
RP/0/RP0/CPU0:Oct 17 05:37:50.271 UTC: eem_ed_generic[195]: FH_GENERIC_MSG_PUBLISH_EVENT recieved from OBJECT_TRACKING  
RP/0/RP0/CPU0:Oct 17 05:37:50.271 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.272 UTC: eem_ed_generic[195]: de-bulk event#1 of 1  event-id:372 spec-id:56
RP/0/RP0/CPU0:Oct 17 05:37:50.272 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.272 UTC: eem_ed_generic[195]: calling PAL publish bulk_len 0 event_keylen 44 event_datalen 36 len 474 space_left 2022  
RP/0/RP0/CPU0:Oct 17 05:37:50.272 UTC: eem_ed_generic[195]: fh_fd_msg_send_event: sending publish data:0:0
RP/0/RP0/CPU0:Oct 17 05:37:50.272 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.272 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.272 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.273 UTC: eem_server[207]: received async FH_MSG_EVENT_PUBLISH fdid:7
RP/0/RP0/CPU0:Oct 17 05:37:50.273 UTC: eem_server[207]: EEM: server processes multi events: esid=56
RP/0/RP0/CPU0:Oct 17 05:37:50.273 UTC: eem_server[207]: fms_chkpt_tbl_add: add chkpt obj 0x40002b78 from table 0x40001100successful
RP/0/RP0/CPU0:Oct 17 05:37:50.273 UTC: eem_server[207]: EEM: server processes multi events: timewin=1, sync_flag=0, ec_index=0, cmp_occ=1
RP/0/RP0/CPU0:Oct 17 05:37:50.273 UTC: eem_server[207]: EEM: server processes multi events: get correlate result esid=56
RP/0/RP0/CPU0:Oct 17 05:37:50.273 UTC: eem_server[207]: EEM: ctx=24:(56,1,1)(57,1,1)
LC/0/1/CPU0:Oct 17 05:37:50.296 UTC: ifmgr[209]: %PKT_INFRA-LINK-3-UPDOWN : Interface HundredGigE0/1/0/0, changed state to Down
RP/0/RP0/CPU0:Oct 17 05:37:50.296 UTC: eem_ed_syslog[201]: syslog_scan: failed
LC/0/1/CPU0:Oct 17 05:37:50.296 UTC: ifmgr[209]: %PKT_INFRA-LINEPROTO-5-UPDOWN : Line protocol on Interface HundredGigE0/1/0/0, changed state to Down
LC/0/1/CPU0:Oct 17 05:37:50.296 UTC: ethernet_link_oam_daemon[172]: %L2-ELO-6-INTF_SESSION_DOWN : HundredGigE0/1/0/0: OAM session has gone down
RP/0/RP0/CPU0:Oct 17 05:37:50.298 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:37:50.298 UTC: eem_ed_syslog[201]: syslog_scan: failed

Scenario1 Re-run :    Pull out the links between two ASR9ks, script did not run this time. Please note the bold text that's different from Scenario1 when ran first time.

RP/0/RP0/CPU0:Oct 17 05:43:45.541 UTC: object_tracking[367]: %SERVICES-OT-6-TRACK_INFO : track 100 state Track_Down
RP/0/RP0/CPU0:Oct 17 05:43:45.541 UTC: ospf[1018]: %ROUTING-OSPF-5-ADJCHG : Process 3, Nbr 144.133.160.42 on Bundle-Ether20 in area 3.0.0.2 from FULL to DOWN, Neighbor Down: interface down or detached, vrf default vrfid 0x60000000
RP/0/RP0/CPU0:Oct 17 05:43:45.542 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:43:45.542 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:43:45.544 UTC: bfd[1185]: %L2-BFD-6-SESSION_STATE_DOWN : BFD session to neighbor 172.16.1.3 on interface Bundle-Ether20 has gone down. Reason: None
RP/0/RP0/CPU0:Oct 17 05:43:45.544 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:43:45.549 UTC: eem_ed_generic[195]: generic_recvr_ipc_cb:got IPC_NOTIFY_INPUT_WAITING - GED process conn 1 
RP/0/RP0/CPU0:Oct 17 05:43:45.550 UTC: eem_ed_generic[195]: FH_GENERIC_MSG_PUBLISH_EVENT recieved from OBJECT_TRACKING  
RP/0/RP0/CPU0:Oct 17 05:43:45.550 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:43:45.550 UTC: eem_ed_generic[195]: de-bulk event#1 of 1  event-id:372 spec-id:56
RP/0/RP0/CPU0:Oct 17 05:43:45.550 UTC: eem_ed_generic[195]: calling PAL publish bulk_len 0 event_keylen 44 event_datalen 36 len 474 space_left 2022  
RP/0/RP0/CPU0:Oct 17 05:43:45.550 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:43:45.550 UTC: eem_ed_generic[195]: fh_fd_msg_send_event: sending publish data:0:0
RP/0/RP0/CPU0:Oct 17 05:43:45.551 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:43:45.551 UTC: eem_server[207]: received async FH_MSG_EVENT_PUBLISH fdid:7
RP/0/RP0/CPU0:Oct 17 05:43:45.551 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:43:45.551 UTC: eem_server[207]: EEM: server processes multi events: esid=56
RP/0/RP0/CPU0:Oct 17 05:43:45.551 UTC: eem_server[207]: fms_chkpt_tbl_add: add chkpt obj 0x40002a18 from table 0x40001100successful
RP/0/RP0/CPU0:Oct 17 05:43:45.552 UTC: eem_ed_syslog[201]: syslog_scan: failed
RP/0/RP0/CPU0:Oct 17 05:43:45.552 UTC: eem_server[207]: fms_chkpt_tbl_remove: delete chkpt obj 0x40002b78 from table 0x40001100successful
RP/0/RP0/CPU0:Oct 17 05:43:45.552 UTC: eem_server[207]: EEM: server processes multi events: timewin=1, sync_flag=0, ec_index=0, cmp_occ=1
RP/0/RP0/CPU0:Oct 17 05:43:45.552 UTC: eem_server[207]: EEM: server processes multi events: get correlate result esid=56
RP/0/RP0/CPU0:Oct 17 05:43:45.552 UTC: eem_server[207]: EEM: ctx=24:(56,1,1)(57,1,1)
RP/0/RP0/CPU0:Oct 17 05:43:45.606 UTC: BM-DISTRIB[1184]: %L2-BM-6-MLACP_BUNDLE_PEERING : Bundle-Ether2651 is no longer peering with Node 144.133.160.42 in IG 2. mLACP peer is no longer reachable
RP/0/RP0/CPU0:Oct 17 05:43:45.606 UTC: BM-DISTRIB[1184]: %L2-BM-6-MLACP_BUNDLE_PEERING : Bundle-Ether2601 is no longer peering with Node 144.133.160.42 in IG 2. mLACP peer is no longer reachable
RP/0/RP0/CPU0:Oct 17 05:43:45.606 UTC: BM-DISTRIB[1184]: %L2-BM-6-MLACP_BUNDLE_PEERING : Bundle-Ether2100 is no longer peering with Node 144.133.160.42 in IG 2. mLACP peer is no longer reachable
RP/0/RP0/CPU0:Oct 17 05:43:45.606 UTC: BM-DISTRIB[1184]: %L2-BM-6-MLACP_BUNDLE_ACTIVE : This device is now the active device for Bundle-Ether2651
RP/0/RP0/CPU0:Oct 17 05:43:45.606 UTC: BM-DISTRIB[1184]: %L2-BM-6-MLACP_BUNDLE_ACTIVE : This device is now the active device for Bundle-Ether2601
RP/0/RP0/CPU0:Oct 17 05:43:45.606 UTC: eem_ed_syslog[201]: syslog_scan: failed

Can someone please help here, I suspect that after scenario 2 is run, somehow script does not clear event e2 and it's values are fed as same when Scenario1 is performed again ?

Please let me know if more information is required.

Regards

Vineet Grover

Mob: +61414071196

1 person had this problem
Labels:
0 Helpful
1 Reply 1

Joe Clarke
Cisco Employee
Cisco Employee

‎10-18-2016 08:26 AM

First, you likely do not want to post your mobile phone number in a public forum.

Second, when dealing with AND events, you should specify a time window to correlate the trigger.  In this case you could probably have just a few seconds of window .  Try:

::cisco::eem::trigger {
    ::cisco::eem::correlate event e1 andnot event e2
} period 3

0 Helpful
Customers Also Viewed These Support Documents