Dear Community,
We have an IPSec Site to Site VPN between our company and another company. They informed us that the VPN tunnel had went down for a short time. When troubleshooting and looking at the logs I saw this:
Apr 24 11:36:56.700: IPSEC(key_engine): got a queue event with 1 KMI message(s)
Apr 24 11:36:56.700: IDB is NULL : in crypto_ipsec_key_engine_delete_sas (), 5431
Apr 24 11:36:56.700: IPSEC(key_engine_delete_sas): rec'd delete notify from ISAKMP
Apr 24 11:36:56.700: IPSEC: still in use sa: 0x223C7364
Apr 24 11:36:56.700: IPSEC(key_engine_delete_sas): delete SA with spi 0x21438AC8 proto 50 for 50.x.x.30
Apr 24 11:36:56.700: IPSEC(delete_sa): deleting SA,
(sa) sa_dest= 64.x.x.111, sa_proto= 50,
sa_spi= 0xF555AF28(4116033320),
sa_trans= esp-aes 256 esp-sha-hmac , sa_conn_id= 4233
sa_lifetime(k/sec)= (4608000/28800),
(identity) local= 64.x.x.111:0, remote= 50.x.x.30:0,
local_proxy= 64.x.x.114/255.255.255.255/256/0,
remote_proxy= 10.10.10.1/255.255.255.255/256/0
Apr 24 11:36:56.700: IPSEC(delete_sa): deleting SA,
(sa) sa_dest= 50.x.x.30, sa_proto= 50,
sa_spi= 0x21438AC8(558074568),
sa_trans= esp-aes 256 esp-sha-hmac , sa_conn_id= 4234
sa_lifetime(k/sec)= (4608000/28800),
(identity) local= 64.x.x.111:0, remote= 50.x.x.30:0,
local_proxy= 64.x.x.114/255.255.255.255/256/0,
remote_proxy= 10.10.10.1/255.255.255.255/256/0
Apr 24 11:36:56.700: IPSEC(send_delete_notify_kmi): not sending KEY_ENGINE_DELETE_SAS
Apr 24 11:36:56.704: IPSEC(ident_delete_notify_kmi): Failed to send KEY_ENG_DELETE_SAS
Apr 24 11:36:56.704: %CRYPTO-5-SESSION_STATUS: Crypto tunnel is DOWN. Peer 50.x.x.30:500 Id: 50.x.x.30
Apr 24 11:36:56.708: IPSEC(ident_update_final_flow_stats): Collect Final Stats and update MIB
IPSEC get IKMP peer index from peer 0x3F5EA400 ikmp handle 0x80000066
IPSEC IKMP peer index 0
[ident_update_final_flow_stats] : Flow delete complete event received for flow id 0x340008B9,peer index 0
Apr 24 11:39:35.508: IPSEC(validate_proposal_request): proposal part #1
Apr 24 11:39:35.508: IPSEC(validate_proposal_request): proposal part #1,
(key eng. msg.) INBOUND local= 64.x.x.111:0, remote= 50.x.x.30:0,
local_proxy= 64.x.x.114/255.255.255.255/256/0,
remote_proxy= 10.10.10.1/255.255.255.255/256/0,
protocol= ESP, transform= esp-aes 256 esp-sha-hmac (Tunnel),
lifedur= 0s and 0kb,
spi= 0x0(0), conn_id= 0, keysize= 256, flags= 0x0
Apr 24 11:39:35.508: Crypto mapdb : proxy_match
src addr : 64.x.x.114
dst addr : 10.10.10.1
protocol : 0
src port : 0
dst port : 0
Apr 24 11:39:35.508: (ipsec_process_proposal)Map Accepted: atl2client, 94
Apr 24 11:39:35.508: IPSEC(key_engine): got a queue event with 1 KMI message(s)
Apr 24 11:39:35.508: IPSEC(ipsec_get_crypto_session_id):
Invalid Payload Id
Apr 24 11:39:35.508: Crypto mapdb : proxy_match
src addr : 64.x.x.114
dst addr : 10.10.10.1
protocol : 256
src port : 0
dst port : 0
Apr 24 11:39:35.508: IPSEC(crypto_ipsec_create_ipsec_sas): Map found atl2client, 94
Apr 24 11:39:35.508: IPSEC(get_old_outbound_sa_for_peer): No outbound SA found for peer 3F5EA400
Apr 24 11:39:35.508: IPSEC(create_sa): sa created,
(sa) sa_dest= 64.x.x.111, sa_proto= 50,
sa_spi= 0xECCEA7FE(3972966398),
sa_trans= esp-aes 256 esp-sha-hmac , sa_conn_id= 4263
sa_lifetime(k/sec)= (4608000/28800),
(identity) local= 64.x.x.111:0, remote= 50.x.x.30:0,
local_proxy= 64.x.x.114/255.255.255.255/256/0,
remote_proxy= 10.10.10.1/255.255.255.255/256/0
Apr 24 11:39:35.508: IPSEC(create_sa): sa created,
(sa) sa_dest= 50.x.x.30, sa_proto= 50,
sa_spi= 0xC318AE7(204573415),
sa_trans= esp-aes 256 esp-sha-hmac , sa_conn_id= 4264
sa_lifetime(k/sec)= (4608000/28800),
(identity) local= 64.x.x.111:0, remote= 50.x.x.30:0,
local_proxy= 64.x.x.114/255.255.255.255/256/0,
remote_proxy= 10.10.10.1/255.255.255.255/256/0
Apr 24 11:39:35.512: %CRYPTO-5-SESSION_STATUS: Crypto tunnel is UP . Peer 50.x.x.30:500 Id: 50.x.x.30
Apr 24 11:39:35.592: IPSEC(key_engine): got a queue event with 1 KMI message(s)
Apr 24 11:39:35.592: IPSEC(ipsec_get_crypto_session_id):
Invalid Payload Id
Apr 24 11:39:35.592: IPSEC(key_engine_enable_outbound): rec'd enable notify from ISAKMP
Apr 24 11:39:35.592: IPSEC: Expand action denied, notify RP
I can see that the Phase 2 IPSec SA for this flow was in fact deleted, and then 3 minutes later it was rebuilt. However, I am having trouble figuring WHY this happened or which side of the tunnel initiated the teardown of the SA. there are no logs before or after these that can provide any more context unfortunately. Would anyone be able to assist me with deciphering this?
Thanks.
