Cisco ASA VPN Issue

[Dinesh Moudgil]

Hi Mokhalil82,

It is quite weird that the ASA will show phase 1 and 2 up and the Watchguard will show that phase 1 is not.

It is possible that the tunnel comes up on ASA side but gets terminated at the same instant thus we see the phase 1 and 2 momentarily up.
Would you be able to share the debug outputs?


Regards,
Dinesh Moudgil

P.S. Please rate helpful posts

[Mokhalil82]

Hi, thanks for the responses

Following are the debugs from the ASA, I have replaced the local public IP with Y.Y.Y.Y and remote public IP with X.X.X.X

Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Oakley begin quick mode
Mar 01 07:18:22 [IKEv1 DECODE]Group = X.X.X.X, IP = X.X.X.X, IKE Initiator starting QM: msg id = 6c94f062
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, IKE got SPI from key engine: SPI = 0x1e7f11e8
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, oakley constucting quick mode
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing blank hash payload
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing IPSec SA payload
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing IPSec nonce payload
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing proxy ID
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Transmitting Proxy Id:
Local host: 10.1.201.4 Protocol 6 Port 0
Remote subnet: 172.16.224.0 Mask 255.255.255.0 Protocol 6 Port 3389
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing qm hash payload
Mar 01 07:18:22 [IKEv1 DECODE]Group = X.X.X.X, IP = X.X.X.X, IKE Initiator sending 1st QM pkt: msg id = 6c94f062
Mar 01 07:18:22 [IKEv1]IP = X.X.X.X, IKE_DECODE SENDING Message (msgid=6c94f062) with payloads : HDR + HASH (8) + SA (1) + NONCE (10) + ID (5) + ID (5) + NONE (0) total length : 168
Mar 01 07:18:22 [IKEv1]IKE Receiver: Packet received on Y.Y.Y.Y:500 from X.X.X.X:500
Mar 01 07:18:22 [IKEv1]IP = X.X.X.X, IKE_DECODE RECEIVED Message (msgid=6c94f062) with payloads : HDR + HASH (8) + SA (1) + NOTIFY (11) + NONCE (10) + ID (5) + ID (5) + NONE (0) total length : 196
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing hash payload
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing SA payload
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing notify payload
Mar 01 07:18:22 [IKEv1 DECODE]Responder Lifetime decode follows (outb SPI[4]|attributes):
Mar 01 07:18:22 [IKEv1 DECODE]0000: 1E7F11E8 80010001 00020004 00007080 ..............p.
0010: 80010002 00020004 0001F400 ............

Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing nonce payload
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing ID payload
Mar 01 07:18:22 [IKEv1 DECODE]Group = X.X.X.X, IP = X.X.X.X, ID_IPV4_ADDR ID received
10.1.201.4
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing ID payload
Mar 01 07:18:22 [IKEv1 DECODE]Group = X.X.X.X, IP = X.X.X.X, ID_IPV4_ADDR_SUBNET ID received--172.16.224.0--255.255.255.0
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, loading all IPSEC SAs
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Generating Quick Mode Key!
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, NP encrypt rule look up for crypto map outside_map 20 matching ACL SMART_METERS_DR_VPN: returned cs_id=4ce0edd0; encrypt_rule=e3f56e90; tunnelFlow_rule=e3f567e0
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Generating Quick Mode Key!
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, NP encrypt rule look up for crypto map outside_map 20 matching ACL SMART_METERS_DR_VPN: returned cs_id=4ce0edd0; encrypt_rule=e3f56e90; tunnelFlow_rule=e3f567e0
Mar 01 07:18:22 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, Security negotiation complete for LAN-to-LAN Group (X.X.X.X) Responder, Inbound SPI = 0x1e7f11e8, Outbound SPI = 0x84b5882c
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, oakley constructing final quick mode
Mar 01 07:18:22 [IKEv1 DECODE]Group = X.X.X.X, IP = X.X.X.X, IKE Initiator sending 3rd QM pkt: msg id = 6c94f062
Mar 01 07:18:22 [IKEv1]IP = X.X.X.X, IKE_DECODE SENDING Message (msgid=6c94f062) with payloads : HDR + HASH (8) + NONE (0) total length : 76
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, IKE got a KEY_ADD msg for SA: SPI = 0x84b5882c
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Pitcher: received KEY_UPDATE, spi 0x1e7f11e8
Mar 01 07:18:22 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Starting P2 rekey timer: 27360 seconds.
Mar 01 07:18:22 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, PHASE 2 COMPLETED (msgid=6c94f062)
Mar 01 07:18:26 [IKEv1]IKE Receiver: Packet received on Y.Y.Y.Y:500 from X.X.X.X:500
Mar 01 07:18:26 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, Duplicate Phase 2 packet detected. Retransmitting last packet.
Mar 01 07:18:26 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, Initiator resending lost, last msg
Mar 01 07:18:26 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Starting P2 rekey timer: 27356 seconds.
Mar 01 07:18:26 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, PHASE 2 COMPLETED (msgid=6c94f062)

