Wednesday, November 21, 2018

VPN Tunnel bouncing, help me understand the debug output

I have a cisco 819 with VPN tunnels going to my other lab router. I reloaded the device and started noticing tunnel is bouncing, I tried to debug and google what I didn't understand but that raised more question than it answered. So I am seeking the experts help to help determine what's up with this VPN configuration. I am 100% sure my other router is configured correctly but there are other VPN tunnels connecting to it and they are all fine so I know the issue is with the 819.

debug cry isak===============

000271: Nov 22 04:00:38.075 UTC: ISAKMP:(2001):purging node -108306351

000272: Nov 22 04:00:40.775 UTC: ISAKMP:(2001):purging node -1984004343

000273: Nov 22 04:00:48.679 UTC: ISAKMP (2002): received packet from xxxx dport 4500 sport 4500 vpn(I) QM_IDLE

000274: Nov 22 04:00:48.679 UTC: ISAKMP: set new node 1824528058 to QM_IDLE

000275: Nov 22 04:00:48.679 UTC: ISAKMP:(2002): processing HASH payload. message ID = 1824528058

000276: Nov 22 04:00:48.679 UTC: ISAKMP:(2002): processing DELETE payload. message ID = 1824528058

000277: Nov 22 04:00:48.679 UTC: ISAKMP:(2002):peer does not do paranoid keepalives.

000278: Nov 22 04:00:48.679 UTC: ISAKMP:(2002):Enqueued KEY_MGR_DELETE_SAS for IPSEC SA (SPI:0xABFD32EA)

000279: Nov 22 04:00:48.679 UTC: ISAKMP:(2002):deleting node 1824528058 error FALSE reason "Informational (in) state 1"

000280: Nov 22 04:00:48.679 UTC: ISAKMP: Failed to find peer index node to update peer_info_list

000281: Nov 22 04:00:48.679 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel1, changed state to down

000282: Nov 22 04:00:51.050 UTC: ISAKMP: set new node 0 to QM_IDLE

000283: Nov 22 04:00:51.050 UTC: SA has outstanding requests (local xxxxx port 4500, remote xxxxx port 4500)

000284: Nov 22 04:00:51.050 UTC: ISAKMP:(2002): sitting IDLE. Starting QM immediately (QM_IDLE )

000285: Nov 22 04:00:51.050 UTC: ISAKMP:(2002):beginning Quick Mode exchange, M-ID of 1875605379

000286: Nov 22 04:00:51.050 UTC: ISAKMP:(2002):QM Initiator gets spi

000287: Nov 22 04:00:51.050 UTC: ISAKMP:(2002): sending packet to xxxx my_port 4500 peer_port 4500 (I) QM_IDLE

000288: Nov 22 04:00:51.050 UTC: ISAKMP:(2002):Sending an IKE IPv4 Packet.

000289: Nov 22 04:00:51.050 UTC: ISAKMP:(2002):Node 1875605379, Input = IKE_MESG_INTERNAL, IKE_INIT_QM

000290: Nov 22 04:00:51.050 UTC: ISAKMP:(2002):Old State = IKE_QM_READY New State = IKE_QM_I_QM1

000291: Nov 22 04:00:51.278 UTC: ISAKMP (2002): received packet from xxxxx dport 4500 sport 4500 vpn (I) QM_IDLE

000292: Nov 22 04:00:51.278 UTC: ISAKMP:(2002): processing HASH payload. message ID = 1875605379

000293: Nov 22 04:00:51.278 UTC: ISAKMP:(2002): processing SA payload. message ID = 1875605379

000294: Nov 22 04:00:51.278 UTC: ISAKMP:(2002):Checking IPSec proposal 1

000295: Nov 22 04:00:51.278 UTC: ISAKMP: transform 1, ESP_AES

000296: Nov 22 04:00:51.278 UTC: ISAKMP: attributes in transform:

000297: Nov 22 04:00:51.278 UTC: ISAKMP: encaps is 4 (Transport-UDP)

000298: Nov 22 04:00:51.278 UTC: ISAKMP: SA life type in seconds

000299: Nov 22 04:00:51.278 UTC: ISAKMP: SA life duration (basic) of 3600

000300: Nov 22 04:00:51.278 UTC: ISAKMP: SA life type in kilobytes

000301: Nov 22 04:00:51.278 UTC: ISAKMP: SA life duration (VPI) of 0x0 0x46 0x50 0x0

000302: Nov 22 04:00:51.278 UTC: ISAKMP: authenticator is HMAC-SHA256

