EEM timeout error try to conect SMPT server

[robertvasquez99]

Hi team,

I trying to send a mail from my router cisco on GNS3 but when run the script i get this log. 

Jan 6 02:29:27.835: %HA_EM-3-FMPD_SMTP: Error occurred when sending mail to SMTP server: aspmx.l.google.com : timeout error

[balaji.bandi]

Jan 6 02:29:27.835: %HA_EM-3-FMPD_SMTP: Error occurred when sending mail to SMTP server: aspmx.l.google.com : timeout error

Does the node in GNS3 able to reach google.com - mail server ?

how does your EEM Script looks like -

event manager environment _email_from EEM_memLeak@domain.com
event manager environment _email_to first.last@domain.com
event manager environment _email_server mailrelay.domain.com

below example : ( you can also use source interface if you like to use specific interface for mail relay)

event manager applet memLeak
description "Send an test email based on logs"
event syslog pattern "MY MESSASGE"
action 1.0 info type routername
action 2.0 mail server "$_email_server" to "$_email_to" from "$_email_from" subject "Memory leak detected on $_info_routername" body "Device has CRITICAL MESSAGE on switch $_info_routername; please take corrective action"
action 3.0 exit

[robertvasquez99]

Hi Bandi,

Yes, the router is able to reach google server. 

This is the script ;

event manager environment _email_from XXXXX@gmail.com
event manager environment _email_server aspmx.l.google.com
event manager environment _email_to YYYYYY@gmail.com
event manager applet IPAddressNotify
event none
action 1.0 info type routername
action 1.5 cli command "enable"
action 2.0 cli command "show ip int br"
action 8.0 mail server "aspmx.l.google.com" to "YYYYYY@gmail.com" from "XXXXX@gmail.com" subject "Router reload" body "$_cli_result"
action 9.0 syslog msg "E-mail was sent"

[MHM Cisco World]

are you use NAT cloud in GNS3 ??
and can you DNS resolve the email server.

[robertvasquez99]

Hi MHM,

are you use NAT cloud in GNS3 ??

I'm not sure but i think yes because the address assigned to router is different to lan network. For example : The segment for my lan is 10.0.0.1/24 and the GNS3 router has 172.26. segment.

and can you DNS resolve the email server.

Yes, this point is ok... I can ping the IP address and name address. 

[MHM Cisco World]

can you check the windows FW if it allow or not the SMTP port ?

[balaji.bandi]

have you tried this format :

action 2.0 mail server "$_email_server" to "$_email_to" from "$_email_from" subject "Memory leak detected on $_info_routername" body "Device has CRITICAL MESSAGE on switch $_info_routername; please take corrective action"

you can run the debug of event viewer.

also always exit at the end.

#debug event manager action cli

also look Gmail timeout codes

https://support.google.com/a/answer/3726730?hl=en

[robertvasquez99]

This is the log that i get. 

R2#event manager run IPAddressNotify

