Solved: EIGRP: holding time expired

Bledian · ‎10-03-2023

Hi community,

We have a client with 50 DMVPN spokes, connected with 2 Hubs. All Spokes are fine expect one. It was working and suddenly Tunnel adjency started flapping:

%DUAL-5-NBRCHANGE: EIGRP-IPv4 600: Neighbor x.x.x.x (TunnelX) is up: new adjacency

%DUAL-5-NBRCHANGE: EIGRP-IPv4 600: Neighbor x.x.x.x (TunnelX) is down: holding time expired

Any help would be appreciated

Best regards,

BR.

MHM Cisco World · ‎10-03-2023

Eigrp multicast or unicast is drop by ISP.

It ISP issue.

View solution in original post

Bledian · ‎10-03-2023

DEBUG CRYPTO ON SPOKE:

Oct 3 09:02:54.743: ISAKMP: (1452):retransmitting phase 1 MM_KEY_EXCH...
.Oct 3 09:02:54.743: ISAKMP: (1452):: incrementing error counter on sa, attempt 1 of 5: retransmit phase 1
.Oct 3 09:02:54.743: ISAKMP: (1452):retransmitting phase 1 MM_KEY_EXCH
.Oct 3 09:02:54.743: ISAKMP-PAK: (1452):sending packet to 91.239.145.48 my_port 4500 peer_port 4500 (I) MM_KEY_EXCH
.Oct 3 09:02:54.743: ISAKMP: (1452):Sending an IKE IPv4 Packet.
.Oct 3 09:02:58.767: ISAKMP: (1451):purging SA., sa=3A09C708, delme=3A09C708
.Oct 3 09:02:58.843: ISAKMP-PAK: (1452):received packet from 91.239.145.48 dport 4500 sport 4500 Global (I) MM_KEY_EXCH
.Oct 3 09:02:58.843: ISAKMP: (1452):set new node 2036612765 to QM_IDLE
.Oct 3 09:02:58.843: ISAKMP-PAK: (1452):received packet from 91.239.145.48 dport 4500 sport 4500 Global (I) MM_KEY_EXCH
.Oct 3 09:02:58.847: ISAKMP-PAK: (1452):received packet from 91.239.145.48 dport 4500 sport 4500 Global (I) MM_KEY_EXCH
.Oct 3 09:02:58.847: ISAKMP-PAK: (1452):received packet from 91.239.145.48 dport 4500 sport 4500 Global (I) MM_KEY_EXCH
.Oct 3 09:02:58.847: ISAKMP-PAK: (1452):received packet from 91.239.145.48 dport 4500 sport 4500 Global (I) MM_KEY_EXCH
.Oct 3 09:02:58.847: ISAKMP: (1452):Info Notify message requeue retry counter exceeded sa request from 91.239.145.48 to 192.168.1.101.
.Oct 3 09:03:00.843: ISAKMP-PAK: (1452):received packet from 91.239.145.48 dport 4500 sport 4500 Global (I) MM_KEY_EXCH
.Oct 3 09:03:00.843: ISAKMP: (1452):set new node 929581521 to QM_IDLE
.Oct 3 09:03:00.843: ISAKMP-PAK: (1452):received packet from 91.239.145.48 dport 4500 sport 4500 Global (I) MM_KEY_EXCH
.Oct 3 09:03:00.847: ISAKMP-PAK: (1452):received packet from 91.239.145.48 dport 4500 sport 4500 Global (I) MM_KEY_EXCH
.Oct 3 09:03:00.847: ISAKMP-PAK: (1452):received packet from 91.239.145.48 dport 4500 sport 4500 Global (I) MM_KEY_EXCH
.Oct 3 09:03:00.851: ISAKMP-PAK: (1452):received packet from 91.239.145.48 dport 4500 sport 4500 Global (I) MM_KEY_EXCH
.Oct 3 09:03:00.851: ISAKMP: (1452):Info Notify message requeue retry counter exceeded sa request from 91.239.145.48 to 192.168.1.101.
.Oct 3 09:03:02.567: ISAKMP: (1452):set new node 0 to QM_IDLE
.Oct 3 09:03:02.567: ISAKMP-ERROR: (1452):SA is still budding. Attached new ipsec request to it. (local 192.168.1.101, remote 91.239.145.48)
.Oct 3 09:03:02.567: ISAKMP-ERROR: (0):Error while processing SA request: Failed to initialize SA
.Oct 3 09:03:02.567: ISAKMP-ERROR: (0):Error while processing KMI message 0, error 2.
.Oct 3 09:03:04.742: ISAKMP: (1452):retransmitting phase 1 MM_KEY_EXCH...
.Oct 3 09:03:04.742: ISAKMP: (1452):: incrementing error counter on sa, attempt 2 of 5: retransmit phase 1
.Oct 3 09:03:04.742: ISAKMP: (1452):retransmitting phase 1 MM_KEY_EXCH
.Oct 3 09:03:04.742: ISAKMP-PAK: (1452):sending packet to 91.239.145.48 my_port 4500 peer_port 4500 (I) MM_KEY_EXCH