Mar 01 07:18:31 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing hash payload
Mar 01 07:18:31 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing delete
Mar 01 07:18:31 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, Connection terminated for peer X.X.X.X. Reason: Peer Terminate Remote Proxy 10.1.201.4, Local Proxy 172.16.224.0
Mar 01 07:18:31 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Active unit receives a delete event for remote peer X.X.X.X.

Mar 01 07:18:31 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, IKE Deleting SA: Remote Proxy 172.16.224.0, Local Proxy 10.1.201.4
Mar 01 07:18:31 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, IKE SA MM:e6334151 rcv'd Terminate: state MM_ACTIVE flags 0x00000042, refcnt 1, tuncnt 0
Mar 01 07:18:31 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, IKE SA MM:e6334151 terminating: flags 0x01000002, refcnt 0, tuncnt 0
Mar 01 07:18:31 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, sending delete/delete with reason message
Mar 01 07:18:31 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing blank hash payload
Mar 01 07:18:31 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing IKE delete payload
Mar 01 07:18:31 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing qm hash payload
Mar 01 07:18:31 [IKEv1]IP = X.X.X.X, IKE_DECODE SENDING Message (msgid=86b3d0d1) with payloads : HDR + HASH (8) + DELETE (12) + NONE (0) total length : 80
Mar 01 07:18:31 [IKEv1 DEBUG]Pitcher: received key delete msg, spi 0x1e7f11e8
Mar 01 07:18:31 [IKEv1 DEBUG]Pitcher: received key delete msg, spi 0x1e7f11e8
Mar 01 07:18:31 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, Session is being torn down. Reason: User Requested

[Aditya Ganjoo]

Hi,

It seems the session is being torn down by the Watchguard.

On the Watchguard do you see anything like this in debugs:

iked Rejected QM third message from Y.Y.Y.Y to X.X.X.X

If yes then the issue is with the Watchguard device as it receives the packet from the ASA.

I would request if you can either check with WatchGuard support or share the logs from the devcie.

[Mokhalil82]

The watchguard logs show the following

2016-02-29 13:08:12 iked (X.X.X.X<->Y.Y.Y.Y)IKE phase-1 negotiation from X.X.X.X:500 to Y.Y.Y.Y:500 failed. Gateway-Endpoint='ADA' Reason=Received AES key length 128, expecting 256 id="0203-0008" Debug
2016-02-29 13:08:12 iked (X.X.X.X<->Y.Y.Y.Y)IKE phase-1 negotiation from X.X.X.X:500 to Y.Y.Y.Y:500 failed. Gateway-Endpoint='ADA' Reason=Received encryption 3DES, expecting AES id="0203-0006" Debug
2016-02-29 13:08:12 iked (X.X.X.X<->Y.Y.Y.Y)IKE phase-1 negotiation from X.X.X.X:500 to Y.Y.Y.Y:500 failed. Gateway-Endpoint='ADA' Reason=Received encryption 3DES, expecting AES id="0203-0006" Debug
2016-02-29 13:08:12 iked (X.X.X.X<->Y.Y.Y.Y)IKE phase-1 negotiation from X.X.X.X:500 to Y.Y.Y.Y:500 failed. Gateway-Endpoint='ADA' Reason=Received DH group 5, expecting 2 id="0203-0004" Debug

Seems like it is expecting certain parameters but reciving something different. I have various IKE policies configured on the ASA and I though they would auto negotiate the phase 1 policy when multiples are configured.

