Cisco – IPSec failure with `IKE message failed its sanity check or is malformed`

ciscoipsec

I've been battling with my IPSec configuration for some days (with foolish deadline looming) and would like to ask for help with it failing its initial connection.

It's designed as client-to-router spokes with Cisco router at the centre, various devices (eventually) as the spokes.

Key exchange appears to work
Connection fails with %CRYPTO-4-IKMP_BAD_MESSAGE: IKE message from 1.2.3.22 failed its sanity check or is malformed
Retransmission and doom thereafter
UDP ports 500 and 4500 known to traverse network

The goal is to get client attached under R3 with IP traffic to server.

              172.30.20/24      
      ==+=========+=======
        |         |
        R3       server 
        |           
        |172.29.20.128...
      client

The transport network looks like this:

                 isp----------isp
                  |1.2.3.22    |2.3.4.30
                  R1(nat)      R2(nat)          
    192.168.0/24  |            |    172.30.20/24          
      ==+====+====+===       ==+====+====+====+==
        |    |                      |    |    |
        AP   U1                     R3   U2   server
        |
      client

client is an iphone on wifi under very conventional hotel/office-style NAT network under R1 (sanitised to 1.2.3.22)
R2 (sanitised to 2.3.4.30) is doing NAT with port forwarding to R3
R3 debug and monitor capture
U1 and U2 convenient Unix hosts for verifying packet transfer etc

R2 Configuration

R2 is Cisco 867VAE-K9 running c860vae-advsecurityk9-mz.153-2.T.bin

interface Vlan1
 ip address 172.30.20.254 255.255.255.0
 ip nat inside
interface Vlan87
 ip address 2.3.4.30 255.255.255.252
 ip nat outside
ip nat inside source list NAT interface Vlan87 overload
ip nat inside source static esp 172.30.20.252 interface Vlan87
ip nat inside source static udp 172.30.20.252 500 interface Vlan87 500
ip nat inside source static udp 172.30.20.252 4500 interface Vlan87 4500
ip access-list standard NAT
 permit 172.30.20.0 0.0.0.255
ip route 0.0.0.0 0.0.0.0 2.3.4.29

R3 Configuration

R3 is Cisco 867VAE-K9 running c860vae-advsecurityk9-mz.152-4.M3.bin

aaa authentication login VPN_CLIENT_LOGIN local
aaa authorization network VPN_CLIENT_GROUP local 
username vpnuser password 0 *secret1*
!
crypto isakmp policy 10
 encr aes 256
 hash sha512
 authentication pre-share
 group 14
crypto isakmp key *secret2* address 0.0.0.0        
!
crypto isakmp client configuration group VPN_CLIENTS
 key *secret3*
 dns 8.8.8.8
 domain example.local
 pool VPN_CLIENT_POOL
 acl 110
!
crypto ipsec transform-set TS esp-aes 256 esp-sha512-hmac 
 mode tunnel
!
crypto dynamic-map VPNDYNAMIC 10
 set transform-set TS 
!
crypto map DYNMAP client authentication list VPN_CLIENT_LOGIN
crypto map DYNMAP isakmp authorization list VPN_CLIENT_GROUP
crypto map DYNMAP client configuration address respond
crypto map DYNMAP 10 ipsec-isakmp dynamic VPNDYNAMIC 
!
interface GigabitEthernet1
 ip address 172.30.20.252 255.255.255.0
 crypto map DYNMAP
!
ip local pool VPN_CLIENT_POOL 172.29.20.128 172.29.20.254
!
ip route 0.0.0.0 0.0.0.0 172.30.20.254
!
access-list 110 permit ip 172.30.20.0 0.0.0.255 172.29.20.0 0.0.0.255

Client configuration

client is Apple iphone 5.2 running IOS 10.3.

VPN config
Type IPSec
Server 2.3.4.30
Account vpnuser
Password secret1
Use certificate No
Group Name blank
Secret secret2

ANNOTATED DEBUG

Following is on R3 output of debug crypto isakmp, with interspersed output of monitor capture matching all UDP to 1.2.3.22 (exported as pcap and displayed with tcpdump)