!

Oct 3 09:03:00.851: ISAKMP: (1452):Info Notify message requeue retry counter exceeded sa request from 91.239.145.48 to 192.168.1.101.
.Oct 3 09:03:02.567: ISAKMP: (1452):set new node 0 to QM_IDLE
.Oct 3 09:03:02.567: ISAKMP-ERROR: (1452):SA is still budding. Attached new ipsec request to it. (local 192.168.1.101, remote 91.239.145.48)
.Oct 3 09:03:02.567: ISAKMP-ERROR: (0):Error while processing SA request: Failed to initialize SA
.Oct 3 09:03:02.567: ISAKMP-ERROR: (0):Error while processing KMI message 0, error 2.
.Oct 3 09:03:04.742: ISAKMP: (1452):retransmitting phase 1 MM_KEY_EXCH...
.Oct 3 09:03:04.742: ISAKMP: (1452):: incrementing error counter on sa, attempt 2 of 5: retransmit phase 1
.Oct 3 09:03:04.742: ISAKMP: (1452):retransmitting phase 1 MM_KEY_EXCH
.Oct 3 09:03:04.742: ISAKMP-PAK: (1452):sending packet to 91.239.145.48 my_port 4500 peer_port 4500 (I) MM_KEY_EXCH
.Oct 3 09:03:04.742: ISAKMP: (1452):Sending an IKE IPv4 Packet.
.Oct 3 09:03:14.742: ISAKMP: (1452):retransmitting phase 1 MM_KEY_EXCH...
.Oct 3 09:03:14.742: ISAKMP: (1452):: incrementing error counter on sa, attempt 3 of 5: retransmit phase 1
.Oct 3 09:03:14.742: ISAKMP: (1452):retransmitting phase 1 MM_KEY_EXCH
.Oct 3 09:03:14.742: ISAKMP-PAK: (1452):sending packet to 91.239.145.48 my_port 4500 peer_port 4500 (I) MM_KEY_EXCH
.Oct 3 09:03:14.742: ISAKMP: (1452):Sending an IKE IPv4 Packet.
.Oct 3 09:03:17.469: ISAKMP: (1452):quick mode timer expired.
.Oct 3 09:03:17.469: ISAKMP: (1452):src 192.168.1.101 dst 91.239.145.48, SA is not authenticated
.Oct 3 09:03:17.469: ISAKMP: (1452):peer does not do paranoid keepalives.
.Oct 3 09:03:17.469: ISAKMP-ERROR: (1452):deleting SA reason "QM_TIMER expired" state (I) MM_KEY_EXCH (peer 91.239.145.48)
.Oct 3 09:03:17.469: IPSec: Key engine got a KEY_MGR_CHECK_MORE_SAS message
.Oct 3 09:03:17.469: ISAKMP (1452): IPSec has no more SA's with this peer. Won't keepalive phase 1.
.Oct 3 09:03:17.469: ISAKMP-ERROR: (1452):deleting SA reason "QM_TIMER expired" state (I) MM_KEY_EXCH (peer 91.239.145.48)
.Oct 3 09:03:17.469: ISAKMP: (0):Unlocking peer struct 0x2315D21C for isadb_mark_sa_deleted(), count 0
.Oct 3 09:03:17.469: ISAKMP: (0):Deleting peer node by peer_reap for 91.239.145.48: 2315D21C
.Oct 3 09:03:17.469: ISAKMP: (1452):deleting node 428389660 error FALSE reason "IKE deleted"
.Oct 3 09:03:17.469: ISAKMP: (1452):deleting node -1212416909 error FALSE reason "IKE deleted"
.Oct 3 09:03:17.469: ISAKMP: (1452):deleting node 2036612765 error FALSE reason "IKE deleted"
.Oct 3 09:03:17.469: ISAKMP: (1452):deleting node 929581521 error FALSE reason "IKE deleted"
.Oct 3 09:03:17.469: ISAKMP: (1452):deleting node -1782379682 error FALSE reason "IKE deleted"
.Oct 3 09:03:17.469: ISAKMP: (1452):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL
.Oct 3 09:03:17.469: ISAKMP: (1452):Old State = IKE_I_MM5 New State = IKE_DEST_SA