Thanks

[Dinesh Moudgil]

Mokhalil82,

Would you mind creating/setting up an isakmp policy real quick on ASA as policy number sequence 1 pertaining to the same parameters configured on Watchguard.

Ideally, they should auto negotiate whatever may be the sequence number of the policies.

Regards,
Dinesh Moudgil

P.S. Please rate helpful posts. 

[Mokhalil82]

Hi

I have setup  a new policy at sequence number 1 and recreated the VPN on my side and I still get the same.

I am expecting them to negotiate the IKE policies between them but according to the watchguard logs it is receiving the incorrect policy to what is configured on that side

[Dinesh Moudgil · Accepted solution]

Thanks for the update, Mokhalil82

For the last time, lets take simultaneous debugs on both the sides and share the outputs, I think we can drill it down with that information.
Additionally, if we can packet captures as well, that ll be helpful.

Make sure the timestamp is correct on both sides.

Regards,
Dinesh Moudgil

P.S. Please rate helpful posts.

[Mokhalil82]

Hi

I am using ASA version 9.1(6)6

The watchguard has the following logs

2016-03-03 10:56:22 iked (X.X.X.X<->Y.Y.Y.Y)QuickMode: Start with IsakmpSA 0xc850a22f for 'CIUP' IKE policy                  Debug

2016-03-03 10:56:22 iked (X.X.X.X<->Y.Y.Y.Y)recv P1SA_REMOTE_DELETE, start the mwanTimer(15) to make sure P1SA is created again for ikePcy(COOP)       Debug

I am trying to arrange a session with the 2rd party to go through this at the same time

[Mokhalil82]

So on the watchguard we are getting the following logs, X = watchguard public IP

Y=ASA public IP

<158>Mar 3 19:07:53 iked[1497]: recv ACTION XPATH(/vpn/ipsec/bovpn/rekey), need to process it
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)(NATT)IkeFindIsakmpSABySPD: Matched IP and peer_udp_port=0 p1saId=0 : pIsakmpSA p1saID=c850a22f DestPort=500
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)(NATT)IkeFindIsakmpSABySPD: Matched IP and peer_udp_port=0 p1saId=0 : pIsakmpSA p1saID=c850a22f DestPort=500
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)IkeProposalHtoN : net order spi(0xffffffbc 0x10 0xffffff90 0x0d)
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)IpsecOutAttibute: found key length attrib len 256
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)Starting phase 2 to Y.Y.Y.Y:500 quick mode message(id fc0b23e7)
<156>Mar 3 19:07:53 iked[1497]: 'Winchester' IPSec policy is not enabled. Ignoring rekey request.
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)******** RECV an IKE packet at X.X.X.X:500(socket=11 ifIndex=2) from Peer Y.Y.Y.Y:500 ********
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)IkeNotifyPayloadNtoH : SPI Size 4 first4(0000000000)
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)******** RECV an IKE packet at X.X.X.X:500(socket=11 ifIndex=2) from Peer Y.Y.Y.Y:500 ********
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)Received an inform delete message from Y.Y.Y.Y:500
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)Process DELETE payload: try to delete Isakmp SA (numSPI 1)
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)Process DELETE payload: found IsakmpSA to delete (peer 0xd90a9f02)
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)IkeInDeleteProcess: Mark for IPSec SA rekey. Reason=IKE_P1SA_REMOTE_DELETE. No other mature P1 SA found
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)recv P1SA_REMOTE_DELETE, start the mwanTimer(15) to make sure P1SA is created again for ikePcy(CIUP)
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)IkeDeleteIsakmpSA: try to delete Isakmp SA 0x81f5b00 for Gateway CIUP
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)IkeDeleteIsakmpSA: try to delete QMState SA 0x8227498 for Gateway CIUP
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)IkeDeleteQMState: try to delete QMState 0x8227498 (ID fc0b23e7) with IsakmpSA(0x81f5b00) Gateway(CIUP)
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)SA Nego Fail: saHandle 0x0x8b9e458 InitMode 1, reason 2
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)SA Nego Fail: free saHandle
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)Totally 1 Pending P2 SA Requests Got Dropped.
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)IkeDeleteIsakmpSA: Stop Phase One Retry and Life Timer
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)IkeDeleteIsakmpSA: Stop Phase One DPD Retry timer
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)IkeDeleteIsakmpSA: (DELETING) Start Phase One Delay Deletion Timer for IsakmpSA(0x81f5b00) Gateway(CIUP)
<158>Mar 3 19:08:03 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)IkeLifeTimeout : remove the IsakmpSA struct 0x81f5b00 (peer Y.Y.Y.Y gateway CIUP) in DELETING state
<158>Mar 3 19:08:03 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)IkeDeleteIsakmpSA: try to delete Isakmp SA 0x81f5b00 for Gateway CIUP
<158>Mar 3 19:08:03 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)IkeDeleteIsakmpSA: (DELETING) Isakmp SA 0x81f5b00 peer Y.Y.Y.Y local X.X.X.X