Jul 14 12:10:47.776: %BUFCAP-6-ENABLE: Capture Point POINT1 enabled.
       12:10:58.312750 IP 1.2.3.22.500 > 172.30.20.252.500: isakmp: phase 1 I ident
Jul 14 12:10:58.315: ISAKMP (0): received packet from 1.2.3.22 dport 500 sport 500 Global (N) NEW SA
Jul 14 12:10:58.315: ISAKMP: Created a peer struct for 1.2.3.22, peer port 500
Jul 14 12:10:58.315: ISAKMP: New peer created peer = 0x86E4DCB0 peer_handle = 0x8000000D
Jul 14 12:10:58.315: ISAKMP: Locking peer struct 0x86E4DCB0, refcount 1 for crypto_isakmp_process_block
Jul 14 12:10:58.315: ISAKMP:(0):Setting client config settings 86C03770
Jul 14 12:10:58.315: ISAKMP:(0):(Re)Setting client xauth list  and state
Jul 14 12:10:58.315: ISAKMP/xauth: initializing AAA request
Jul 14 12:10:58.319: ISAKMP: local port 500, remote port 500
Jul 14 12:10:58.319: ISAKMP:(0):insert sa successfully sa = 84C4E0E0
Jul 14 12:10:58.319: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
Jul 14 12:10:58.319: ISAKMP:(0):Old State = IKE_READY  New State = IKE_R_MM1 

Jul 14 12:10:58.319: ISAKMP:(0): processing SA payload. message ID = 0
Jul 14 12:10:58.319: ISAKMP:(0): processing vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID seems Unity/DPD but major 69 mismatch
Jul 14 12:10:58.319: ISAKMP (0): vendor ID is NAT-T RFC 3947
Jul 14 12:10:58.319: ISAKMP:(0): processing vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID seems Unity/DPD but major 198 mismatch
Jul 14 12:10:58.319: ISAKMP:(0): processing vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID seems Unity/DPD but major 29 mismatch
Jul 14 12:10:58.319: ISAKMP:(0): processing vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID seems Unity/DPD but major 245 mismatch
Jul 14 12:10:58.319: ISAKMP (0): vendor ID is NAT-T v7
Jul 14 12:10:58.319: ISAKMP:(0): processing vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID seems Unity/DPD but major 114 mismatch
Jul 14 12:10:58.319: ISAKMP:(0): processing vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID seems Unity/DPD but major 227 mismatch
Jul 14 12:10:58.319: ISAKMP:(0): processing vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID seems Unity/DPD but major 250 mismatch
Jul 14 12:10:58.319: ISAKMP:(0): processing vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID seems Unity/DPD but major 157 mismatch
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID is NAT-T v3
Jul 14 12:10:58.319: ISAKMP:(0): processing vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID seems Unity/DPD but major 164 mismatch
Jul 14 12:10:58.319: ISAKMP:(0): processing vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID seems Unity/DPD but major 123 mismatch
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID is NAT-T v2
Jul 14 12:10:58.319: ISAKMP:(0): processing vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID seems Unity/DPD but major 242 mismatch
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID is XAUTH
Jul 14 12:10:58.319: ISAKMP:(0): processing vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID is Unity
Jul 14 12:10:58.319: ISAKMP:(0): processing vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0): processing IKE frag vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0):Support for IKE Fragmentation not enabled
Jul 14 12:10:58.319: ISAKMP:(0): processing vendor id payload
Jul 14 12:10:58.319: ISAKMP:(0): vendor ID is DPD
Jul 14 12:10:58.319: ISAKMP:(0):found peer pre-shared key matching 1.2.3.22
Jul 14 12:10:58.319: ISAKMP:(0): local preshared key found
Jul 14 12:10:58.319: ISAKMP:(0): Authentication by xauth preshared
Jul 14 12:10:58.319: ISAKMP:(0):Checking ISAKMP transform 1 against priority 10 policy
mismatches deleted ISAKMP:(0):Hash algorithm offered does not match policy!
Jul 14 12:10:58.323: ISAKMP:(0):Checking ISAKMP transform 4 against priority 10 policy
Jul 14 12:10:58.323: ISAKMP:      life type in seconds
Jul 14 12:10:58.323: ISAKMP:      life duration (basic) of 3600
Jul 14 12:10:58.323: ISAKMP:      encryption AES-CBC
Jul 14 12:10:58.323: ISAKMP:      keylength of 256
Jul 14 12:10:58.323: ISAKMP:      auth XAUTHInitPreShared
Jul 14 12:10:58.323: ISAKMP:      hash SHA512
Jul 14 12:10:58.323: ISAKMP:      default group 14
Jul 14 12:10:58.323: ISAKMP:(0):atts are acceptable. Next payload is 3
Jul 14 12:10:58.323: ISAKMP:(0):Acceptable atts:actual life: 86400
Jul 14 12:10:58.323: ISAKMP:(0):Acceptable atts:life: 0
Jul 14 12:10:58.323: ISAKMP:(0):Basic life_in_seconds:3600
Jul 14 12:10:58.323: ISAKMP:(0):Returning Actual lifetime: 3600
Jul 14 12:10:58.323: ISAKMP:(0)::Started lifetime timer: 3600.

       12:10:58.536748 IP 172.30.20.252.500 > 1.2.3.22.500: isakmp: phase 1 R ident