000303: Nov 22 04:00:51.278 UTC: ISAKMP: key length is 256

000304: Nov 22 04:00:51.278 UTC: ISAKMP:(2002):atts are acceptable.

000305: Nov 22 04:00:51.278 UTC: ISAKMP:(2002): processing NONCE payload. message ID = 1875605379

000306: Nov 22 04:00:51.278 UTC: ISAKMP:(2002): processing ID payload. message ID = 1875605379

000307: Nov 22 04:00:51.278 UTC: ISAKMP:(2002): processing ID payload. message ID = 1875605379

000308: Nov 22 04:00:51.278 UTC: ISAKMP:received payload type 21

000309: Nov 22 04:00:51.278 UTC: ISAKMP:received payload type 21

000310: Nov 22 04:00:51.278 UTC: ISAKMP:(2002):Node 1875605379, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH

000311: Nov 22 04:00:51.278 UTC: ISAKMP:(2002):Old State = IKE_QM_I_QM1 New State = IKE_QM_IPSEC_INSTALL_AWAIT

000312: Nov 22 04:00:51.282 UTC: ISAKMP: Failed to find peer index node to update peer_info_list

000313: Nov 22 04:00:51.282 UTC: ISAKMP:(2002):Received IPSec Install callback... proceeding with the negotiation

000314: Nov 22 04:00:51.282 UTC: ISAKMP:(2002):Successfully installed IPSEC SA (SPI:0xE7461622) on Tunnel1

000315: Nov 22 04:00:51.282 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel1, changed state to up

000316: Nov 22 04:00:51.286 UTC: ISAKMP:(2002): sending packet to xxxx my_port 4500 peer_port 4500 (I) QM_IDLE

000317: Nov 22 04:00:51.286 UTC: ISAKMP:(2002):Sending an IKE IPv4 Packet.

000318: Nov 22 04:00:51.286 UTC: ISAKMP:(2002):deleting node 1875605379 error FALSE reason "No Error"

000319: Nov 22 04:00:51.286 UTC: ISAKMP:(2002):Node 1875605379, Input = IKE_MESG_FROM_IPSEC, IPSEC_INSTALL_DONE

000320: Nov 22 04:00:51.286 UTC: ISAKMP:(2002):Old State = IKE_QM_IPSEC_INSTALL_AWAIT New State = IKE_QM_PHASE2_COMPLETE

000321: Nov 22 04:01:38.674 UTC: ISAKMP:(2002):purging node 1824528058

000322: Nov 22 04:01:41.282 UTC: ISAKMP:(2002):purging node 1875605379

000323: Nov 22 04:01:43.182 UTC: ISAKMP (2001): received packet from xxxx dport 4500 sport 4500 vpn (I) QM_IDLE

000324: Nov 22 04:01:43.182 UTC: ISAKMP: set new node -501181912 to QM_IDLE

000325: Nov 22 04:01:43.182 UTC: ISAKMP:(2001): processing HASH payload. message ID = 3793785384

000326: Nov 22 04:01:43.182 UTC: ISAKMP:(2001): processing DELETE payload. message ID = 3793785384

000327: Nov 22 04:01:43.182 UTC: ISAKMP:(2001):peer does not do paranoid keepalives.

000328: Nov 22 04:01:43.182 UTC: ISAKMP:(2001):Enqueued KEY_MGR_DELETE_SAS for IPSEC SA (SPI:0xA91CA6B)

000329: Nov 22 04:01:43.182 UTC: ISAKMP:(2001):deleting node -501181912 error FALSE reason "Informational (in) state 1"

000330: Nov 22 04:01:43.182 UTC: ISAKMP: Failed to find peer index node to update peer_info_list

000331: Nov 22 04:01:43.182 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel2103, changed state to down

debug cry ipse=============

00381: Nov 22 04:07:45.100 UTC: IPSEC(key_engine): got a queue event with 1 KMI message(s)

000382: Nov 22 04:07:45.100 UTC: IDB is NULL : in crypto_ipsec_key_engine_delete_sas (), 5059

000383: Nov 22 04:07:45.100 UTC: IPSEC(key_engine_delete_sas): rec'd delete notify from ISAKMP

000384: Nov 22 04:07:45.100 UTC: IPSEC: still in use sa: 0x25081C4

000385: Nov 22 04:07:45.100 UTC: IPSEC(key_engine_delete_sas): delete SA with spi 0x5CB389E7 proto 50 for xxxx

000386: Nov 22 04:07:45.100 UTC: IPSEC(delete_sa): deleting SA,

(sa) sa_dest= xxxx, sa_proto= 50,

