EEM script problem, or not recognizing or doing anything?

[bnidacoc]

I've ben having significant issue with some EEM actions I'm trying to get going.  I have removed all other events and created a very simplistic event for the sake of troubleshooting and seeking help.  

I've tried various EEM scrips across multiple platforms, 3850 and IE-4010.  This is an IE-4010 running the latest gold star code (as of a week or two back) from Cisco, 15.2(8)E1.

[REMOVED]#terminal monitor
[REMOVED]#show run | b event manager
event manager applet SYSLOG-RECOGNITION
event syslog pattern "%SYS-5-CONFIG_I:"
action 1.00 syslog msg "Config Message Recognized"
!
end

[REMOVED]#conf t
Enter configuration commands, one per line. End with CNTL/Z.
[REMOVED](config)#exit
[REMOVED]#
May 19 11:40:50.222: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
[REMOVED]#
[REMOVED]#show log | i SYSLOG-RECOGNITION
May 19 11:28:47.966: %PARSER-5-CFGLOG_LOGGEDCMD: User:[REMOVED] logged command:event manager applet SYSLOG-RECOGNITION
[REMOVED]#
[REMOVED]#show logg | i %SYS-5-CONFIG_I:
May 19 09:21:33.907: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 09:21:41.369: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 09:29:38.361: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 09:50:58.987: %PARSER-5-CFGLOG_LOGGEDCMD: User:[REMOVED] logged command:event syslog pattern "%SYS-5-CONFIG_I: Configured from"
May 19 09:51:05.631: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 09:52:54.180: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 09:57:12.306: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 09:59:37.081: %PARSER-5-CFGLOG_LOGGEDCMD: User:[REMOVED] logged command:event syslog pattern "%SYS-5-CONFIG_I: Configured from"
May 19 09:59:42.072: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 10:00:35.736: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 10:11:14.501: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:09:33.103: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:10:56.803: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:12:16.071: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:13:24.510: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:23:17.986: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:24:25.674: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:25:16.042: %PARSER-5-CFGLOG_LOGGEDCMD: User:[REMOVED] logged command:event syslog pattern "%SYS-5-CONFIG_I:"
May 19 11:25:19.544: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:25:40.632: %PARSER-5-CFGLOG_LOGGEDCMD: User:[REMOVED] logged command:event syslog pattern "%SYS-5-CONFIG_I:"
May 19 11:26:14.470: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:26:47.243: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:28:48.029: %PARSER-5-CFGLOG_LOGGEDCMD: User:[REMOVED] logged command:event syslog pattern "%SYS-5-CONFIG_I:"
May 19 11:29:00.487: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:29:18.963: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:38:15.244: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:40:50.222: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:43:52.589: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 11:44:02.439: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
[REMOVED]#

Why is this not working?

[balaji.bandi]

You mean this syslog message not generated :

action 1.00 syslog msg "Config Message Recognized"

what was the issue ?

[bnidacoc]

Yes, that log message is not being logged.

I tried to reduce a script to the most simple possible, for the sake of troubleshooting.  

What is the issue?  It is not logging the log as I configured.  I've tried to do more complex stuff, those applets were not working, but I removed those applets for the sake of the most simplistic troubleshooting.

[balaji.bandi]

enable-debug and see what is wrong :

tested debug looks ok :

May 19 17:27:45.731: %SYS-5-CONFIG_I: Configured from console by console
May 19 17:27:45.738: EEM: policy_dir xml builtin: name:_syslog_sequence value:
May 19 17:27:45.738: EEM: policy_dir xml builtin: name:_syslog_timestamp value:May 19 17:27:45.731
May 19 17:27:45.738: EEM: policy_dir xml builtin: name:_syslog_facility value:SYS
May 19 17:27:45.738: EEM: policy_dir xml builtin: name:_syslog_mnemonic value:CONFIG_I
May 19 17:27:45.738: %HA_EM-6-LOG: SYSLOG-RECOGNITION: Config Message Recognized

[bnidacoc]

Not sure which debug, there is a lot of CDP/LLDP, routing debugs if I do all.