Jul 14 12:10:58.539: ISAKMP (0): vendor ID is NAT-T RFC 3947
Jul 14 12:10:58.539: ISAKMP (0): vendor ID is NAT-T v7
Jul 14 12:10:58.539: ISAKMP:(0): vendor ID is NAT-T v3
Jul 14 12:10:58.539: ISAKMP:(0): vendor ID is NAT-T v2
Jul 14 12:10:58.539: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
Jul 14 12:10:58.539: ISAKMP:(0):Old State = IKE_R_MM1  New State = IKE_R_MM1 

Jul 14 12:10:58.539: ISAKMP:(0): constructed NAT-T vendor-rfc3947 ID
Jul 14 12:10:58.539: ISAKMP:(0): sending packet to 1.2.3.22 my_port 500 peer_port 500 (R) MM_SA_SETUP
Jul 14 12:10:58.539: ISAKMP:(0):Sending an IKE IPv4 Packet.
Jul 14 12:10:58.539: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
Jul 14 12:10:58.539: ISAKMP:(0):Old State = IKE_R_MM1  New State = IKE_R_MM2 

       12:10:58.932745 IP 1.2.3.22.500 > 172.30.20.252.500: isakmp: phase 1 I ident
Jul 14 12:10:58.935: ISAKMP (0): received packet from 1.2.3.22 dport 500 sport 500 Global (R) MM_SA_SETUP
Jul 14 12:10:58.935: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
Jul 14 12:10:58.935: ISAKMP:(0):Old State = IKE_R_MM2  New State = IKE_R_MM3 

Jul 14 12:10:58.935: ISAKMP:(0): processing KE payload. message ID = 0
       12:10:59.216750 IP 172.30.20.252.500 > 1.2.3.22.500: isakmp: phase 1 R ident
Jul 14 12:10:59.219: ISAKMP:(0): processing NONCE payload. message ID = 0
Jul 14 12:10:59.219: ISAKMP:(0):found peer pre-shared key matching 1.2.3.22
Jul 14 12:10:59.219: ISAKMP:received payload type 20
Jul 14 12:10:59.219: ISAKMP (1008): NAT found, both nodes inside NAT
Jul 14 12:10:59.219: ISAKMP:received payload type 20
Jul 14 12:10:59.219: ISAKMP (1008): NAT found, both nodes inside NAT
Jul 14 12:10:59.219: ISAKMP:(1008):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
Jul 14 12:10:59.219: ISAKMP:(1008):Old State = IKE_R_MM3  New State = IKE_R_MM3 

Jul 14 12:10:59.219: ISAKMP:(1008): sending packet to 1.2.3.22 my_port 500 peer_port 500 (R) MM_KEY_EXCH
Jul 14 12:10:59.219: ISAKMP:(1008):Sending an IKE IPv4 Packet.
Jul 14 12:10:59.219: ISAKMP:(1008):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
Jul 14 12:10:59.219: ISAKMP:(1008):Old State = IKE_R_MM3  New State = IKE_R_MM4 

       12:10:59.536748 IP 1.2.3.22.4500 > 172.30.20.252.4500: NONESP-encap: isakmp: phase 1 I ident[E]

