Re: EEM Errors - fh_parse_var: could not find environment variable

cwkronk1982 · ‎11-14-2022

I'm getting multiple of the following errors when my EEM policies run:

%HA_EM-3-FMPD_UNKNOWN_ENV: fh_parse_var: could not find environment variable: state
%HA_EM-3-FMPD_UNKNOWN_ENV: fh_parse_var: could not find environment variable: ip

I get both when BGP_UpDown runs and just the variable: state one when BGP_UpDown_2 runs. The policies work and the errors don't seem to affect operation, but I'd like to know why they're appearing and if there's a fix for them.

event manager applet BGP_UpDown
event syslog pattern "BGP-5-ADJCHANGE: neighbor 172.16.2[05]0.1 Down|Up"
action 1.0 cli command "enable"
action 2.1 regexp "BGP-5-ADJCHANGE: neighbor ([0-9]+\.[0-9]+\.[0-9]+\.[0-9]+) ([A-Za-z]+)" $_syslog_msg match ip state
action 2.2 if $state eq "Down"
action 2.3 set reverse "up"
action 2.4 else
action 2.5 set reverse "down"
action 2.6 end
action 2.7 if $ip eq "172.16.200.1"
action 2.8 set reverseip "172.16.250.1"
action 2.9 else
action 3.0 set reverseip "172.16.200.1"
action 3.1 end
action 3.2 cli command "show ip bgp neighbor $reverseip | inc BGP state"
action 3.3 regexp "BGP state = (Established)" $_cli_result match reverseipstate
action 3.4 cli command "config t"
action 3.5 cli command "router bgp 65510"
action 3.6 if $_regexp_result eq "0"
action 3.7 if $state eq "Down"
action 3.8 cli command "neighbor 192.168.0.2 shutdown"
action 3.9 cli command "neighbor 192.168.0.3 shutdown "
action 4.0 cli command "end"
action 4.1 cli command "wr mem"
action 4.2 end
action 4.3 end
action 5.0 if $state eq "Up" 
action 5.1 cli command "no neighbor 192.168.0.2 shutdown"
action 5.2 cli command "no neighbor 192.168.0.3 shutdown"
action 5.3 cli command "end"
action 5.4 cli command "wr mem"
action 5.5 end


event manager applet BGP_UpDown_2
event syslog pattern "BGP-5-ADJCHANGE: neighbor 172.16.100.1 Down|Up"
action 1.0 cli command "enable"
action 2.1 regexp "BGP-5-ADJCHANGE: neighbor 172.16.100.1 ([A-Za-z]+)" $_syslog_msg match state
action 2.2 cli command "conf t"
action 2.3 cli command "router bgp 65501"
action 2.4 if $state eq "Down"
action 2.5 cli command "neighbor 192.168.0.4 shutdown"
action 2.6 cli command "neighbor 192.168.0.5 shutdown"
action 2.7 cli command "end"
action 2.8 end
action 2.9 if $state eq "Up"
action 3.0 cli command "no neighbor 192.168.0.4 shutdown"
action 3.1 cli command "no neighbor 192.168.0.5 shutdown"
action 3.2 cli command "end"
action 3.3 end

Dan Frey · ‎11-14-2022

The variables ip and state are created from parsing the original syslog message stored in $_syslog_msg. The entire string is placed in a variable called "match" and then variable "ip" is the first set of parenthesis() and variable "state" is from the second parenthesis(). This line creates ip and state variables.

action 2.1 regexp "BGP-5-ADJCHANGE: neighbor ([0-9]+\.[0-9]+\.[0-9]+\.[0-9]+) ([A-Za-z]+)" $_syslog_msg match ip state

The regexp and parsing can be tested in the tclsh

MPLS#tclsh
MPLS(tcl)#set _syslog_msg "%BGP-5-ADJCHANGE: neighbor 172.27.2.3 Up" 
%BGP-5-ADJCHANGE: neighbor 172.27.2.3 Up
MPLS(tcl)#regexp {BGP-5-ADJCHANGE: neighbor ([0-9]+\.[0-9]+\.[0-9]+\.[0-9]+) ([A-Za-z]+)} $_syslog_msg match ip state 
1
MPLS(tcl)#puts $ip
172.27.2.3

MPLS(tcl)#puts $state
Up

Variables "ip" and "state" are getting the proper values when parsed from $_syslog_msg. The error message you are receiving looks like the values are not getting populated because the regexp does not match. What does your BGP-5-ADJCHANGE message look like that triggers the policy?

cwkronk1982 · ‎11-14-2022