[REMOVED]#show debugging
Embedded Event Manager:
Debug EEM Syslog Event Detector debugging is on
[REMOVED]#conf t
Enter configuration commands, one per line. End with CNTL/Z.
[REMOVED](config)#exit
[REMOVED]#
May 19 13:35:33.685: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])
May 19 13:35:33.685: syslog_pubinfo_enqueue: matched message="
May 19 13:35:33.685: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty0 ([REMOVED])"

And I added the cli command enable, as some other posts illustrated it.

show run | b event manager
event manager applet SYSLOG-RECOGNITION
event syslog pattern "SYS-5-CONFIG"
action 0.50 cli command "enable"
action 1.00 syslog msg "Config Message Recognized"
!
end

[Georg Pauwen]

Hello,

enable 'debug event manager action cli' then generate a SYS-5 message:

Device#conf t

Device(config)#line vty 0 4

Device(config-line)#transport input all

I used your exact same script and it seems to work fine. Which EEM version are you running ?

Router#show event manager version
Embedded Event Manager Version 4.00
Component Versions:
eem: (rel9)1.2.11
eem-gold: (rel1)1.0.2
eem-call-home: (rel2)1.0.5

[bnidacoc]

Hmm!  Today, I power it back on, it works first thing.  I suppose I should reboot more often, but that usually isn't necessary from my experience with almost all Cisco products, and this is the latest Cisco gold code, but I've had no experience with EEM scripting/applets.

I'll post again if I run into problems with the original scripts I was trying to get to work.  

Thanks for making these testing efforts in your lab.

testbench-4010#show event manager version
Embedded Event Manager Version 4.00
Component Versions:
eem: (rel9)1.2.22
eem-gold: (rel1)1.0.2
eem-call-home: (rel2)1.0.4
Event Detectors:
Name Version Node Type
application 01.00 node0/0 RP
identity 01.00 node0/0 RP
mat 01.00 node0/0 RP
neighbor-discovery 01.00 node0/0 RP
generic 01.00 node0/0 RP
routing 03.00 node0/0 RP
syslog 01.00 node0/0 RP
cli 01.00 node0/0 RP
config 01.00 node0/0 RP
counter 01.00 node0/0 RP
crash 01.00 node0/0 RP
ds 01.00 node0/0 RP
env 01.00 node0/0 RP
gold 01.00 node0/0 RP
interface 01.00 node0/0 RP
ioswdsysmon 01.00 node0/0 RP
ipsla 01.00 node0/0 RP
none 01.00 node0/0 RP
oir 01.00 node0/0 RP
rpc 01.00 node0/0 RP
snmp 01.00 node0/0 RP
snmp-object 01.00 node0/0 RP
snmp-notification 01.00 node0/0 RP
test 01.00 node0/0 RP
timer 01.00 node0/0 RP

testbench-4010#

[Georg Pauwen]

Well, it works, that is the most important. A reboot often does wonders...

[bnidacoc]

Ha, I definitely hear you there.  However, I unplug this device at the end of each workday because I don't want it to put more heat into my marginally cooled workspace when I'm not at the office, so I considered it fresh.....

I'm going to resume my scripts to backup to FTP (original intent).  Hopefully I won't have t ask for assistance again.  Thanks.

[bnidacoc]

Ah, I tried this on an in production box last week after testing at the bench.  I forgot, good weekend....

Here it is, which this also got reduced in size as I was troubleshooting it..

[REMOVED]#
[REMOVED]#conf t
Enter configuration commands, one per line. End with CNTL/Z.
[REMOVED](config)#exit
[REMOVED]#
May 23 09:41:24.118: %SYS-5-CONFIG_I: Configured from console by [REMOVED] on vty5 ([REMOVED])
[REMOVED]#
[REMOVED]#
[REMOVED]#
[REMOVED]#show debugging
TCP:
FTP transactions debugging is on
Embedded Event Manager:
Debug EEM action cli debugging is on

[REMOVED]#show run | b event manager
event manager applet CHANGE-BACKUP
event syslog pattern "%SYS-5-CONFIG_I"
action 1.00 cli command "enable"
action 1.10 syslog msg "Action 1.00 has completed"
action 5.00 cli command "copy run ftp://[REMOVED]/TEST.conf"
action 5.10 syslog msg "Action 5.00 has completed"
!
end