Jul 14 12:10:59.543: ISAKMP (1008): received packet from 1.2.3.22 dport 4500 sport 4500 Global (R) MM_KEY_EXCH
Jul 14 12:10:59.543: ISAKMP: reserved not zero on ID payload!
Jul 14 12:10:59.543: %CRYPTO-4-IKMP_BAD_MESSAGE: IKE message from 1.2.3.22 failed its sanity check or is malformed
Jul 14 12:10:59.543: ISAKMP (1008): incrementing error counter on sa, attempt 1 of 5: reset_retransmission

NOTE 1 SECOND GAP
       12:11:00.540748 IP 172.30.20.252.500 > 1.2.3.22.500: isakmp: phase 1 R ident

Jul 14 12:11:00.543: ISAKMP:(1008): retransmitting phase 1 MM_KEY_EXCH...
Jul 14 12:11:00.543: ISAKMP (1008): incrementing error counter on sa, attempt 2 of 5: retransmit phase 1
Jul 14 12:11:00.543: ISAKMP:(1008): retransmitting phase 1 MM_KEY_EXCH
Jul 14 12:11:00.543: ISAKMP:(1008): sending packet to 1.2.3.22 my_port 500 peer_port 500 (R) MM_KEY_EXCH
Jul 14 12:11:00.543: ISAKMP:(1008):Sending an IKE IPv4 Packet.
       12:11:00.736746 IP 1.2.3.22.4500 > 172.30.20.252.4500: NONESP-encap: isakmp: phase 1 I ident[E]
Jul 14 12:11:00.743: ISAKMP (1008): received packet from 1.2.3.22 dport 4500 sport 4500 Global (R) MM_KEY_EXCH
Jul 14 12:11:00.743: ISAKMP:(1008): phase 1 packet is a duplicate of a previous packet.
retransmissions deleted
Jul 14 12:11:20.059: ISAKMP:(1008):deleting SA reason "Death by retransmission P1" state (R) MM_KEY_EXCH (peer 1.2.3.22)

12:10:59.536748 IP (tos 0x0, ttl 52, id 7631, offset 0, flags [none], proto UDP (17), length 172)
    1.2.3.22.4500 > 172.30.20.252.4500: [udp sum ok] NONESP-encap: isakmp 1.0 msgid 00000000 cookie 362a9b378758c0d1->419c3976368d9f91: phase 1 I ident[E]: [encrypted id]

Very grateful for any pointers.

Best Answer

Answering my own question: the solution was:

Use the correct group name in the client config (VPN_CLIENTS in example)
Use the group's key (secret3) in the client, not the main key (secret2) (latter appears to be extraneous, comment welcome)
Use less noisy debugging (debug crypto ipsec) to identify hash and transform incompatibilities
Get the exact right hashes etc.

Then get the policies and transforms right for this client, by reading the failures is good detail, and then reading them again.

Solution worked identically for "Cisco IPSec" VPN on a Macintosh running OSX 10.13.

Client changes

Account vpnuser
Password secret1
Group Name VPN_CLIENTS
Secret secret3

R3 changes

crypto isakmp policy 10
 encr aes 256
 hash sha512
 authentication pre-share
 group 14 

crypto ipsec transform-set TS esp-aes 256 esp-sha-hmac

Routes

You've obviously got to get a route from server to client, such as adding on R2:

ip route 172.29.30.0 255.255.255.0 172.30.20.252

Additionally, added reverse-route to R3's group, though it's not clear to me if this is necessary and the exact interactions with the ACL. (Comments welcome).

crypto dynamic-map VPNDYNAMIC 10
 ...
 reverse-route

Many thanks for the errors and debugging messages shown here: https://zeeshannetwork.wordpress.com/2016/12/04/ipsec-part-vii-common-issues-in-phase2/

R2 Configuration

R3 Configuration

Client configuration

ANNOTATED DEBUG

Best Answer

Client changes

R3 changes

Routes

Related Solutions

Cisco – bgp: session with 79.170.119.177 failed (OPEN Message Error : Unsupported Opt Param

Cisco ASA 5505 stop passing traffic randomly

Related Topic