ASA Logs

Mar 03 14:33:37 [IKEv1]NAT-T disabled in crypto map outside_map 20.
Mar 03 14:33:37 [IKEv1]IP = X.X.X.X, IKE Initiator: New Phase 1, Intf inside, IKE Peer X.X.X.X local Proxy Address 10.1.201.4, remote Proxy Address 172.16.224.0, Crypto map (outside_map)
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, constructing ISAKMP SA payload
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, constructing Fragmentation VID + extended capabilities payload
Mar 03 14:33:37 [IKEv1]IP = X.X.X.X, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + NONE (0) total length : 344
Mar 03 14:33:37 [IKEv1]IKE Receiver: Packet received on Y.Y.Y.Y:500 from X.X.X.X:500
Mar 03 14:33:37 [IKEv1]IP = X.X.X.X, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + NONE (0) total length : 100
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, processing SA payload
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, Oakley proposal is acceptable
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, processing VID payload
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, Received xauth V6 VID
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, constructing ke payload
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, constructing nonce payload
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, constructing Cisco Unity VID payload
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, constructing xauth V6 VID payload
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, Send IOS VID
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, Constructing ASA spoofing IOS Vendor ID payload (version: 1.0.0, capabilities: 20000001)
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, constructing VID payload
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, Send Altiga/Cisco VPN3000/Cisco ASA GW VID
Mar 03 14:33:37 [IKEv1]IP = X.X.X.X, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + KE (4) + NONCE (10) + VENDOR (13) + VENDOR (13) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 256
Mar 03 14:33:37 [IKEv1]IKE Receiver: Packet received on Y.Y.Y.Y:500 from X.X.X.X:500
Mar 03 14:33:37 [IKEv1]IP = X.X.X.X, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + KE (4) + NONCE (10) + NONE (0) total length : 172
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, processing ke payload
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, processing ISA_KE payload
Mar 03 14:33:37 [IKEv1 DEBUG]IP = X.X.X.X, processing nonce payload
Mar 03 14:33:37 [IKEv1]IP = X.X.X.X, Connection landed on tunnel_group X.X.X.X
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Generating keys for Initiator...
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing ID payload
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing hash payload
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Computing hash for ISAKMP
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing dpd vid payload
Mar 03 14:33:37 [IKEv1]IP = X.X.X.X, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + ID (5) + HASH (8) + VENDOR (13) + NONE (0) total length : 84
Mar 03 14:33:37 [IKEv1]IKE Receiver: Packet received on Y.Y.Y.Y:500 from X.X.X.X:500
Mar 03 14:33:37 [IKEv1]IP = X.X.X.X, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + ID (5) + HASH (8) + VENDOR (13) + NONE (0) total length : 84
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing ID payload
Mar 03 14:33:37 [IKEv1 DECODE]Group = X.X.X.X, IP = X.X.X.X, ID_IPV4_ADDR ID received
X.X.X.X
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing hash payload
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Computing hash for ISAKMP
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing VID payload
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Received DPD VID
Mar 03 14:33:37 [IKEv1]IP = X.X.X.X, Connection landed on tunnel_group X.X.X.X
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Oakley begin quick mode
Mar 03 14:33:37 [IKEv1 DECODE]Group = X.X.X.X, IP = X.X.X.X, IKE Initiator starting QM: msg id = 3e3bd831
Mar 03 14:33:37 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, PHASE 1 COMPLETED
Mar 03 14:33:37 [IKEv1]IP = X.X.X.X, Keep-alive type for this connection: DPD
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Starting P1 rekey timer: 21600 seconds.
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, IKE got SPI from key engine: SPI = 0x3f03d9f2
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, oakley constucting quick mode
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing blank hash payload
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing IPSec SA payload
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing IPSec nonce payload
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing proxy ID
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Transmitting Proxy Id:
Local host: 10.1.201.4 Protocol 6 Port 0
Remote subnet: 172.16.224.0 Mask 255.255.255.0 Protocol 6 Port 3389
Mar 03 14:33:37 [IKEv1 DECODE]Group = X.X.X.X, IP = X.X.X.X, IKE Initiator sending Initial Contact
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing qm hash payload
Mar 03 14:33:37 [IKEv1 DECODE]Group = X.X.X.X, IP = X.X.X.X, IKE Initiator sending 1st QM pkt: msg id = 3e3bd831
Mar 03 14:33:37 [IKEv1]IP = X.X.X.X, IKE_DECODE SENDING Message (msgid=3e3bd831) with payloads : HDR + HASH (8) + SA (1) + NONCE (10) + ID (5) + ID (5) + NOTIFY (11) + NONE (0) total length : 196
Mar 03 14:33:37 [IKEv1]IKE Receiver: Packet received on Y.Y.Y.Y:500 from X.X.X.X:500
Mar 03 14:33:37 [IKEv1]IP = X.X.X.X, IKE_DECODE RECEIVED Message (msgid=3e3bd831) with payloads : HDR + HASH (8) + SA (1) + NOTIFY (11) + NONCE (10) + ID (5) + ID (5) + NONE (0) total length : 196
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing hash payload
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing SA payload
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing notify payload
Mar 03 14:33:37 [IKEv1 DECODE]Responder Lifetime decode follows (outb SPI[4]|attributes):
Mar 03 14:33:37 [IKEv1 DECODE]0000: 3F03D9F2 80010001 00020004 00007080 ?.............p.
0010: 80010002 00020004 0001F400 ............

Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing nonce payload
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing ID payload
Mar 03 14:33:37 [IKEv1 DECODE]Group = X.X.X.X, IP = X.X.X.X, ID_IPV4_ADDR ID received
10.1.201.4
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing ID payload
Mar 03 14:33:37 [IKEv1 DECODE]Group = X.X.X.X, IP = X.X.X.X, ID_IPV4_ADDR_SUBNET ID received--172.16.224.0--255.255.255.0
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, loading all IPSEC SAs
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Generating Quick Mode Key!
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, NP encrypt rule look up for crypto map outside_map 20 matching ACL SMART_METERS_DR_VPN: returned cs_id=511a5740; encrypt_rule=09490ac0; tunnelFlow_rule=4ce0a280
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Generating Quick Mode Key!
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, NP encrypt rule look up for crypto map outside_map 20 matching ACL SMART_METERS_DR_VPN: returned cs_id=511a5740; encrypt_rule=09490ac0; tunnelFlow_rule=4ce0a280
Mar 03 14:33:37 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, Security negotiation complete for LAN-to-LAN Group (X.X.X.X) Initiator, Inbound SPI = 0x3f03d9f2, Outbound SPI = 0xa4e68bbd
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, oakley constructing final quick mode
Mar 03 14:33:37 [IKEv1 DECODE]Group = X.X.X.X, IP = X.X.X.X, IKE Initiator sending 3rd QM pkt: msg id = 3e3bd831
Mar 03 14:33:37 [IKEv1]IP = X.X.X.X, IKE_DECODE SENDING Message (msgid=3e3bd831) with payloads : HDR + HASH (8) + NONE (0) total length : 76
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, IKE got a KEY_ADD msg for SA: SPI = 0xa4e68bbd
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Pitcher: received KEY_UPDATE, spi 0x3f03d9f2
Mar 03 14:33:37 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Starting P2 rekey timer: 27360 seconds.
Mar 03 14:33:37 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, PHASE 2 COMPLETED (msgid=3e3bd831)