sa_spi= 0xFF76B8AF(4285970607),

sa_trans= esp-aes 256 esp-sha256-hmac , sa_conn_id= 167

sa_lifetime(k/sec)= (4608000/3600),

(identity) local= xxxx, remote= xxxxx,

local_proxy= xxxx/xxxxx/47/0,

remote_proxy= xxxxx/xxxxx/47/0

000387: Nov 22 04:07:45.104 UTC: IPSEC(delete_sa): deleting SA,

(sa) sa_dest= xxxx, sa_proto= 50,

sa_spi= 0x5CB389E7(1555270119),

sa_trans= esp-aes 256 esp-sha256-hmac , sa_conn_id= 168

sa_lifetime(k/sec)= (4608000/3600),

(identity) local= xxxx, remote= xxxxx,

local_proxy= xxxxx/xxxx/47/0,

remote_proxy= xxxx/xxxx/47/0

000388: Nov 22 04:07:45.104 UTC: IPSEC(send_delete_notify_kmi): not sending KEY_ENGINE_DELETE_SAS

000389: Nov 22 04:07:45.104 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel1, changed state to down

000390: Nov 22 04:07:45.108 UTC: IPSEC(ident_delete_notify_kmi): Failed to send KEY_ENG_DELETE_SAS

000391: Nov 22 04:07:45.108 UTC: IPSEC(ident_update_final_flow_stats): Collect Final Stats and update MIB

IPSEC get IKMP peer index from peer 0x21DAEBD8 ikmp handle 0x80000002

IPSEC IKMP peer index 0

[ident_update_final_flow_stats] : Flow delete complete event received for flow id 0x140000A7,peer index 0

000392: Nov 22 04:07:53.623 UTC: IPSEC(sa_request): ,

(key eng. msg.) OUTBOUND local= xxxxx, remote= xxxxx,

local_proxy= xxxx/xxxx/47/0,

remote_proxy= xxxx/xxxx/47/0,

protocol= ESP, transform= esp-aes 256 esp-sha256-hmac (Transport),

lifedur= 3600s and 4608000kb,

spi= 0x0(0), conn_id= 0, keysize= 256, flags= 0x0

000393: Nov 22 04:07:53.807 UTC: IPSEC(validate_proposal_request): proposal part #1

000394: Nov 22 04:07:53.807 UTC: IPSEC(validate_proposal_request): proposal part #1,

(key eng. msg.) INBOUND local= xxxx, remote= xxxxx,

local_proxy= xxxxx/xxxx/47/0,

remote_proxy= xxxx/xxxx/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

000395: Nov 22 04:07:53.807 UTC: Crypto mapdb : proxy_match

src addr : xxxx

dst addr : xxxx

protocol : 47

src port : 0

dst port : 0

000396: Nov 22 04:07:53.807 UTC: (ipsec_process_proposal)Map Accepted: VPNList, 55555

000397: Nov 22 04:07:53.807 UTC: IPSEC(key_engine): got a queue event with 1 KMI message(s)

000398: Nov 22 04:07:53.807 UTC: Crypto mapdb : proxy_match

src addr : xxxx

dst addr : xxxx

protocol : 47

src port : 0

dst port : 0

000399: Nov 22 04:07:53.807 UTC: IPSEC(crypto_ipsec_create_ipsec_sas): Map found VPNList, 55555

000400: Nov 22 04:07:53.807 UTC: IPSEC(create_sa): sa created,

(sa) sa_dest= xxxx, sa_proto= 50,

sa_spi= 0xC38C347E(3280745598),

sa_trans= esp-aes 256 esp-sha256-hmac , sa_conn_id= 171

sa_lifetime(k/sec)= (4608000/3600),

(identity) local= xxxx, remote= xxxxx,

local_proxy= xxxx/xxxx/47/0,

remote_proxy= xxxx/xxxx/47/0

000401: Nov 22 04:07:53.807 UTC: IPSEC(create_sa): sa created,

(sa) sa_dest= xxxx, sa_proto= 50,

sa_spi= 0x8C46F874(2353461364),

sa_trans= esp-aes 256 esp-sha256-hmac , sa_conn_id= 172

sa_lifetime(k/sec)= (4608000/3600),

(identity) local= xxxx, remote= xxxx,

local_proxy= xxxxx/xxxxx/47/0,

remote_proxy= xxxx/xxxx/47/0

000402: Nov 22 04:07:53.807 UTC: IPSEC: Expand action denied, notify RP

000403: Nov 22 04:07:53.811 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel1, changed state to up



No comments:

Post a Comment