The values have to be getting populated though because the EEM policies are working. When they see the adjacency changes messages they are doing what they're supposed to. When BGP_UpDown sees 172.16.200.1 and 172.16.250.1 go down, it puts in the cli commands to shut down 192.168.0.2 and 192.168.0.3 and it does the opposite when one comes back up. BGP_UpDown_2 shuts down or brings up 192.168.0.4 and 0.5 when the peer to 172.16.100.1 goes down or up respectively.

When I try doing what you did in tclsh, I get the following:

set _syslog_msg "%BGP-5-ADJCHANGE: neighbor 172.16.100.1 Down BGP Notification received"
regexp "BGP-5-ADJCHANGE: neighbor 172.16.100.1 ([A-Za-z]+)" $_syslog_msg match state
switch-01(tcl)#$or 172.16.100.1 ([A-Za-z]+)" $_syslog_msg match state
invalid command name "A-Za-z" ^
% Invalid input detected at '^' marker.

I can do the following and $state returns the correct variable:

set _syslog_msg "%BGP-5-ADJCHANGE: neighbor 172.16.100.1 Down BGP Notification received"
regexp "BGP-5-ADJCHANGE: neighbor 172.16.100.1 (Up|Down)" $_syslog_msg match state
%BGP-5-ADJCHANGE: neighbor 172.16.100.1 Down BGP Notification received
switch-01(tcl)#$GE: neighbor 172.16.100.1 (Up|Down)" $_syslog_msg match state
1
switch-01(tcl)#puts $state
Down

Could this be an issue with IOSv?

Here are the syslog messages for BGP_UpDown

*Nov 14 16:36:36.623: %BGP-5-NBR_RESET: Neighbor 172.16.250.1 reset (BGP Notification sent)
*Nov 14 16:36:36.624: %BGP-5-ADJCHANGE: neighbor 172.16.250.1 Down BGP Notification sent
*Nov 14 16:36:36.624: %BGP_SESSION-5-ADJCHANGE: neighbor 172.16.250.1 IPv4 Unicast topology base removed from session BGP Notification sent
*Nov 14 16:36:40.718: %BGP-3-NOTIFICATION: sent to neighbor 172.16.200.1 4/0 (hold time expired) 0 bytes 
*Nov 14 16:36:40.719: %BGP-5-NBR_RESET: Neighbor 172.16.200.1 reset (BGP Notification sent)
*Nov 14 16:36:40.720: %BGP-5-ADJCHANGE: neighbor 172.16.200.1 Down BGP Notification sent
*Nov 14 16:36:40.720: %BGP_SESSION-5-ADJCHANGE: neighbor 172.16.200.1 IPv4 Unicast topology base removed from session BGP Notification sent
*Nov 14 16:36:40.990: %BGP-3-NOTIFICATION: sent to neighbor 192.168.0.2 6/2 (Administrative Shutdown) 0 bytes 
*Nov 14 16:36:40.990: %BGP-5-NBR_RESET: Neighbor 192.168.0.2 reset (Admin. shutdown)
*Nov 14 16:36:40.995: %BGP-5-ADJCHANGE: neighbor 192.168.0.2 Down Admin. shutdown
*Nov 14 16:36:40.995: %BGP_SESSION-5-ADJCHANGE: neighbor 192.168.0.2 IPv4 Unicast topology base removed from session Admin. shutdown
*Nov 14 16:36:41.107: %BGP-3-NOTIFICATION: sent to neighbor 192.168.0.3 6/2 (Administrative Shutdown) 0 bytes 
*Nov 14 16:36:41.107: %BGP-5-NBR_RESET: Neighbor 192.168.0.3 reset (Admin. shutdown)
*Nov 14 16:36:41.111: %BGP-5-ADJCHANGE: neighbor 192.168.0.3 Down Admin. shutdown
*Nov 14 16:36:41.112: %BGP_SESSION-5-ADJCHANGE: neighbor 192.168.0.3 IPv4 Unicast topology base removed from session Admin. shutdown
*Nov 14 16:36:41.190: %SYS-5-CONFIG_I: Configured from console by on vty0 (EEM:BGP_UpDown)
*Nov 14 16:36:41.384: %HA_EM-3-FMPD_UNKNOWN_ENV: fh_parse_var: could not find environment variable: state
*Nov 14 16:36:41.385: %HA_EM-3-FMPD_UNKNOWN_ENV: fh_parse_var: could not find environment variable: ip
*Nov 14 16:36:42.271: %HA_EM-3-FMPD_UNKNOWN_ENV: fh_parse_var: could not find environment variable: state
*Nov 14 16:36:42.271: %HA_EM-3-FMPD_UNKNOWN_ENV: fh_parse_var: could not find environment variable: state

Here are the syslog messages for BGP_UpDown_2