Mar 03 14:33:40 [IKEv1]IKE Receiver: Packet received on Y.Y.Y.Y:500 from X.X.X.X:500
Mar 03 14:33:40 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, Duplicate Phase 2 packet detected. Retransmitting last packet.
Mar 03 14:33:40 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, Initiator resending lost, last msg
Mar 03 14:33:40 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Starting P2 rekey timer: 27356 seconds.
Mar 03 14:33:40 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, PHASE 2 COMPLETED (msgid=3e3bd831)
Mar 03 14:33:42 [IKEv1]IKE Receiver: Packet received on Y.Y.Y.Y:500 from 87.127.237.146:500

Mar 03 14:33:44 [IKEv1]IKE Receiver: Packet received on Y.Y.Y.Y:500 from X.X.X.X:500
Mar 03 14:33:44 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, Duplicate Phase 2 packet detected. Retransmitting last packet.
Mar 03 14:33:44 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, Initiator resending lost, last msg
Mar 03 14:33:44 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Starting P2 rekey timer: 27353 seconds.
Mar 03 14:33:44 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, PHASE 2 COMPLETED (msgid=3e3bd831)
Mar 03 14:33:46 [IKEv1]IKE Receiver: Packet received on Y.Y.Y.Y:500 from X.X.X.X:500
Mar 03 14:33:46 [IKEv1]IP = X.X.X.X, IKE_DECODE RECEIVED Message (msgid=853b7701) with payloads : HDR + HASH (8) + DELETE (12) + NONE (0) total length : 68
Mar 03 14:33:46 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing hash payload
Mar 03 14:33:46 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing delete
Mar 03 14:33:46 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, Connection terminated for peer X.X.X.X. Reason: Peer Terminate Remote Proxy 172.16.224.0, Local Proxy 10.1.201.4
Mar 03 14:33:46 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Active unit receives a delete event for remote peer X.X.X.X.