Bledian · ‎10-03-2023

DEBUG CRYPTOS ON HUB:

Oct 3 10:31:15.953: IPSEC(key_engine): got a queue event with 1 KMI message(s)
Oct 3 10:31:15.953: IDB is NULL : in crypto_ipsec_key_engine_delete_sas (), 5502
Oct 3 10:31:15.953: IPSEC(key_engine_delete_sas): rec'd delete notify from ISAKMP
Oct 3 10:31:15.953: IPSEC: still in use sa: 0x17507600
Oct 3 10:31:15.953: IPSEC(key_engine_delete_sas): delete SA with spi 0x2983D24F proto 50 for 78.188.5.166
Oct 3 10:31:15.953: IPSEC(delete_sa): deleting SA,
(sa) sa_dest= 172.29.0.200, sa_proto= 50, 
sa_spi= 0xC27DAE9A(3263016602), 
sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 4055
sa_lifetime(k/sec)= (0/3600),
(identity) local= 172.29.0.200:0, remote= 78.188.5.166:0,
local_proxy= 172.29.0.200/255.255.255.255/47/0,
remote_proxy= 78.188.5.166/255.255.255.255/47/0
Oct 3 10:31:15.953: IPSEC(delete_sa): deleting SA,
(sa) sa_dest= 78.188.5.166, sa_proto= 50, 
sa_spi= 0x2983D24F(696504911), 
sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 4056
sa_lifetime(k/sec)= (0/3600),
(identity) local= 172.29.0.200:0, remote= 78.188.5.166:0,
local_proxy= 172.29.0.200/255.255.255.255/47/0,
remote_proxy= 78.188.5.166/255.255.255.255/47/0
Oct 3 10:31:15.953: IPSEC(send_delete_notify_kmi): not sending KEY_ENGINE_DELETE_SAS
Oct 3 10:31:15.953: IPSEC: Expand action denied, notify RP
Oct 3 10:31:15.953: IPSEC(ident_delete_notify_kmi): Failed to send KEY_ENG_DELETE_SAS
Oct 3 10:31:15.953: IPSEC(ident_update_final_flow_stats): Collect Final Stats and update MIB 
IPSEC get IKMP peer index from peer 0x2C73188 ikmp handle 0x80007EA5
IPSEC IKMP peer index 0 
[ident_update_final_flow_stats] : Flow delete complete event received for flow id 0x14000FD7,peer index 0

Oct 3 10:31:16.081: IPSEC(ipsec_internal_request_flow_stats): IPSEC: Adding In flow 0x14000F4D to flow array

Oct 3 10:31:16.081: IPSEC(ipsec_internal_request_flow_stats): IPSEC: Adding In flow 0x14000F4E to flow array

Oct 3 10:31:16.081: IPSEC(ipsec_internal_request_flow_stats): IPSEC: Flow Stats Ptr 0x3976B64 for FLOW_ID : 0x14000F4D

Oct 3 10:31:16.081: IPSEC(ipsec_internal_request_flow_stats): IPSEC: Flow Stats Ptr 0x3976B64 for FLOW_ID : 0x14000F4E

Oct 3 10:31:16.081: IPSEC(ipsec_internal_request_flow_stats): call crypto-engine to pull stats; hdle_count=2
Oct 3 10:31:16.081: IPSEC(sibling_update_flow_stats): IPSEC: MIB Stats Ptr 0x2C72CD0

Oct 3 10:31:16.081: IPSEC(sibling_update_flow_stats): IPSEC: MIB Stats Ptr 0x2C72CD0

Oct 3 10:31:16.081: IPSEC(sibling_update_flow_stats): IPSEC: Flow ID : 0x14000F4D, Flow Stats Ptr 0x3976B64

