certificate protected DMVPN issue CRYPTO-6-IKMP_NOT_ENCRYPTED

[Andrii Oliinyk]

Hi there

i've met something strange with one of tunnel being built from spoke to hub. both hub & spoke hve been enrolled with quite valid certificates from the CA but hub at the end of phase 1 fails packets from spoke.

Here is how debug looks on the hub. Any idea what can be wrong?

Apr 10 12:04:55.618 UTC: ISAKMP-PAK: (73632):received packet from SPOK_EXT_IP dport 4500 sport 4500 Global (R) MM_NO_STATE
Apr 10 12:05:05.620 UTC: ISAKMP-PAK: (73632):received packet from SPOK_EXT_IP dport 4500 sport 4500 Global (R) MM_NO_STATE
Apr 10 12:05:20.568 UTC: ISAKMP-PAK: (0):received packet from SPOK_EXT_IP dport 500 sport 500 Global (N) NEW SA
Apr 10 12:05:20.568 UTC: ISAKMP: (0):Created a peer struct for SPOK_EXT_IP, peer port 500
Apr 10 12:05:20.569 UTC: ISAKMP: (0):New peer created peer = 0x80007FA967F09360 peer_handle = 0x800000008004F89E
Apr 10 12:05:20.569 UTC: ISAKMP: (0):Locking peer struct 0x80007FA967F09360, refcount 1 for crypto_isakmp_process_block
Apr 10 12:05:20.569 UTC: ISAKMP: (0):local port 500, remote port 500
Apr 10 12:05:20.569 UTC: ISAKMP: (0):Find a dup sa in the avl tree during calling isadb_insert sa = 80007FA971B44588
Apr 10 12:05:20.569 UTC: ISAKMP: (0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
Apr 10 12:05:20.569 UTC: ISAKMP: (0):Old State = IKE_READY New State = IKE_R_MM1

Apr 10 12:05:20.569 UTC: ISAKMP: (0):processing SA payload. message ID = 0
Apr 10 12:05:20.569 UTC: ISAKMP: (0):processing vendor id payload
Apr 10 12:05:20.569 UTC: ISAKMP: (0):vendor ID seems Unity/DPD but major 69 mismatch
Apr 10 12:05:20.569 UTC: ISAKMP: (0):vendor ID is NAT-T RFC 3947
Apr 10 12:05:20.569 UTC: ISAKMP: (0):processing vendor id payload
Apr 10 12:05:20.569 UTC: ISAKMP: (0):vendor ID seems Unity/DPD but major 245 mismatch
Apr 10 12:05:20.569 UTC: ISAKMP: (0):vendor ID is NAT-T v7
Apr 10 12:05:20.569 UTC: ISAKMP: (0):processing vendor id payload
Apr 10 12:05:20.569 UTC: ISAKMP: (0):vendor ID seems Unity/DPD but major 157 mismatch
Apr 10 12:05:20.569 UTC: ISAKMP: (0):vendor ID is NAT-T v3
Apr 10 12:05:20.569 UTC: ISAKMP: (0):processing vendor id payload
Apr 10 12:05:20.569 UTC: ISAKMP: (0):vendor ID seems Unity/DPD but major 123 mismatch
Apr 10 12:05:20.569 UTC: ISAKMP: (0):vendor ID is NAT-T v2
Apr 10 12:05:20.569 UTC: ISAKMP: (0):IKE->PKI Get configured TrustPoints state (R) MM_NO_STATE (peer SPOK_EXT_IP)
Apr 10 12:05:20.569 UTC: ISAKMP: (0):PKI->IKE Got configured TrustPoints state (R) MM_NO_STATE (peer SPOK_EXT_IP)
Apr 10 12:05:20.569 UTC: ISAKMP: (0):Checking ISAKMP transform 1 against priority 10 policy
Apr 10 12:05:20.569 UTC: ISAKMP: (0): encryption AES-CBC
Apr 10 12:05:20.569 UTC: ISAKMP: (0): keylength of 128
Apr 10 12:05:20.569 UTC: ISAKMP: (0): hash SHA256
Apr 10 12:05:20.569 UTC: ISAKMP: (0): default group 1
Apr 10 12:05:20.569 UTC: ISAKMP: (0): auth RSA sig
Apr 10 12:05:20.569 UTC: ISAKMP: (0): life type in seconds
Apr 10 12:05:20.569 UTC: ISAKMP: life duration (VPI) of 0x0 0x1 0x51 0x80
Apr 10 12:05:20.569 UTC: ISAKMP: (0):atts are acceptable. Next payload is 0
Apr 10 12:05:20.570 UTC: ISAKMP: (0):Acceptable atts:actual life: 86400
Apr 10 12:05:20.570 UTC: ISAKMP: (0):Acceptable atts:life: 0
Apr 10 12:05:20.570 UTC: ISAKMP: (0):Fill atts in sa vpi_length:4
Apr 10 12:05:20.570 UTC: ISAKMP: (0):Fill atts in sa life_in_seconds:86400
Apr 10 12:05:20.570 UTC: ISAKMP: (0):IKE->PKI Start PKI Session state (R) MM_NO_STATE (peer SPOK_EXT_IP)
Apr 10 12:05:20.570 UTC: ISAKMP: (0):PKI->IKE Started PKI Session state (R) MM_NO_STATE (peer SPOK_EXT_IP)
Apr 10 12:05:20.570 UTC: ISAKMP: (0):Returning Actual lifetime: 86400
Apr 10 12:05:20.570 UTC: ISAKMP: (0):Started lifetime timer: 86400.

Apr 10 12:05:20.571 UTC: ISAKMP: (0):processing vendor id payload
Apr 10 12:05:20.571 UTC: ISAKMP: (0):vendor ID seems Unity/DPD but major 69 mismatch
Apr 10 12:05:20.571 UTC: ISAKMP: (0):vendor ID is NAT-T RFC 3947
Apr 10 12:05:20.571 UTC: ISAKMP: (0):processing vendor id payload
Apr 10 12:05:20.571 UTC: ISAKMP: (0):vendor ID seems Unity/DPD but major 245 mismatch
Apr 10 12:05:20.571 UTC: ISAKMP: (0):vendor ID is NAT-T v7
Apr 10 12:05:20.571 UTC: ISAKMP: (0):processing vendor id payload
Apr 10 12:05:20.572 UTC: ISAKMP: (0):vendor ID seems Unity/DPD but major 157 mismatch
Apr 10 12:05:20.572 UTC: ISAKMP: (0):vendor ID is NAT-T v3
Apr 10 12:05:20.572 UTC: ISAKMP: (0):processing vendor id payload
Apr 10 12:05:20.572 UTC: ISAKMP: (0):vendor ID seems Unity/DPD but major 123 mismatch
Apr 10 12:05:20.572 UTC: ISAKMP: (0):vendor ID is NAT-T v2
Apr 10 12:05:20.572 UTC: ISAKMP: (0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
Apr 10 12:05:20.572 UTC: ISAKMP: (0):Old State = IKE_R_MM1 New State = IKE_R_MM1

Apr 10 12:05:20.572 UTC: ISAKMP: (0):constructed NAT-T vendor-rfc3947 ID
Apr 10 12:05:20.572 UTC: ISAKMP-PAK: (0):sending packet to SPOK_EXT_IP my_port 500 peer_port 500 (R) MM_SA_SETUP
Apr 10 12:05:20.572 UTC: ISAKMP: (0):Sending an IKE IPv4 Packet.
Apr 10 12:05:20.572 UTC: ISAKMP: (0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
Apr 10 12:05:20.572 UTC: ISAKMP: (0):Old State = IKE_R_MM1 New State = IKE_R_MM2

Apr 10 12:05:20.600 UTC: ISAKMP-PAK: (0):received packet from SPOK_EXT_IP dport 500 sport 500 Global (R) MM_SA_SETUP
Apr 10 12:05:20.600 UTC: ISAKMP: (0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
Apr 10 12:05:20.601 UTC: ISAKMP: (0):Old State = IKE_R_MM2 New State = IKE_R_MM3

Apr 10 12:05:20.601 UTC: ISAKMP: (0):processing KE payload. message ID = 0
Apr 10 12:05:20.602 UTC: ISAKMP: (0):processing NONCE payload. message ID = 0
Apr 10 12:05:20.602 UTC: ISAKMP: (73633):processing vendor id payload
Apr 10 12:05:20.602 UTC: ISAKMP: (73633):vendor ID is DPD
Apr 10 12:05:20.602 UTC: ISAKMP: (73633):processing vendor id payload
Apr 10 12:05:20.602 UTC: ISAKMP: (73633):speaking to another IOS box!
Apr 10 12:05:20.602 UTC: ISAKMP: (73633):processing vendor id payload
Apr 10 12:05:20.602 UTC: ISAKMP: (73633):vendor ID seems Unity/DPD but major 149 mismatch
Apr 10 12:05:20.602 UTC: ISAKMP: (73633):vendor ID is XAUTH
Apr 10 12:05:20.602 UTC: ISAKMP: (73633):received payload type 20
Apr 10 12:05:20.602 UTC: ISAKMP: (73633):NAT found, both nodes inside NAT
Apr 10 12:05:20.602 UTC: ISAKMP: (73633):received payload type 20
Apr 10 12:05:20.603 UTC: ISAKMP: (73633):NAT found, both nodes inside NAT
Apr 10 12:05:20.603 UTC: ISAKMP: (73633):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
Apr 10 12:05:20.603 UTC: ISAKMP: (73633):Old State = IKE_R_MM3 New State = IKE_R_MM3

Apr 10 12:05:20.603 UTC: ISAKMP: (73633):IKE->PKI Get configured TrustPoints state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.603 UTC: ISAKMP: (73633):PKI->IKE Got configured TrustPoints state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.603 UTC: ISAKMP: (73633):IKE->PKI Get IssuerNames state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.603 UTC: ISAKMP: (73633):PKI->IKE Got IssuerNames state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.603 UTC: ISAKMP: (73633):constructing CERT_REQ for issuer cn=trust_point-01
Apr 10 12:05:20.603 UTC: ISAKMP: (73633):constructing CERT_REQ for issuer cn=trust_point-02
Apr 10 12:05:20.603 UTC: ISAKMP-PAK: (73633):sending packet to SPOK_EXT_IP my_port 500 peer_port 500 (R) MM_KEY_EXCH
Apr 10 12:05:20.603 UTC: ISAKMP: (73633):Sending an IKE IPv4 Packet.
Apr 10 12:05:20.603 UTC: ISAKMP: (73633):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
Apr 10 12:05:20.603 UTC: ISAKMP: (73633):Old State = IKE_R_MM3 New State = IKE_R_MM4

Apr 10 12:05:20.642 UTC: ISAKMP-PAK: (73633):received packet from SPOK_EXT_IP dport 4500 sport 4500 Global (R) MM_KEY_EXCH
Apr 10 12:05:20.642 UTC: ISAKMP: (73633):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
Apr 10 12:05:20.642 UTC: ISAKMP: (73633):Old State = IKE_R_MM4 New State = IKE_R_MM5

Apr 10 12:05:20.642 UTC: ISAKMP: (73633):processing ID payload. message ID = 0
Apr 10 12:05:20.642 UTC: ISAKMP: (73633):ID payload
next-payload : 6
type : 2
Apr 10 12:05:20.642 UTC: ISAKMP: (73633): FQDN name : SPOK-FQDN
Apr 10 12:05:20.642 UTC: ISAKMP: (73633): protocol : 17
port : 0
length : 32
Apr 10 12:05:20.642 UTC: ISAKMP: (73633):processing CERT payload. message ID = 0
Apr 10 12:05:20.642 UTC: ISAKMP: (73633):processing a CT_X509_SIGNATURE cert
Apr 10 12:05:20.642 UTC: ISAKMP: (73633):IKE->PKI Add peer's certificate state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.642 UTC: ISAKMP: (73633):PKI->IKE Added peer's certificate state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.642 UTC: ISAKMP: (73633):IKE->PKI Get PeerCertificateChain state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.643 UTC: ISAKMP: (73633):PKI->IKE Got PeerCertificateChain state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.643 UTC: ISAKMP: (73633):peer's pubkey isn't cached
Apr 10 12:05:20.643 UTC: ISAKMP: (73633):IKE->PKI Validate certificate chain state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.645 UTC: ISAKMP: (73633):PKI->IKE Validate certificate chain state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.645 UTC: ISAKMP-ERROR: (73633):Unable to get DN from certificate!
Apr 10 12:05:20.645 UTC: ISAKMP: (73633):processing SIG payload. message ID = 0
Apr 10 12:05:20.647 UTC: ISAKMP: (73633):received payload type 17
Apr 10 12:05:20.647 UTC: ISAKMP: (73633):processing NOTIFY INITIAL_CONTACT protocol 1
spi 0, message ID = 0, sa = 0x80007FA971B44588
Apr 10 12:05:20.647 UTC: ISAKMP: (73633):SA authentication status:
authenticated
Apr 10 12:05:20.647 UTC: ISAKMP: (73633):SA has been authenticated with SPOK_EXT_IP
Apr 10 12:05:20.647 UTC: ISAKMP: (73633):Detected port floating to port = 4500
Apr 10 12:05:20.647 UTC: ISAKMP: (73633):Trying to find existing peer HUB-INT-IP/SPOK_EXT_IP/4500/
Apr 10 12:05:20.647 UTC: ISAKMP: (73633):SA authentication status:
authenticated
Apr 10 12:05:20.647 UTC: ISAKMP: (73633):Process initial contact,
bring down existing phase 1 and 2 SA's with local HUB-INT-IP remote SPOK_EXT_IP remote port 4500
Apr 10 12:05:20.647 UTC: ISAKMP: (0):Trying to insert a peer HUB-INT-IP/SPOK_EXT_IP/4500/,
Apr 10 12:05:20.647 UTC: ISAKMP: (0): and inserted successfully 80007FA967F09360.
Apr 10 12:05:20.647 UTC: ISAKMP: (73633):Setting UDP ENC peer struct 0x80007FA971C9BED0 sa= 0x80007FA971B44588
Apr 10 12:05:20.647 UTC: ISAKMP: (73633):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
Apr 10 12:05:20.647 UTC: ISAKMP: (73633):Old State = IKE_R_MM5 New State = IKE_R_MM5

Apr 10 12:05:20.647 UTC: ISAKMP: (73633):processing CERT_REQ payload. message ID = 0
Apr 10 12:05:20.648 UTC: ISAKMP: (73633):peer wants a CT_X509_SIGNATURE cert
Apr 10 12:05:20.648 UTC: ISAKMP: (73633):peer wants cert issued by cn=trust_point-01
Apr 10 12:05:20.648 UTC: ISAKMP: (73633):processing CERT_REQ payload. message ID = 0
Apr 10 12:05:20.648 UTC: ISAKMP: (73633):peer wants a CT_X509_SIGNATURE cert
Apr 10 12:05:20.648 UTC: ISAKMP: (73633):peer wants cert issued by cn=trust_point-02
Apr 10 12:05:20.648 UTC: ISAKMP: (73633):IKE->PKI Get self CertificateChain state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.648 UTC: ISAKMP: (73633):PKI->IKE Got self CertificateChain state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.648 UTC: ISAKMP: (73633):IKE->PKI Get SubjectName state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.648 UTC: ISAKMP: (73633):PKI->IKE Got SubjectName state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.648 UTC: ISAKMP-ERROR: (73633):My ID configured as IPv4 Addr, but Addr not in Cert!
Apr 10 12:05:20.648 UTC: ISAKMP-ERROR: (73633):Using FQDN as My ID
Apr 10 12:05:20.648 UTC: ISAKMP: (73633):SA is doing
Apr 10 12:05:20.648 UTC: ISAKMP: (73633):RSA signature authentication using id type ID_FQDN
Apr 10 12:05:20.648 UTC: ISAKMP: (73633):ID payload
next-payload : 6
type : 2
Apr 10 12:05:20.648 UTC: ISAKMP: (73633): FQDN name : HUB-FQDN
Apr 10 12:05:20.648 UTC: ISAKMP: (73633): protocol : 17
port : 0
length : 31
Apr 10 12:05:20.648 UTC: ISAKMP: (73633):Total payload length: 31
Apr 10 12:05:20.648 UTC: ISAKMP: (73633):IKE->PKI Get CertificateChain to be sent to peer state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.649 UTC: ISAKMP: (73633):PKI->IKE Got CertificateChain to be sent to peer state (R) MM_KEY_EXCH (peer SPOK_EXT_IP)
Apr 10 12:05:20.649 UTC: ISAKMP: (73633):constructing CERT payload for hostname=HUB-FQDN
Apr 10 12:05:20.649 UTC: ISAKMP: (73633):using the trust_point-01 trustpoint's keypair to sign
Apr 10 12:05:20.653 UTC: ISAKMP-PAK: (73633):sending packet to SPOK_EXT_IP my_port 4500 peer_port 4500 (R) MM_KEY_EXCH
Apr 10 12:05:20.653 UTC: ISAKMP: (73633):Sending an IKE IPv4 Packet.
Apr 10 12:05:20.653 UTC: ISAKMP: (73633):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
Apr 10 12:05:20.653 UTC: ISAKMP: (73633):Old State = IKE_R_MM5 New State = IKE_P1_COMPLETE

Apr 10 12:05:20.653 UTC: ISAKMP: (73633):IKE_DPD is enabled, initializing timers
Apr 10 12:05:20.653 UTC: ISAKMP: (73633):IKE->PKI End PKI Session state (R) QM_IDLE (peer SPOK_EXT_IP)
Apr 10 12:05:20.653 UTC: ISAKMP: (73633):PKI->IKE Ended PKI session state (R) QM_IDLE (peer SPOK_EXT_IP)
Apr 10 12:05:20.653 UTC: ISAKMP: (73633):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE
Apr 10 12:05:20.653 UTC: ISAKMP: (73633):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

Apr 10 12:05:20.679 UTC: ISAKMP-PAK: (73633):received packet from SPOK_EXT_IP dport 4500 sport 4500 Global (R) QM_IDLE
Apr 10 12:05:20.680 UTC: %CRYPTO-6-IKMP_NOT_ENCRYPTED: IKE packet from SPOK_EXT_IP was not encrypted and it should've been.
Apr 10 12:05:30.642 UTC: ISAKMP-PAK: (73633):received packet from SPOK_EXT_IP dport 4500 sport 4500 Global (R) QM_IDLE
Apr 10 12:05:30.642 UTC: ISAKMP-PAK-ERROR: (73633):reserved not zero on ID payload!
Apr 10 12:05:30.643 UTC: %CRYPTO-4-IKMP_BAD_MESSAGE: IKE message from SPOK_EXT_IP failed its sanity check or is malformed
Apr 10 12:05:30.643 UTC: ISAKMP: (73633):: incrementing error counter on sa, attempt 1 of 5: reset_retransmission
Apr 10 12:05:31.643 UTC: ISAKMP: (73633):retransmitting phase 1 QM_IDLE ...
Apr 10 12:05:31.643 UTC: ISAKMP: (73633):: incrementing error counter on sa, attempt 2 of 5: retransmit phase 1
Apr 10 12:05:31.643 UTC: ISAKMP: (73633):retransmitting phase 1 QM_IDLE
Apr 10 12:05:31.643 UTC: ISAKMP-PAK: (73633):sending packet to SPOK_EXT_IP my_port 4500 peer_port 4500 (R) QM_IDLE
Apr 10 12:05:31.643 UTC: ISAKMP: (73633):Sending an IKE IPv4 Packet.
Apr 10 12:05:31.669 UTC: ISAKMP-PAK: (73633):received packet from SPOK_EXT_IP dport 4500 sport 4500 Global (R) QM_IDLE
Apr 10 12:05:31.669 UTC: %CRYPTO-6-IKMP_NOT_ENCRYPTED: IKE packet from SPOK_EXT_IP was not encrypted and it should've been.
Apr 10 12:05:37.529 UTC: IPSEC: still in use sa: 0x7FA96C6F3E60
Apr 10 12:05:37.530 UTC: IPSEC(send_delete_notify_kmi): not sending KEY_ENGINE_DELETE_SAS
Apr 10 12:05:40.643 UTC: ISAKMP-PAK: (73633):received packet from SPOK_EXT_IP dport 4500 sport 4500 Global (R) QM_IDLE
Apr 10 12:05:40.643 UTC: ISAKMP-PAK-ERROR: (73633):reserved not zero on ID payload!
Apr 10 12:05:40.643 UTC: ISAKMP: (73633):: incrementing error counter on sa, attempt 3 of 5: reset_retransmission
Apr 10 12:05:41.644 UTC: ISAKMP: (73633):retransmitting phase 1 QM_IDLE ...
Apr 10 12:05:41.644 UTC: ISAKMP: (73633):: incrementing error counter on sa, attempt 4 of 5: retransmit phase 1
Apr 10 12:05:41.644 UTC: ISAKMP: (73633):retransmitting phase 1 QM_IDLE
Apr 10 12:05:41.644 UTC: ISAKMP-PAK: (73633):sending packet to SPOK_EXT_IP my_port 4500 peer_port 4500 (R) QM_IDLE
Apr 10 12:05:41.644 UTC: ISAKMP: (73633):Sending an IKE IPv4 Packet.
Apr 10 12:05:41.671 UTC: ISAKMP-PAK: (73633):received packet from SPOK_EXT_IP dport 4500 sport 4500 Global (R) QM_IDLE
Apr 10 12:05:41.671 UTC: %CRYPTO-6-IKMP_NOT_ENCRYPTED: IKE packet from SPOK_EXT_IP was not encrypted and it should've been.
Apr 10 12:05:46.619 UTC: ISAKMP: (73632):purging SA., sa=80007FA971B7A090, delme=80007FA971B7A090
Apr 10 12:05:50.643 UTC: ISAKMP-PAK: (73633):received packet from SPOK_EXT_IP dport 4500 sport 4500 Global (R) QM_IDLE
Apr 10 12:05:50.643 UTC: ISAKMP-PAK-ERROR: (73633):reserved not zero on ID payload!
Apr 10 12:05:50.643 UTC: ISAKMP: (73633):: incrementing error counter on sa, attempt 5 of 5: reset_retransmission
Apr 10 12:05:51.644 UTC: ISAKMP: (73633):retransmitting phase 1 QM_IDLE ...
Apr 10 12:05:51.644 UTC: ISAKMP-ERROR: (73633):Phase 1 negotiation failed with DPD active; deleting IKE/IPSec SAs
Apr 10 12:05:51.644 UTC: ISAKMP: (73633):peer does not do paranoid keepalives.
Apr 10 12:05:51.644 UTC: ISAKMP-ERROR: (73633):deleting SA reason "Death by retransmission P1" state (R) QM_IDLE (peer SPOK_EXT_IP)
Apr 10 12:05:51.644 UTC: IPSec: Key engine got a KEY_MGR_CHECK_MORE_SAS message
Apr 10 12:05:51.644 UTC: ISAKMP (73633): IPSec has no more SA's with this peer. Won't keepalive phase 1.
Apr 10 12:05:51.644 UTC: ISAKMP: (73633):set new node 2314410054 to QM_IDLE
Apr 10 12:05:51.644 UTC: ISAKMP-PAK: (73633):sending packet to SPOK_EXT_IP my_port 4500 peer_port 4500 (R) QM_IDLE
Apr 10 12:05:51.644 UTC: ISAKMP: (73633):Sending an IKE IPv4 Packet.
Apr 10 12:05:51.644 UTC: ISAKMP: (73633):purging node 2314410054
Apr 10 12:05:51.644 UTC: ISAKMP: (73633):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL
Apr 10 12:05:51.644 UTC: ISAKMP: (73633):Old State = IKE_P1_COMPLETE New State = IKE_DEST_SA

Apr 10 12:05:51.645 UTC: ISAKMP-ERROR: (73633):deleting SA reason "Death by retransmission P1" state (R) QM_IDLE (peer SPOK_EXT_IP)
Apr 10 12:05:51.645 UTC: ISAKMP: (0):Unlocking peer struct 0x80007FA967F09360 for isadb_mark_sa_deleted(), count 0
Apr 10 12:05:51.645 UTC: ISAKMP: (0):Deleting peer node by peer_reap for SPOK_EXT_IP: 80007FA967F09360
Apr 10 12:05:51.645 UTC: ISAKMP: (73633):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
Apr 10 12:05:51.645 UTC: ISAKMP: (73633):Old State = IKE_DEST_SA New State = IKE_DEST_SA

Apr 10 12:06:00.643 UTC: ISAKMP-PAK: (73633):received packet from SPOK_EXT_IP dport 4500 sport 4500 Global (R) MM_NO_STATE
Apr 10 12:06:10.643 UTC: ISAKMP-PAK: (73633):received packet from SPOK_EXT_IP dport 4500 sport 4500 Global (R) MM_NO_STATE

[Rob Ingram]

Hi,

Sounds like this old bug, what IOS version are you running?

Do you still have the same issue if you test using pre-shared key?

[Andrii Oliinyk]

tnx for input. dosnt match my case quite good.
hub is ASR1001-X@16.06.06
spoke is ISR4331/K9@16.06.06
but idea with psk is stiil Ok. i've already been thinking ~it.
will update soon

[Andrii Oliinyk · Accepted solution]

we have 2 ChPs in the middle (1 per each side : hub & this specific spoke). both r NATting hubs & spoke. Hub's side is constatntly operational for tenses of spokes. moreover, ChP on the spoke's side serves another one DMVPN spoke from this branch & this one spoke's connection to hub i pretty operational :0|
the difference between spokes is their external IPs: operational 1st is being NATted with IP from one public subnet & 2nd nonoperational is being NATted with IP from different public subnet. The ChP-box has default route to next-hop from 1st operational subnet. in case of non operational spoke we have asymmetry + below r some findings about this:

[c-nsp] Cisco to Checkpoint VPN
Enno Rey erey at ernw.de
Sat Feb 17 12:51:52 EST 2007
Previous message: [c-nsp] Cisco to Checkpoint VPN
Next message: [c-nsp] Possible causes: [%SYS-3-CONFIG_NO_PRIVATE: No space remaining to save private config] on 3550
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]
hmm... the output below is a typical (IOS) router "debug isakmp" output.
It indicates roughly "main mode message 4 was processed, now going to message 5".
please forgive some theoretic explanation here, could be helpful.
IKE consists of two phases: "phase one" [which can be done in "aggressive mode" (3 messages) and "main mode" (6 messages)] and "phase two" ["quick mode" (3 messages)].
Phase 1 secures the IKE itself, phase 2 secures the following "production IPsec connection".
In phase one these five parameters are important: authentication (PSK/certs), encryption, hash algorithm, dh group, lifetype/time. In phase two the following: mode (tunnel/transport), transforms [which traffic [ACLs on cisco] should be secured how (encyption, hash)], pfs yes/no, lifetime.
The six messages of main mode can be broken down to three bilateral exchanges:
- negotiation of parameters (message 1+2),
- exchange of key stuff for diffie hellman based generation of key material (message 3+4),
- identification/authentication, secured by the key material just generated (message 5+6).

Given this and regarding "message 4" seems to be processed (Old State = IKE_I_MM4 New
> > State = IKE_I_MM5) this would indicate a problem with the PSK. But the cisco message for PSK mismatch is another one ("%CRYPTO-4-IKMP_BAD_MESSAGE: IKE message from 10.1.1.1 failed its sanity check or is malformed" if cisco is responder, if cisco is initiator it's not so easy, usually it's something like

*Feb 8 08:40:11.487: ISAKMP:(1006):Old State = IKE_I_MM4 New State = IKE_I_MM5
*Feb 8 08:40:11.487: ISAKMP (0:1006): received packet from 10.1.1.1 dport 500 sport 500 Global (I) MM_KEY_EXCH
*Feb 8 08:40:11.487: %CRYPTO-6-IKMP_NOT_ENCRYPTED: IKE packet from 10.1.1.1 was not encrypted and it should've been.
")
and he said he checked the PSK several times.

So what can we conclude here:

a) it does not look like a "phase 1" parameter problem, the param negotiation is already successfully done at the time of the debug sniplet.
b) it's not a phase 2 problem (so ACLs do not yet matter). Don't waste your time checking them at this point.

hard to investigate further without additional info. questions:

a) maybe something modifying packets in the path (NAT whatever)?

....