Mar 03 14:33:46 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, IKE Deleting SA: Remote Proxy 172.16.224.0, Local Proxy 10.1.201.4
Mar 03 14:33:46 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, IKE SA MM:c0004c0e rcv'd Terminate: state MM_ACTIVE flags 0x00008062, refcnt 1, tuncnt 0
Mar 03 14:33:46 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, IKE SA MM:c0004c0e terminating: flags 0x01008022, refcnt 0, tuncnt 0
Mar 03 14:33:46 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, sending delete/delete with reason message
Mar 03 14:33:46 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing blank hash payload
Mar 03 14:33:46 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing IKE delete payload
Mar 03 14:33:46 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, constructing qm hash payload
Mar 03 14:33:46 [IKEv1]IP = X.X.X.X, IKE_DECODE SENDING Message (msgid=28266a62) with payloads : HDR + HASH (8) + DELETE (12) + NONE (0) total length : 80
Mar 03 14:33:46 [IKEv1 DEBUG]Pitcher: received key delete msg, spi 0x3f03d9f2
Mar 03 14:33:46 [IKEv1 DEBUG]Pitcher: received key delete msg, spi 0x3f03d9f2
Mar 03 14:33:46 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, Session is being torn down. Reason: User Requested
Mar 03 14:33:46 [IKEv1]Ignoring msg to mark SA with dsID 153333760 dead because SA deleted

Mar 03 14:34:00 [IKEv1]IKE Receiver: Packet received on Y.Y.Y.Y:500 from X.X.X.X:500
Mar 03 14:34:00 [IKEv1]IP = X.X.X.X, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + NONE (0) total length : 108
Mar 03 14:34:00 [IKEv1 DEBUG]IP = X.X.X.X, processing SA payload
Mar 03 14:34:00 [IKEv1]Phase 1 failure: Mismatched attribute types for class Group Description: Rcv'd: Group 2 Cfg'd: Group 5
Mar 03 14:34:00 [IKEv1]Phase 1 failure: Mismatched attribute types for class Group Description: Rcv'd: Group 2 Cfg'd: Group 5
Mar 03 14:34:00 [IKEv1 DEBUG]IP = X.X.X.X, Oakley proposal is acceptable
Mar 03 14:34:00 [IKEv1 DEBUG]IP = X.X.X.X, processing VID payload
Mar 03 14:34:00 [IKEv1 DEBUG]IP = X.X.X.X, Received DPD VID
Mar 03 14:34:00 [IKEv1 DEBUG]IP = X.X.X.X, processing IKE SA payload
Mar 03 14:34:00 [IKEv1]Phase 1 failure: Mismatched attribute types for class Group Description: Rcv'd: Group 2 Cfg'd: Group 5
Mar 03 14:34:00 [IKEv1]Phase 1 failure: Mismatched attribute types for class Group Description: Rcv'd: Group 2 Cfg'd: Group 5
Mar 03 14:34:00 [IKEv1 DEBUG]IP = X.X.X.X, IKE SA Proposal # 1, Transform # 1 acceptable Matches global IKE entry # 8
Mar 03 14:34:00 [IKEv1 DEBUG]IP = X.X.X.X, constructing ISAKMP SA payload
Mar 03 14:34:00 [IKEv1 DEBUG]IP = X.X.X.X, constructing Fragmentation VID + extended capabilities payload
Mar 03 14:34:00 [IKEv1]IP = X.X.X.X, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + NONE (0) total length : 108
Mar 03 14:34:00 [IKEv1]IKE Receiver: Packet received on Y.Y.Y.Y:500 from X.X.X.X:500