*Jan 7 03:08:35.967: cli_history_entry_add: free_hist_list size=0, hist_list size=7
*Jan 7 03:08:35.971: check_eem_cli_policy_handler: command_string=event manager run IPAddressNotify
*Jan 7 03:08:35.971: check_eem_cli_policy_handler: num_matches = 0, response_code = 1
*Jan 7 03:08:35.975: fh_fd_none_event_match: parameters = , sync = 1, get_tty = 1, tty_buf = 0
*Jan 7 03:08:35.975: none_conn_tm_alloc: ptp=0x6AF148DC
*Jan 7 03:08:35.975: fh_fd_none_event_match: publish_timer=0x68E3281C, ptp=0x6AF148DC, max_delay=30000
*Jan 7 03:08:35.979: none_conn_tm_add: re=0x6AE42040, ptp=0x6AF148DC
*Jan 7 03:08:35.983: fh_fd_none_event_match: re = 0x6AE42040, num_matches = 1
*Jan 7 03:08:35.991: fh_server_event_handler XOS_IPC_ASYNC_REQ_MSG: FH_MSG_DETECTOR_POLL
*Jan 7 03:08:35.991: fh_send_server_sig: received a pulse from none on node0/0 with fdid: 15
*Jan 7 03:08:35.991: fh_reg_send_msg_to_fd server sending FH_MSG_SERVER_POLL message to FD:none xos_ipc_sync_send to fdc->eph = 1048591)
*Jan 7 03:08:35.995: fh_reg_send_msg_to_fd server sent FH_MSG_SERVER_POLL message to FD:none event passed to fdc->eph = 1048591 status 0
*Jan 7 03:08:35.995: fh_send_server_sig: received FH_MSG_EVENT_PUBLISH_SYNC
*Jan 7 03:08:35.995: EEM: server processes multi events: esid=1
*Jan 7 03:08:35.995: EEM: server processes multi events: timewin=1, sync_flag=1, ec_index=0, cmp_occ=1
*Jan 7 03:08:35.995: EEM: server processes multi events: get correlate result esid=1
*Jan 7 03:08:35.995: EEM: ctx=1:(1,1,1)
*Jan 7 03:08:35.995: EEM: server processes multi events: corr_res=1, cur_tcnt=1, cmp_tcnt=1
*Jan 7 03:08:35.995: EEM: server processes multi events: schedule an event esid=1, corr_id=2, grpid=1
*Jan 7 03:08:35.995: fh_schedule_callback: fh_schedule_callback: cc=6A9AE784 prev_epc=0; epc=6AFE4970
*Jan 7 03:08:35.995: EEM server schedules one event: policy_type=applet epc=0x6AFE4970.
*Jan 7 03:08:35.995: EEM: server processes multi events: clean correlate data in ec: esid=1
*Jan 7 03:08:35.999: fh_server_event_handler XOS_IPC_REPLY_MSG
*Jan 7 03:08:35.999: fh_set_epc_pid: EEM callback policy IPAddressNotify has been scheduled to run. fdid: 15 sn: 1 jobid: 2
*Jan 7 03:08:35.999: fh_io_ipc_msg: received FH_MSG_API_INIT; jobid=15, processid=120, client=5, job name=EEM Callback Thread
*Jan 7 03:08:35.999: fh_server: fh_io_ipc_msg: received msg FH_MSG_EVENT_REQINFO_MULTI from client 5 pclient 1
*Jan 7 03:08:36.003: fh_server: fh_io_ipc_msg: received msg FH_MSG_EVENT_TTYINFO from client 5 pclient 1
*Jan 7 03:08:36.003: Registering tag: <fh_var> id: 1
*Jan 7 03:08:36.003: Pushing tag <fh_publish_event_spec> on to stack
*Jan 7 03:08:36.003: open tag is <fh_publish_event_spec>
*Jan 7 03:08:36.003: Pushing tag <fh_publish_common> on to stack
*Jan 7 03:08:36.003: open tag is <fh_publish_common>
*Jan 7 03:08:36.003: Pushing tag <fh_event_type> on to stack
*Jan 7 03:08:36.003: open tag is <fh_event_type>
*Jan 7 03:08:36.003: Name-Value Pair: Name=(pdir) Value=(_event_type)
*Jan 7 03:08:36.003: Name-Value Pair: Name=(tcl) Value=(event_type)
*Jan 7 03:08:36.003: Pushing tag <fh_var> on to stack
*Jan 7 03:08:36.003: open tag is <fh_var>
*Jan 7 03:08:36.003: Popping tag <fh_var> off stack
*Jan 7 03:08:36.003: close tag is </fh_var>
*Jan 7 03:08:36.003: Popping tag <fh_event_type> off stack
*Jan 7 03:08:36.003: close tag is </fh_event_type>
*Jan 7 03:08:36.003: Pushing tag <fh_event_spec_id> on to stack
*Jan 7 03:08:36.003: open tag is <fh_event_spec_id>
*Jan 7 03:08:36.003: Popping tag <fh_event_spec_id> off stack
*Jan 7 03:08:36.003: close tag is </fh_event_spec_id>
*Jan 7 03:08:36.003: Pushing tag <fh_event_name> on to stack
*Jan 7 03:08:36.003: open tag is <fh_event_name>
*Jan 7 03:08:36.003: Name-Value Pair: Name=(pdir) Value=(_event_type_string)
*Jan 7 03:08:36.003: Name-Value Pair: Name=(tcl) Value=(event_type_string)
*Jan 7 03:08:36.003: Pushing tag <fh_var> on to stack
*Jan 7 03:08:36.003: open tag is <fh_var>
*Jan 7 03:08:36.003: Popping tag <fh_var> off stack
*Jan 7 03:08:36.003: close tag is </fh_var>
*Jan 7 03:08:36.003: Popping tag <fh_event_name> off stack
*Jan 7 03:08:36.003: close tag is </fh_event_name>
*Jan 7 03:08:36.003: Pushing tag <fh_event_severity> on to stack
*Jan 7 03:08:36.003: open tag is <fh_event_severity>
*Jan 7 03:08:36.003: Name-Value Pair: Name=(pdir) Value=(_event_severity)
*Jan 7 03:08:36.003: Name-Value Pair: Name=(tcl) Value=(event_severity)
*Jan 7 03:08:36.003: Pushing tag <fh_var> on to stack
*Jan 7 03:08:36.003: open tag is <fh_var>
*Jan 7 03:08:36.003: Popping tag <fh_var> off stack
*Jan 7 03:08:36.003: close tag is </fh_var>
*Jan 7 03:08:36.003: Popping tag <fh_event_severity> off stack
*Jan 7 03:08:36.003: close tag is </fh_event_severity>
*Jan 7 03:08:36.003: Pushing tag <fh_event_sn> on to stack
*Jan 7 03:08:36.003: open tag is <fh_event_sn>
*Jan 7 03:08:36.003: Popping tag <fh_event_sn> off stack
*Jan 7 03:08:36.003: close tag is </fh_event_sn>
*Jan 7 03:08:36.003: Popping tag <fh_publish_common> off stack
*Jan 7 03:08:36.003: close tag is </fh_publish_common>
*Jan 7 03:08:36.003: Pushing tag <fh_fd_publish_none_spec> on to stack
*Jan 7 03:08:36.003: open tag is <fh_fd_publish_none_spec>
*Jan 7 03:08:36.003: Name-Value Pair: Name=(pdir) Value=(_none_argc)
*Jan 7 03:08:36.003: Name-Value Pair: Name=(tcl) Value=(argc)
*Jan 7 03:08:36.003: Pushing tag <fh_var> on to stack
*Jan 7 03:08:36.003: open tag is <fh_var>
*Jan 7 03:08:36.003: Popping tag <fh_var> off stack
*Jan 7 03:08:36.003: close tag is </fh_var>
*Jan 7 03:08:36.003: Popping tag <fh_fd_publish_none_spec> off stack
*Jan 7 03:08:36.003: close tag is </fh_fd_publish_none_spec>
*Jan 7 03:08:36.003: Popping tag <fh_publish_event_spec> off stack
*Jan 7 03:08:36.003: close tag is </fh_publish_event_spec>
*Jan 7 03:08:36.003: EEM: policy_dir xml builtin: name:_event_type value:131
*Jan 7 03:08:36.003: EEM: policy_dir xml builtin: name:_event_type_string value:none
*Jan 7 03:08:36.003: EEM: policy_dir xml builtin: name:_event_severity value:severity-normal
*Jan 7 03:08:36.003: EEM: policy_dir xml builtin: name:_none_argc value:0
*Jan 7 03:08:36.011: %HA_EM-6-LOG: IPAddressNotify : DEBUG(cli_lib) : : CTL : cli_open called.
*Jan 7 03:08:36.015: %HA_EM-6-LOG: IPAddressNotify : DEBUG(cli_lib) : : OUT : R2>
*Jan 7 03:08:36.015: %HA_EM-6-LOG: IPAddressNotify : DEBUG(cli_lib) : : IN : R2>enable
*Jan 7 03:08:36.015: cli_history_entry_add: free_hist_list size=0, hist_list size=7
*Jan 7 03:08:36.015: eem_no_scan flag set, skipping scan of command_string=enable
*Jan 7 03:08:36.039: %HA_EM-6-LOG: IPAddressNotify : DEBUG(cli_lib) : : OUT : R2#
*Jan 7 03:08:36.043: %HA_EM-6-LOG: IPAddressNotify : DEBUG(cli_lib) : : IN : R2#show ip int br
*Jan 7 03:08:36.051: cli_history_entry_add: free_hist_list size=0, hist_list size=7
*Jan 7 03:08:36.051: eem_no_scan flag set, skipping scan of command_string=show ip interface brief
*Jan 7 03:08:36.059: %HA_EM-6-LOG: IPAddressNotify : DEBUG(cli_lib) : : OUT : Interface IP-Address OK? Method Status Protocol
*Jan 7 03:08:36.059: %HA_EM-6-LOG: IPAddressNotify : DEBUG(cli_lib) : : OUT : Ethernet0/0 unassigned YES NVRAM administratively down down
*Jan 7 03:08:36.059: %HA_EM-6-LOG: IPAddressNotify : DEBUG(cli_lib) : : OUT : GigabitEthernet0/0 172.18.87.194 YES DHCP up up
*Jan 7 03:08:36.059: %HA_EM-6-LOG: IPAddressNotify : DEBUG(cli_lib) : : OUT : R2#
*Jan 7 03:08:36.059: %HA_EM-6-LOG: fh_send_mail: : DEBUG(smtp_lib) : <?xml version="1.0" encoding="UTF-8" ?><fh_smtp_args><fh_smtp_port>25</fh_smtp_port><fh_smtp_secure>0</fh_smtp_secure></fh_smtp_args>
*Jan 7 03:08:36.063: %HA_EM-6-LOG: IPAddressNotify : DEBUG(smtp_lib) : smtp_connect_attempt: 1
*Jan 7 03:08:36.119: %HA_EM-6-LOG: fh_smtp_connect: src: : DEBUG(smtp_lib) :
*Jan 7 03:08:41.123: %HA_EM-6-LOG: IPAddressNotify : DEBUG(smtp_lib) : smtp_connect connect fail 260
*Jan 7 03:08:41.127: %HA_EM-6-LOG: IPAddressNotify : DEBUG(smtp_lib) : fh_smtp_connect failed at attempt 1
*Jan 7 03:08:44.131: %HA_EM-6-LOG: IPAddressNotify : DEBUG(smtp_lib) : smtp_connect_attempt: 2
*Jan 7 03:08:44.135: %HA_EM-6-LOG: fh_smtp_connect: src: : DEBUG(smtp_lib) :
*Jan 7 03:08:49.139: %HA_EM-6-LOG: IPAddressNotify : DEBUG(smtp_lib) : smtp_connect connect fail 260
*Jan 7 03:08:49.143: %HA_EM-6-LOG: IPAddressNotify : DEBUG(smtp_lib) : fh_smtp_connect failed at attempt 2
*Jan 7 03:08:52.147: %HA_EM-6-LOG: IPAddressNotify : DEBUG(smtp_lib) : smtp_connect_attempt: 3
*Jan 7 03:08:52.147: %HA_EM-6-LOG: fh_smtp_connect: src: : DEBUG(smtp_lib) :
R2#
*Jan 7 03:08:57.147: %HA_EM-6-LOG: IPAddressNotify : DEBUG(smtp_lib) : smtp_connect connect fail 260
*Jan 7 03:08:57.151: %HA_EM-6-LOG: IPAddressNotify : DEBUG(smtp_lib) : fh_smtp_connect callback timer is awake
*Jan 7 03:08:57.151: %HA_EM-3-FMPD_SMTP: Error occurred when sending mail to SMTP server: aspmx.l.google.com : timeout error
*Jan 7 03:08:57.151: %HA_EM-6-LOG: IPAddressNotify : DEBUG(cli_lib) : : CTL : cli_close called.
*Jan 7 03:08:57.159: fh_server: fh_io_ipc_msg: received msg FH_MSG_CALLBACK_DONE from client 5 pclient 1
*Jan 7 03:08:57.159: fh_io_ipc_msg: EEM callback policy IPAddressNotify has ended with abnormal exit status of 0xFFFFFFFF
*Jan 7 03:08:57.159: EEM policy IPAddressNotify has exceeded it's elapsed time limit of 20.0 seconds
*Jan 7 03:08:57.159: EEM fms_remote_chkpt_add_event_hist(), data_len = 2984, buf_size = 2996
*Jan 7 03:08:57.159: fh_reg_send_msg_to_fd server sending FH_MSG_EVENT_PUBLISH_DONE message to FD:none xos_ipc_sync_send to fd
R2#c->eph = 1048591)
*Jan 7 03:08:57.159: fh_fd_none_publish_done: rc=1, re=0x6AE42040
*Jan 7 03:08:57.163: fh_fd_none_publish_done: rc=1, publish_expired=0
*Jan 7 03:08:57.163: sid=1, ptp=0x6AF148DC, connp=0x6AE80CC4
*Jan 7 03:08:57.163: none_conn_tm_remove: re=0x6AE42040, ptp=0x6AF148DC
*Jan 7 03:08:57.163: fh_fd_none_conn_tm_free: ptp=0x6AF148DC
*Jan 7 03:08:57.163: fh_reg_send_msg_to_fd server sent FH_MSG_EVENT_PUBLISH_DONE message to FD:none event passed to fdc->eph = 1048591 status 0
*Jan 7 03:08:57.163: EEM: server decrements in use thread: jobid=2 rule id=2 in use thread=0.
*Jan 7 03:08:57.163: fh_schedule_callback: fh_schedule_callback: cc=6A9AE784 prev_epc=6AFE4970; epc=0
*Jan 7 03:08:57.163: fh_schedule_policy: prev_epc=0x0; epc=0x0
*Jan 7 03:08:57.163: EEM server schedules scripts
*Jan 7 03:08:57.167: fh_server: fh_io_ipc_msg: received msg FH_MSG_API_CLOSE from client 5 pclient 1
R2#n 7 03:08:57.167: fh_io_ipc_msg: received FH_MSG_API_CLOSE client=5
*Jan 7 03:08:57.167:
*Jan 7 03:08:57.167: tty is now going through its death sequence
*Jan 7 03:08:57.171: fh_fd_match_event: re=0x6AE42040, policyname=IPAddressNotify, parameters=,
R2#
*Jan 7 03:08:59.999: fh_fd_timer_process_async
R2#

[balaji.bandi]

I have addressed on other post :

https://community.cisco.com/t5/network-management/ha-em-6-log-debug-smtp-lib-smtp-connect-connect-fail-260/td-p/4750809

[robertvasquez99 · Accepted solution]

 https://community.cisco.com/t5/network-management/ha-em-6-log-debug-smtp-lib-smtp-connect-connect-fail-260/m-p/4751034#M150282