[REMOVED]#

Not even action item 1.10 is putting a message in syslog, or displayed in the term mon enabled session.

While I've got it in terminal monitor, nothing debug was displayed on the screen.

Embedded Event Manager Version 4.00
Component Versions:
eem: (rel9)1.2.22
eem-gold: (rel1)1.0.2
eem-call-home: (rel2)1.0.4
Event Detectors:
Name Version Node Type
application 01.00 node0/0 RP
identity 01.00 node0/0 RP
mat 01.00 node0/0 RP
neighbor-discovery 01.00 node0/0 RP
generic 01.00 node0/0 RP
routing 03.00 node0/0 RP
syslog 01.00 node0/0 RP
cli 01.00 node0/0 RP
config 01.00 node0/0 RP
counter 01.00 node0/0 RP
crash 01.00 node0/0 RP
ds 01.00 node0/0 RP
env 01.00 node0/0 RP
gold 01.00 node0/0 RP
interface 01.00 node0/0 RP
ioswdsysmon 01.00 node0/0 RP
ipsla 01.00 node0/0 RP
none 01.00 node0/0 RP
oir 01.00 node0/0 RP
rpc 01.00 node0/0 RP
snmp 01.00 node0/0 RP
snmp-object 01.00 node0/0 RP
snmp-notification 01.00 node0/0 RP
test 01.00 node0/0 RP
timer 01.00 node0/0 RP

[bnidacoc]

I have pending jobs....

[REMOVED]#show event manager policy pending

Key: p - Priority :L - Low, H - High, N - Normal, Z - Last
s - Scheduling node :A - Active, S - Standby

default class - 4 applet events
no. job id p s status time of event event type name
1 1192 N A pend Mon May23 09:31:13 2022 syslog CHANGE-BACKUP
2 1193 N A pend Mon May23 09:32:43 2022 syslog CHANGE-BACKUP
3 1194 N A pend Mon May23 09:35:20 2022 syslog CHANGE-BACKUP
4 1195 N A pend Mon May23 09:41:24 2022 syslog CHANGE-BACKUP
[REMOVED]#show event manager policy regi
[REMOVED]#show event manager policy registered
No. Class Type Event Type Trap Time Registered Name
1 applet user syslog Off Mon May 23 09:31:07 2022 CHANGE-BACKUP
pattern {%SYS-5-CONFIG_I}
maxrun 20.000
action 1.00 cli command "enable"
action 1.10 syslog msg "Action 1.00 has completed"
action 5.00 cli command "copy run ftp://[REMOVED]/TEST.conf"
action 5.10 syslog msg "Action 5.00 has completed"

[REMOVED]#

[Georg Pauwen]

Hello,

so which script is not running now ? What is the output of 'debug event manager action cli' when you run the non-functioning script ?

[bnidacoc]

In the 05-23-2022 09:52 AM post, debugging was previously on, I went into conf mode, left, the syslog pattern "%SYS-5-CONFIG_I" was created, was copied to terminal, as well, however the event did not run, not even action 1.10

I noticed that I kept connecting on vty 5, and wondered why.  

[REMOVED]#show users
Line User Host(s) Idle Location
1 vty 0 idle 4d22h EEM:MONTHLY-BACKUP
2 vty 1 idle 4d22h EEM:MONTHLY-BACKUP
3 vty 2 idle 4d23h EEM:MONTHLY-BACKUP
4 vty 3 idle 4d23h EEM:MONTHLY-BACKUP
5 vty 4 idle 4d22h EEM:MONTHLY-BACKUP
* 6 vty 5 [REMOVED] idle 00:00:00 [REMOVED]

Interface User Mode Idle Peer Address

[REMOVED]#

I cleared those line vty sessions 0 - 4.

Maybe I had an error in the script and there was some kind of serial processing logjam.  I pasted in the scripts that worked on the bench, and the script that watches for the syslog string "%SYS-5-CONFIG_I" now works.  

Thanks for helping me with this.