Oct 3 10:31:16.081: IPSEC(sibling_update_flow_stats): IPSEC: MIB Stats Ptr 0x2C72CD0

Oct 3 10:31:16.081: IPSEC(lifetime_expiry): SA lifetime threshold reached, expiring in 678 seconds
Oct 3 10:31:16.081: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 172.29.0.200:4500, remote= 85.242.96.227:4500,
local_proxy= 172.29.0.200/255.255.255.255/47/0,
remote_proxy= 85.242.96.227/255.255.255.255/47/0,
protocol= ESP, transform= esp-3des esp-md5-hmac (Transport), 
lifedur= 3600s and -1kb, 
spi= 0xDAC50AFE(3670346494), conn_id= 0, keysize= 0, flags= 0x0
Oct 3 10:31:16.105: IPSEC(validate_proposal_request): proposal part #1
Oct 3 10:31:16.105: IPSEC(validate_proposal_request): proposal part #1,
(key eng. msg.) INBOUND local= 172.29.0.200:0, remote= 69.170.146.227:0,
local_proxy= 91.239.145.48/255.255.255.255/47/0,
remote_proxy= 69.170.146.227/255.255.255.255/47/0,
protocol= ESP, transform= esp-aes 256 esp-sha256-hmac (Transport-UDP), 
lifedur= 0s and 0kb, 
spi= 0x0(0), conn_id= 0, keysize= 256, flags= 0x0
Oct 3 10:31:16.105: map_db_find_best did not find matching map
Oct 3 10:31:16.105: IPSEC(ipsec_process_proposal): transform proposal not supported for identity: 
{esp-aes 256 esp-sha256-hmac }
Oct 3 10:31:16.161: IPSEC(validate_proposal_request): proposal part #1
Oct 3 10:31:16.161: IPSEC(validate_proposal_request): proposal part #1,
(key eng. msg.) INBOUND local= 172.29.0.200:0, remote= 85.242.96.227:0,
local_proxy= 172.29.0.200/255.255.255.255/47/0,
remote_proxy= 85.242.96.227/255.255.255.255/47/0,
protocol= ESP, transform= esp-3des esp-md5-hmac (Transport-UDP), 
lifedur= 0s and 0kb, 
spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
Oct 3 10:31:16.161: Crypto mapdb : proxy_match
src addr : 172.29.0.200
dst addr : 85.242.96.227
protocol : 47
src port : 0
dst port : 0
Oct 3 10:31:16.161: (ipsec_process_proposal)Map Accepted: Tunnel1921-head-0, 66169
Oct 3 10:31:16.161: IPSEC(key_engine): got a queue event with 1 KMI message(s)
Oct 3 10:31:16.161: Crypto mapdb : proxy_match
src addr : 172.29.0.200
dst addr : 85.242.96.227
protocol : 47
src port : 0
dst port : 0
Oct 3 10:31:16.161: IPSEC(crypto_ipsec_create_ipsec_sas): Map found Tunnel1921-head-0, 66169
Oct 3 10:31:16.161: IPSEC(create_sa): sa created,
(sa) sa_dest= 172.29.0.200, sa_proto= 50, 
sa_spi= 0x803C41A9(2151432617), 
sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 4059
sa_lifetime(k/sec)= (0/3600),
(identity) local= 172.29.0.200:0, remote= 85.242.96.227:0,
local_proxy= 172.29.0.200/255.255.255.255/47/0,
remote_proxy= 85.242.96.227/255.255.255.255/47/0
Oct 3 10:31:16.165: IPSEC(create_sa): sa created,
(sa) sa_dest= 85.242.96.227, sa_proto= 50, 
sa_spi= 0x1FBD88B6(532514998), 
sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 4060
sa_lifetime(k/sec)= (0/3600),
(identity) local= 172.29.0.200:0, remote= 85.242.96.227:0,
local_proxy= 172.29.0.200/255.255.255.255/47/0,
remote_proxy= 85.242.96.227/255.255.255.255/47/0
Oct 3 10:31:16.165: IPSEC(update_current_outbound_sa): updated peer 85.242.96.227 current outbound sa to SPI 1FBD88B6

MHM Cisco World · ‎10-03-2023

Eigrp multicast or unicast is drop by ISP.

It ISP issue.