*Nov 14 16:36:37.272: %BGP-5-NBR_RESET: Neighbor 172.16.100.1 reset (BGP Notification received)
*Nov 14 16:36:37.275: %BGP-5-ADJCHANGE: neighbor 172.16.100.1 Down BGP Notification received
*Nov 14 16:36:37.276: %BGP_SESSION-5-ADJCHANGE: neighbor 172.16.100.1 IPv4 Unicast topology base removed from session BGP Notification received
*Nov 14 16:36:37.443: %BGP-3-NOTIFICATION: sent to neighbor 192.168.0.4 6/2 (Administrative Shutdown) 0 bytes 
*Nov 14 16:36:37.443: %BGP-5-NBR_RESET: Neighbor 192.168.0.4 reset (Admin. shutdown)
*Nov 14 16:36:37.445: %BGP-5-ADJCHANGE: neighbor 192.168.0.4 Down Admin. shutdown
*Nov 14 16:36:37.445: %BGP_SESSION-5-ADJCHANGE: neighbor 192.168.0.4 IPv4 Unicast topology base removed from session Admin. shutdown
*Nov 14 16:36:37.558: %BGP-3-NOTIFICATION: sent to neighbor 192.168.0.5 6/2 (Administrative Shutdown) 0 bytes 
*Nov 14 16:36:37.558: %BGP-5-NBR_RESET: Neighbor 192.168.0.5 reset (Admin. shutdown)
*Nov 14 16:36:37.562: %BGP-5-ADJCHANGE: neighbor 192.168.0.5 Down Admin. shutdown
*Nov 14 16:36:37.562: %BGP_SESSION-5-ADJCHANGE: neighbor 192.168.0.5 IPv4 Unicast topology base removed from session Admin. shutdown
*Nov 14 16:36:37.646: %SYS-5-CONFIG_I: Configured from console by on vty0 (EEM:BGP_UpDown)
*Nov 14 16:36:37.783: %HA_EM-3-FMPD_UNKNOWN_ENV: fh_parse_var: could not find environment variable: state
*Nov 14 16:36:37.783: %HA_EM-3-FMPD_UNKNOWN_ENV: fh_parse_var: could not find environment variable: state

Final edit:

I changed the EEM Policy to what's below. It returned an actual value for $state in the tcl shell.

event manager applet BGP_UpDown
event syslog pattern "BGP-5-ADJCHANGE: neighbor 172.16.100.1 Down|Up"
action 1.0 cli command "enable"
action 2.1 regexp "BGP-5-ADJCHANGE: neighbor 172.16.100.1 (Up|Down)" $_syslog_msg match state
action 2.2 cli command "conf t"
action 2.3 cli command "router bgp 65501"
action 2.4 if $state eq "Down"
action 2.5 cli command "neighbor 192.168.0.4 shutdown"
action 2.6 cli command "neighbor 192.168.0.5 shutdown"
action 2.7 cli command "end"
action 2.8 end
action 2.9 if $state eq "Up"
action 3.0 cli command "no neighbor 192.168.0.4 shutdown"
action 3.1 cli command "no neighbor 192.168.0.5 shutdown"
action 3.2 cli command "end"
action 3.3 end

And this is what the console spit out:

*Nov 14 20:00:40.563: %LINK-3-UPDOWN: Interface GigabitEthernet0/3, changed state to up
*Nov 14 20:00:41.563: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/3, changed state to up
*Nov 14 20:00:46.282: %BGP-5-ADJCHANGE: neighbor 172.16.100.1 Up 
*Nov 14 20:00:46.640: %SYS-5-CONFIG_I: Configured from console by on vty0 (EEM:BGP_UpDown)
*Nov 14 20:00:46.776: %HA_EM-3-FMPD_UNKNOWN_ENV: fh_parse_var: could not find environment variable: state
*Nov 14 20:00:46.776: %HA_EM-3-FMPD_UNKNOWN_ENV: fh_parse_var: could not find environment variable: state
*Nov 14 20:00:47.898: %BGP-5-ADJCHANGE: neighbor 192.168.0.4 Up 
*Nov 14 20:00:48.039: %HA_EM-3-FMPD_UNKNOWN_ENV: fh_parse_var: could not find environment variable: state
*Nov 14 20:00:48.040: %HA_EM-3-FMPD_UNKNOWN_ENV: fh_parse_var: could not find environment variable: state
*Nov 14 20:00:49.984: %BGP-5-ADJCHANGE: neighbor 192.168.0.5 Up 
*Nov 14 20:00:50.123: %HA_EM-3-FMPD_UNKNOWN_ENV: fh_parse_var: could not find environment variable: state
*Nov 14 20:00:50.124: %HA_EM-3-FMPD_UNKNOWN_ENV: fh_parse_var: could not find environment variable: state

I'm having a feeling that CML images can't handle EEM policies correctly.