So phase 2 seems to complete and then goes down after receiving a delete event. I am also looking at the phase 1 failure message. Configured shopuld be group 5 and not group 2. I have multiple ike policies and would expect the correct one to be chosen automatically

[Aditya Ganjoo · Accepted solution]

Hi,

Could you please share the relevant VPN config of both the sides ?

It seems there is a config mismatch on either end.

WatchGuard is failing at Phase 1 and it reports a delete event from ASA:

<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)Received an inform delete message from Y.Y.Y.Y:500
<158>Mar 3 19:07:53 iked[1497]: (X.X.X.X<->Y.Y.Y.Y)Process DELETE payload: try to delete Isakmp SA (numSPI 1)

Even on ASA we see Phase 1 failure:

Mar 03 14:34:00 [IKEv1]Phase 1 failure: Mismatched attribute types for class Group Description: Rcv'd: Group 2 Cfg'd: Group 5
Mar 03 14:34:00 [IKEv1]Phase 1 failure: Mismatched attribute types for class Group Description: Rcv'd: Group 2 Cfg'd: Group 5

Regards,

Aditya

Please rate helpful posts.

[Mokhalil82]

Hi I have managed to get to the bottom of the issue, it was a config mismatch. My VPN access list was restricted to certain ports whereas the watchguard was allowing IP which caused the issue, although I did request only certain ports to be configured on the VPN ACL.

Thanks for all the help guys

[Dinesh Moudgil]

Thanks for sharing the root cause,Mokhalil82

Adding on top of this, it is recommended that you use IP based crypto access-list and then use VPN filter to restrict traffic to certain specific ports.

Here is an example for your reference:-
http://www.cisco.com/c/en/us/support/docs/security/pix-500-series-security-appliances/99103-pix-asa-vpn-filter.html

Regards,
Dinesh Moudgil

P.S. Please rate helpful posts.

[Aditya Ganjoo]

Hi,

Could you also share the version info of the ASA ?

Regards,

Aditya

[Dinesh Moudgil]

Looking at the debugs

Mar 01 07:18:22 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, PHASE 2 COMPLETED (msgid=6c94f062)

The phase 2 gets completed. After this, we see another packet from remte side so our ASA tries to resend last packet.

Mar 01 07:18:26 [IKEv1]IKE Receiver: Packet received on Y.Y.Y.Y:500 from X.X.X.X:500
Mar 01 07:18:26 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, Duplicate Phase 2 packet detected. Retransmitting last packet.

Then we see another message from remote side , where it sends delete message,

Mar 01 07:18:31 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing hash payload
Mar 01 07:18:31 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, processing delete
Mar 01 07:18:31 [IKEv1]Group = X.X.X.X, IP = X.X.X.X, Connection terminated for peer X.X.X.X. Reason: Peer Terminate Remote Proxy 10.1.201.4, Local Proxy 172.16.224.0
Mar 01 07:18:31 [IKEv1 DEBUG]Group = X.X.X.X, IP = X.X.X.X, Active unit receives a delete event for remote peer X.X.X.X.

can you please confirm with remote side why we see a delete message?

Regards,
Dinesh Moudgil

P.S. please rate helpful posts.