Cisco Site-to-Site re-establish 2 minute delay

[mark.vinten]

So I have tried to identify why, if I drop my site-to-site VPN tunnel at the remote end, and I see the IKE DELETE come through, it takes 60 - 120 seconds to actually start trying to bring the tunnel back up again if I have a constant ping going?

I have put various debug options on but not really sure what could be causing that.

[Philip D'Ath]

What are the two devices and what software version are they running.

They they have matching encryption domains?

[mark.vinten]

One is a Draytek 2830.  The Cisco is an ASA 5516-X running:

Cisco Adaptive Security Appliance Software Version 9.6(1)
Device Manager Version 7.6(1)

The tunnel itself works when it is established from the Draytek end, no delay.  However, if we drop the tunnel where we see the IKE DELETE or equivalent message, then ping the remote side, it can take up to two minutes for the tunnel to actually start requesting as the initiator. 

I did a show crypto isakmp sa but there was no SA so this would suggest the Cisco should be trying to recreate it straight away.

[Michael Beck]

Just a stray thought.  

After you clear the tunnel, rather than bring it up with a ping from a workstation inside somewhere, try bringing it up with packet tracer.

packet-tracer input inside icmp <IP> 8 0 <destination>

That way you can be assured that the device forming the tunnel is seeing interesting traffic.  

You could also use capture on the inside interface to prove that the 'interesting' traffic is being received.  Your debug shows nothing between the tear down at 11:39:08 and the interesting traffic at 11:41:16. One wonders what is going on during that time... Interesting packets or no?

So if it works immediately, then check for route convergence on either end (assuming the ping host is a couple of hops away from the firewall).  I'm not aware of any VPN tunnel hold down timers now routing protocols are a different matter.

[mark.vinten]

I will try that again when I'm back at the office next week.  Unfortunately, I've been out and about last week and this so can't test that yet.  I did stumble across something else that "cured" it but I will give this ago to see if this shows up why it cured it.

As mentioned previously, pretty convinced that wanted traffic was being sent.  I think I even did a packet trace at the time and saw a drop because the tunnel was not "up" though I want to be sure again.

[mark.vinten]

Here is the debug information from me clearing out the SA to it reestablishing whilst a ping was already going.  It destroys the tunnel at Mar 17 11:39:08 and then reestablishes it two minutes later at Mar 17 11:41:16

ghcs-asa1/act# clear crypto ikev1 sa xxx.xxx.xxx.xxx
ghcs-asa1/act# Mar 17 11:39:08 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, sending delete/delete with reason message
Mar 17 11:39:08 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, constructing blank hash payload
Mar 17 11:39:08 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, constructing IPSec delete payload
Mar 17 11:39:08 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, constructing qm hash payload
Mar 17 11:39:08 [IKEv1]IP = xxx.xxx.xxx.xxx, IKE_DECODE SENDING Message (msgid=4b71715a) with payloads : HDR + HASH (8) + DELETE (12) + NONE (0) total length : 68
Mar 17 11:39:08 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Active unit receives a delete event for remote peer xxx.xxx.xxx.xxx.

Mar 17 11:39:08 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, IKE Deleting SA: Remote Proxy rrr.rrr.0.0, Local Proxy sss.sss.sss.0
Mar 17 11:39:08 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, IKE SA MM:1ca9ac8c rcv'd Terminate: state MM_ACTIVE flags 0x00000062, refcnt 1, tuncnt 0
Mar 17 11:39:08 [IKEv1]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Remove from IKEv1 Tunnel Table succeeded for SA with logicalId 1167360
Mar 17 11:39:08 [IKEv1]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Remove from IKEv1 MIB Table succeeded for SA with logical ID 1167360
Mar 17 11:39:08 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, IKE SA MM:1ca9ac8c terminating: flags 0x01000022, refcnt 0, tuncnt 0
Mar 17 11:39:08 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, sending delete/delete with reason message
Mar 17 11:39:08 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, constructing blank hash payload
Mar 17 11:39:08 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, constructing IKE delete payload
Mar 17 11:39:08 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, constructing qm hash payload
Mar 17 11:39:08 [IKEv1]IP = xxx.xxx.xxx.xxx, IKE_DECODE SENDING Message (msgid=e2571227) with payloads : HDR + HASH (8) + DELETE (12) + NONE (0) total length : 80
Mar 17 11:39:08 [IKEv1]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Session is being torn down. Reason: Administrator Reset
Mar 17 11:41:16 [IKEv1]IP = xxx.xxx.xxx.xxx, IKE Initiator: New Phase 1, Intf inside, IKE Peer xxx.xxx.xxx.xxx local Proxy Address sss.sss.sss.0, remote Proxy Address rrr.rrr.0.0, Crypto map (Internet_map)
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, constructing ISAKMP SA payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, constructing NAT-Traversal VID ver 02 payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, constructing NAT-Traversal VID ver 03 payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, constructing NAT-Traversal VID ver RFC payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, constructing Fragmentation VID + extended capabilities payload
Mar 17 11:41:16 [IKEv1]IP = xxx.xxx.xxx.xxx, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 332
Mar 17 11:41:16 [IKEv1]IP = xxx.xxx.xxx.xxx, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 128
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, processing SA payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, Oakley proposal is acceptable
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, processing VID payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, Received DPD VID
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, processing VID payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, Received NAT-Traversal RFC VID
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, constructing ke payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, constructing nonce payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, constructing Cisco Unity VID payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, constructing xauth V6 VID payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, Send IOS VID
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, Constructing ASA spoofing IOS Vendor ID payload (version: 1.0.0, capabilities: 20000001)
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, constructing VID payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, Send Altiga/Cisco VPN3000/Cisco ASA GW VID
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, constructing NAT-Discovery payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, computing NAT Discovery hash
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, constructing NAT-Discovery payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, computing NAT Discovery hash
Mar 17 11:41:16 [IKEv1]IP = xxx.xxx.xxx.xxx, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + KE (4) + NONCE (10) + VENDOR (13) + VENDOR (13) + VENDOR (13) + VENDOR (13) + NAT-D (20) + NAT-D (20) + NONE (0) total length : 304
Mar 17 11:41:16 [IKEv1]IP = xxx.xxx.xxx.xxx, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + KE (4) + NONCE (10) + NAT-D (20) + NAT-D (20) + NONE (0) total length : 228
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, processing ke payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, processing ISA_KE payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, processing nonce payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, processing NAT-Discovery payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, computing NAT Discovery hash
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, processing NAT-Discovery payload
Mar 17 11:41:16 [IKEv1 DEBUG]IP = xxx.xxx.xxx.xxx, computing NAT Discovery hash
Mar 17 11:41:16 [IKEv1]IP = xxx.xxx.xxx.xxx, Connection landed on tunnel_group xxx.xxx.xxx.xxx
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Generating keys for Initiator...
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, constructing ID payload
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, constructing hash payload
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Computing hash for ISAKMP
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, constructing dpd vid payload
Mar 17 11:41:16 [IKEv1]IP = xxx.xxx.xxx.xxx, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + ID (5) + HASH (8) + VENDOR (13) + NONE (0) total length : 84
Mar 17 11:41:16 [IKEv1]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Automatic NAT Detection Status: Remote end is NOT behind a NAT device This end is NOT behind a NAT device
Mar 17 11:41:16 [IKEv1]IP = xxx.xxx.xxx.xxx, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + ID (5) + HASH (8) + NOTIFY (11) + NONE (0) total length : 92
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, processing ID payload
Mar 17 11:41:16 [IKEv1 DECODE]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, ID_IPV4_ADDR ID received
xxx.xxx.xxx.xxx
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, processing hash payload
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Computing hash for ISAKMP
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, processing notify payload
Mar 17 11:41:16 [IKEv1]IP = xxx.xxx.xxx.xxx, Connection landed on tunnel_group xxx.xxx.xxx.xxx
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Oakley begin quick mode
Mar 17 11:41:16 [IKEv1 DECODE]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, IKE Initiator starting QM: msg id = 07098a06
Mar 17 11:41:16 [IKEv1]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, PHASE 1 COMPLETED
Mar 17 11:41:16 [IKEv1]IP = xxx.xxx.xxx.xxx, Keep-alive type for this connection: DPD
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Starting P1 rekey timer: 64800 seconds.
Mar 17 11:41:16 [IKEv1]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Add to IKEv1 Tunnel Table succeeded for SA with logical ID 1175552
Mar 17 11:41:16 [IKEv1]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Add to IKEv1 MIB Table succeeded for SA with logical ID 1175552
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, IKE got SPI from key engine: SPI = 0x9bb36abc
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, oakley constucting quick mode
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, constructing blank hash payload
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, constructing IPSec SA payload
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, constructing IPSec nonce payload
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, constructing proxy ID
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Transmitting Proxy Id:
 Local subnet: sss.sss.sss.0 mask 255.255.255.0 Protocol 0 Port 0
 Remote subnet: rrr.rrr.0.0 Mask 255.255.255.0 Protocol 0 Port 0
Mar 17 11:41:16 [IKEv1 DECODE]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, IKE Initiator sending Initial Contact
Mar 17 11:41:16 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, constructing qm hash payload
Mar 17 11:41:16 [IKEv1 DECODE]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, IKE Initiator sending 1st QM pkt: msg id = 07098a06
Mar 17 11:41:16 [IKEv1]IP = xxx.xxx.xxx.xxx, IKE_DECODE SENDING Message (msgid=7098a06) with payloads : HDR + HASH (8) + SA (1) + NONCE (10) + ID (5) + ID (5) + NOTIFY (11) + NONE (0) total length : 200
Mar 17 11:41:17 [IKEv1]IP = xxx.xxx.xxx.xxx, IKE_DECODE RECEIVED Message (msgid=7098a06) with payloads : HDR + HASH (8) + SA (1) + NONCE (10) + ID (5) + ID (5) + NONE (0) total length : 168
Mar 17 11:41:17 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, processing hash payload
Mar 17 11:41:17 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, processing SA payload
Mar 17 11:41:17 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, processing nonce payload
Mar 17 11:41:17 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, processing ID payload
Mar 17 11:41:17 [IKEv1 DECODE]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, ID_IPV4_ADDR_SUBNET ID received--sss.sss.sss.0--255.255.255.0
Mar 17 11:41:17 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, processing ID payload
Mar 17 11:41:17 [IKEv1 DECODE]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, ID_IPV4_ADDR_SUBNET ID received--rrr.rrr.0.0--255.255.255.0
Mar 17 11:41:17 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, loading all IPSEC SAs
Mar 17 11:41:17 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Generating Quick Mode Key!
Mar 17 11:41:17 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, NP encrypt rule look up for crypto map Internet_map 3 matching ACL Internet_cryptomap_2: returned cs_id=7843fe40; encrypt_rule=804e81b0; tunnelFlow_rule=803fa7b0
Mar 17 11:41:17 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Generating Quick Mode Key!
Mar 17 11:41:17 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, NP encrypt rule look up for crypto map Internet_map 3 matching ACL Internet_cryptomap_2: returned cs_id=7843fe40; encrypt_rule=804e81b0; tunnelFlow_rule=803fa7b0
Mar 17 11:41:17 [IKEv1]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Security negotiation complete for LAN-to-LAN Group (xxx.xxx.xxx.xxx) Initiator, Inbound SPI = 0x9bb36abc, Outbound SPI = 0xcb2a5f21
Mar 17 11:41:17 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, oakley constructing final quick mode
Mar 17 11:41:17 [IKEv1 DECODE]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, IKE Initiator sending 3rd QM pkt: msg id = 07098a06
Mar 17 11:41:17 [IKEv1]IP = xxx.xxx.xxx.xxx, IKE_DECODE SENDING Message (msgid=7098a06) with payloads : HDR + HASH (8) + NONE (0) total length : 76
Mar 17 11:41:17 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, IKE got a KEY_ADD msg for SA: SPI = 0xcb2a5f21
Mar 17 11:41:17 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Pitcher: received KEY_UPDATE, spi 0x9bb36abc
Mar 17 11:41:17 [IKEv1 DEBUG]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, Starting P2 rekey timer: 24479 seconds.
Mar 17 11:41:17 [IKEv1]Group = xxx.xxx.xxx.xxx, IP = xxx.xxx.xxx.xxx, PHASE 2 COMPLETED (msgid=07098a06)

[Philip D'Ath]

That 2 minute break is suggesting the ASA did not have any interesting traffic.  Check your crypto domain and NAT rules.

[mark.vinten]

Clearly that can't be the case or it wouldn't both to initiate?  Besides, the domain and NAT rules are correct as traffic passes fine once up, but understand your suggestion.  Something I had already checked.