Issue with Cisco IOS XE on ISR4331 with IPSEC vrf aware setup

[zaswadmin]

Hi all,

This is my all time first post here. Sorry for my bad English, it is not my native language. But i hope everything is understandable.

I am at the moment banging my head on the table so to speak due to the fact i am not getting a specific IPSEC configuration working properly.

It concerns a IPSEC vrf aware failover setup in combination with HSRP on Cisco IOS XE routers (ISR4331 - Cisco IOS XE Software, Version 16.06.04) to and i was getting some real unpredictable behavior during implementation like:

- Flapping tunnels between IPSEC router 1 and 2
- Sometimes tunnels would initiate from customer end and terminate OK, but others not (ended in P2 with error 32)
- Could not initiate tunnels myself even though i generated interestic traffic

Anyway, very much disappointment. Especially since I tested everything in advance with GNS3 and classic IOS. Configurations i had in mind worked all fine in virtual lab.

So i made a test setup with the new routers interfaced to each other. Outside interfaces in same IP test segment (10.10.10.0/24) and i wanted to test only one IPSEC tunnel and advance my configuration from there on.

Unfortunately again it works very unpredictable. Sometimes i can initiate the tunnel from router 2 towards router 1, but P2 ends again in error 32. From router 1 i can initiate nothing for some reason. Route for VPN traffic was leaked into customer vrf on both routers.

Reloaded everything to start fresh and now nothing works anymore even though configuration has not changed. Also router 2 does not initiate anything more. Do i miss something very obvious and did i make a mistake? Or am i running into IOS bug or maybe even a hardware issue?

Unfortunately i cannot upgrade the IOS XE yet due to a issue with the customer smart account and smartnet contracts are not linked yet :-( else it would have been my first step. I can hopefully do this next week, but until now i am stuck.

I hope anyone is willing to look into my test setup configurations and check if i made a mistake or am i dealing with soft/hardware issues? I have attached the test configurations were valid to the post.

If you have questions or want some more information just let me know. Happy to provide.

Many thanks in advance!

[Rob Ingram]

Hi,
Is this the full configuration? I see no HSRP standby configuration defined.
Is the topology just a simple P2P VPN between 2 routers? If you could provide a diagram of the solution, that might help.
Can you provide some debug outputs of when the VPN fails to establish please?

IMO you'd be much better off running a VTI configuration, such as FlexVPN - this supports what I believe you are attempting.

HTH

[zaswadmin]

Hi,

Thanks for your reply!

No this is not the full configuration where i started with. Due to the issues i stripped everything to a test setup with one tunnel (P2P) to see if this would work at all.

It did for a while initiate from router 2 generating interesting traffic, but ended in phase 2 with error 32. I do not understand why. From router 1 it does not initiate at all. After a reload it would not work at all anymore. Headed home at that moment.

Thanks by the way for your suggestion of flexvpn, but it concern a migration with existing customer tunnels on classic IOS. So the tunnels still have to work after migration and i therefore do not want to alter to much in this case.

Br.

Some debug output from router 1 during setup initiated from router 2 when it at least made an attempt:

May 29 18:39:46.017: ISAKMP-PAK: (0):received packet from 10.10.10.2 dport 500 sport 500 dmz-outside (N) NEW SA
May 29 18:39:46.017: ISAKMP: (0):Created a peer struct for 10.10.10.2, peer port 500
May 29 18:39:46.017: ISAKMP: (0):New peer created peer = 0x80007FBFC549AB08 peer_handle = 0x8000000080000002
May 29 18:39:46.017: ISAKMP: (0):Locking peer struct 0x80007FBFC549AB08, refcount 1 for crypto_isakmp_process_block
May 29 18:39:46.017: ISAKMP: (0):local port 500, remote port 500
May 29 18:39:46.018: ISAKMP: (0):insert sa successfully sa = 80007FBFC5EA5000
May 29 18:39:46.018: ISAKMP: (0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
May 29 18:39:46.018: ISAKMP: (0):Old State = IKE_READY New State = IKE_R_MM1

May 29 18:39:46.045: ISAKMP: (0):processing SA payload. message ID = 0
May 29 18:39:46.046: ISAKMP: (0):found peer pre-shared key matching 10.10.10.2
May 29 18:39:46.046: ISAKMP: (0):local preshared key found
May 29 18:39:46.046: ISAKMP: (0):Scanning profiles for xauth ... customer-001-nl customer-003-nl customer-007-nl customer-008-nl
May 29 18:39:46.046: ISAKMP: (0):Checking ISAKMP transform 1 against priority 1 policy
May 29 18:39:46.046: ISAKMP: (0): encryption AES-CBC
May 29 18:39:46.046: ISAKMP: (0): keylength of 256
May 29 18:39:46.046: ISAKMP: (0): hash SHA
May 29 18:39:46.046: ISAKMP: (0): default group 5
May 29 18:39:46.046: ISAKMP: (0): auth pre-share
May 29 18:39:46.046: ISAKMP: (0): life type in seconds
May 29 18:39:46.047: ISAKMP: (0): life duration (basic) of 28800
May 29 18:39:46.047: ISAKMP: (0):atts are acceptable. Next payload is 3
May 29 18:39:46.047: ISAKMP: (0):Acceptable atts:actual life: 28800
May 29 18:39:46.047: ISAKMP: (0):Acceptable atts:life: 0
May 29 18:39:46.047: ISAKMP: (0):Basic life_in_seconds:28800
May 29 18:39:46.047: ISAKMP: (0):Returning Actual lifetime: 28800
May 29 18:39:46.047: ISAKMP: (0):Started lifetime timer: 28800.

May 29 18:39:46.058: ISAKMP: (0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
May 29 18:39:46.058: ISAKMP: (0):Old State = IKE_R_MM1 New State = IKE_R_MM1

May 29 18:39:46.058: ISAKMP-PAK: (0):sending packet to 10.10.10.2 my_port 500 peer_port 500 (R) MM_SA_SETUP
May 29 18:39:46.058: ISAKMP: (0):Sending an IKE IPv4 Packet.
May 29 18:39:46.059: ISAKMP: (0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
May 29 18:39:46.059: ISAKMP: (0):Old State = IKE_R_MM1 New State = IKE_R_MM2

May 29 18:39:46.072: ISAKMP-PAK: (0):received packet from 10.10.10.2 dport 500 sport 500 dmz-outside (R) MM_SA_SETUP
May 29 18:39:46.072: ISAKMP: (0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
May 29 18:39:46.072: ISAKMP: (0):Old State = IKE_R_MM2 New State = IKE_R_MM3

May 29 18:39:46.072: ISAKMP: (0):processing KE payload. message ID = 0
May 29 18:39:46.086: ISAKMP: (0):processing NONCE payload. message ID = 0
May 29 18:39:46.086: ISAKMP: (0):found peer pre-shared key matching 10.10.10.2
May 29 18:39:46.086: ISAKMP: (1001):processing vendor id payload
May 29 18:39:46.086: ISAKMP: (1001):vendor ID is DPD
May 29 18:39:46.086: ISAKMP: (1001):processing vendor id payload
May 29 18:39:46.087: ISAKMP: (1001):speaking to another IOS box!
May 29 18:39:46.087: ISAKMP: (1001):processing vendor id payload
May 29 18:39:46.087: ISAKMP: (1001):vendor ID seems Unity/DPD but major 0 mismatch
May 29 18:39:46.087: ISAKMP: (1001):vendor ID is XAUTH
May 29 18:39:46.087: ISAKMP: (1001):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
May 29 18:39:46.087: ISAKMP: (1001):Old State = IKE_R_MM3 New State = IKE_R_MM3

May 29 18:39:46.087: ISAKMP-PAK: (1001):sending packet to 10.10.10.2 my_port 500 peer_port 500 (R) MM_KEY_EXCH
May 29 18:39:46.087: ISAKMP: (1001):Sending an IKE IPv4 Packet.
May 29 18:39:46.087: ISAKMP: (1001):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
May 29 18:39:46.088: ISAKMP: (1001):Old State = IKE_R_MM3 New State = IKE_R_MM4

May 29 18:39:46.112: ISAKMP-PAK: (1001):received packet from 10.10.10.2 dport 500 sport 500 dmz-outside (R) MM_KEY_EXCH
May 29 18:39:46.112: ISAKMP: (1001):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
May 29 18:39:46.112: ISAKMP: (1001):Old State = IKE_R_MM4 New State = IKE_R_MM5

May 29 18:39:46.112: ISAKMP: (1001):processing ID payload. message ID = 0
May 29 18:39:46.113: ISAKMP: (1001):ID payload
next-payload : 8
type : 1
May 29 18:39:46.113: ISAKMP: (1001): address : 10.10.10.2
May 29 18:39:46.113: ISAKMP: (1001): protocol : 17
port : 500
length : 12
May 29 18:39:46.113: ISAKMP: (0):peer matches customer-008-nl profile
May 29 18:39:46.113: ISAKMP: (1001):Found ADDRESS key in keyring customer-008-nl
May 29 18:39:46.113: ISAKMP: (1001):processing HASH payload. message ID = 0
May 29 18:39:46.113: ISAKMP: (1001):received payload type 17
May 29 18:39:46.114: ISAKMP: (1001):processing NOTIFY INITIAL_CONTACT protocol 1
spi 0, message ID = 0, sa = 0x80007FBFC5EA5000
May 29 18:39:46.114: ISAKMP: (1001):SA authentication status:
authenticated
May 29 18:39:46.114: ISAKMP: (1001):SA has been authenticated with 10.10.10.2
May 29 18:39:46.114: ISAKMP: (1001):SA authentication status:
authenticated
May 29 18:39:46.114: ISAKMP: (1001):Process initial contact,
bring down existing phase 1 and 2 SA's with local 10.10.10.1 remote 10.10.10.2 remote port 500
May 29 18:39:46.114: ISAKMP: (0):Trying to insert a peer 10.10.10.1/10.10.10.2/500/dmz-outside,
May 29 18:39:46.114: ISAKMP: (0): and inserted successfully 80007FBFC549AB08.
May 29 18:39:46.114: ISAKMP: (1001):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
May 29 18:39:46.114: ISAKMP: (1001):Old State = IKE_R_MM5 New State = IKE_R_MM5

May 29 18:39:46.115: IPSEC(key_engine): got a queue event with 1 KMI message(s)
May 29 18:39:46.115: ISAKMP: (1001):SA is doing
May 29 18:39:46.115: ISAKMP: (1001):pre-shared key authentication using id type ID_IPV4_ADDR
May 29 18:39:46.115: ISAKMP: (1001):ID payload
next-payload : 8
type : 1
May 29 18:39:46.115: ISAKMP: (1001): address : 10.10.10.1
May 29 18:39:46.115: ISAKMP: (1001): protocol : 17
port : 500
length : 12
May 29 18:39:46.115: ISAKMP: (1001):Total payload length: 12
May 29 18:39:46.115: ISAKMP-PAK: (1001):sending packet to 10.10.10.2 my_port 500 peer_port 500 (R) MM_KEY_EXCH
May 29 18:39:46.115: ISAKMP: (1001):Sending an IKE IPv4 Packet.
May 29 18:39:46.116: ISAKMP: (1001):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
May 29 18:39:46.116: ISAKMP: (1001):Old State = IKE_R_MM5 New State = IKE_P1_COMPLETE

May 29 18:39:46.116: ISAKMP: (1001):IKE_DPD is enabled, initializing timers
May 29 18:39:46.116: ISAKMP: (1001):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE
May 29 18:39:46.116: ISAKMP: (1001):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

May 29 18:39:46.141: ISAKMP-PAK: (1001):received packet from 10.10.10.2 dport 500 sport 500 dmz-outside (R) QM_IDLE
May 29 18:39:46.141: ISAKMP: (1001):set new node 2649488463 to QM_IDLE
May 29 18:39:46.141: ISAKMP: (1001):processing HASH payload. message ID = 2649488463
May 29 18:39:46.141: ISAKMP: (1001):processing SA payload. message ID = 2649488463
May 29 18:39:46.141: ISAKMP: (1001):Checking IPSec proposal 1
May 29 18:39:46.142: ISAKMP: (1001):transform 1, ESP_AES
May 29 18:39:46.142: ISAKMP: (1001): attributes in transform:
May 29 18:39:46.142: ISAKMP: (1001): encaps is 1 (Tunnel)
May 29 18:39:46.142: ISAKMP: (1001): SA life type in seconds
May 29 18:39:46.142: ISAKMP: (1001): SA life duration (basic) of 1800
May 29 18:39:46.142: ISAKMP: (1001): SA life type in kilobytes
May 29 18:39:46.142: ISAKMP: SA life duration (VPI) of 0x0 0x46 0x50 0x0
May 29 18:39:46.142: ISAKMP: (1001): authenticator is HMAC-SHA
May 29 18:39:46.142: ISAKMP: (1001): key length is 256
May 29 18:39:46.142: ISAKMP: (1001): group is 14
May 29 18:39:46.142: ISAKMP: (1001):atts are acceptable.
May 29 18:39:46.142: IPSEC(validate_proposal_request): proposal part #1
May 29 18:39:46.142: IPSEC(validate_proposal_request): proposal part #1,
(key eng. msg.) INBOUND local= 10.10.10.1:0, remote= 10.10.10.2:0,
local_proxy= 192.168.11.0/255.255.255.0/256/0,
remote_proxy= 192.168.22.0/255.255.255.0/256/0,
protocol= ESP, transform= esp-aes 256 esp-sha-hmac (Tunnel),
lifedur= 0s and 0kb,
spi= 0x0(0), conn_id= 0, keysize= 256, flags= 0x0
May 29 18:39:46.143: ISAKMP-ERROR: (1001):IPSec policy invalidated proposal with error 32
May 29 18:39:46.144: ISAKMP-ERROR: (1001):phase 2 SA policy not acceptable! (local 10.10.10.1 remote 10.10.10.2)
May 29 18:39:46.144: ISAKMP: (1001):set new node 260536740 to QM_IDLE
May 29 18:39:46.144: ISAKMP: (1001):Sending NOTIFY PROPOSAL_NOT_CHOSEN protocol 3
spi 9223512498443076336, message ID = 260536740
May 29 18:39:46.144: ISAKMP-PAK: (1001):sending packet to 10.10.10.2 my_port 500 peer_port 500 (R) QM_IDLE
May 29 18:39:46.144: ISAKMP: (1001):Sending an IKE IPv4 Packet.
May 29 18:39:46.145: ISAKMP: (1001):purging node 260536740
May 29 18:39:46.145 UTC: %CRYPTO-5-IPSEC_SETUP_FAILURE: IPSEC SETUP FAILED for local:10.10.10.2 local_id:10.10.10.2 remote:10.10.10.1 remote_id:10.10.10.1 IKE profile:customer-008-nl fvrf:dmz-outside fail_reason:IPSec Proposal failure fail_class_cnt:1
May 29 18:39:46.145: ISAKMP-ERROR: (1001):deleting node 2649488463 error TRUE reason "QM rejected"
May 29 18:39:46.146: ISAKMP: (1001):Node 2649488463, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH
May 29 18:39:46.146: ISAKMP: (1001):Old State = IKE_QM_READY New State = IKE_QM_READY
May 29 18:40:16.040: ISAKMP-PAK: (1001):received packet from 10.10.10.2 dport 500 sport 500 dmz-outside (R) QM_IDLE
May 29 18:40:16.040: ISAKMP: (1001):set new node 578161319 to QM_IDLE
May 29 18:40:16.040: ISAKMP: (1001):processing HASH payload. message ID = 578161319
May 29 18:40:16.040: ISAKMP: (1001):processing SA payload. message ID = 578161319
May 29 18:40:16.041: ISAKMP: (1001):Checking IPSec proposal 1
May 29 18:40:16.041: ISAKMP: (1001):transform 1, ESP_AES
May 29 18:40:16.041: ISAKMP: (1001): attributes in transform:
May 29 18:40:16.041: ISAKMP: (1001): encaps is 1 (Tunnel)
May 29 18:40:16.041: ISAKMP: (1001): SA life type in seconds
May 29 18:40:16.041: ISAKMP: (1001): SA life duration (basic) of 1800
May 29 18:40:16.041: ISAKMP: (1001): SA life type in kilobytes
May 29 18:40:16.041: ISAKMP: SA life duration (VPI) of 0x0 0x46 0x50 0x0
May 29 18:40:16.041: ISAKMP: (1001): authenticator is HMAC-SHA
May 29 18:40:16.041: ISAKMP: (1001): key length is 256
May 29 18:40:16.041: ISAKMP: (1001): group is 14
May 29 18:40:16.041: ISAKMP: (1001):atts are acceptable.
May 29 18:40:16.041: IPSEC(validate_proposal_request): proposal part #1
May 29 18:40:16.042: IPSEC(validate_proposal_request): proposal part #1,
(key eng. msg.) INBOUND local= 10.10.10.1:0, remote= 10.10.10.2:0,
local_proxy= 192.168.11.0/255.255.255.0/256/0,
remote_proxy= 192.168.22.0/255.255.255.0/256/0,
protocol= ESP, transform= esp-aes 256 esp-sha-hmac (Tunnel),
lifedur= 0s and 0kb,
spi= 0x0(0), conn_id= 0, keysize= 256, flags= 0x0
May 29 18:40:16.042: ISAKMP-ERROR: (1001):IPSec policy invalidated proposal with error 32
May 29 18:40:16.043: ISAKMP-ERROR: (1001):phase 2 SA policy not acceptable! (local 10.10.10.1 remote 10.10.10.2)
May 29 18:40:16.043: ISAKMP: (1001):set new node 3760900537 to QM_IDLE
May 29 18:40:16.043: ISAKMP: (1001):Sending NOTIFY PROPOSAL_NOT_CHOSEN protocol 3
spi 9223512498443076336, message ID = 3760900537
May 29 18:40:16.043: ISAKMP-PAK: (1001):sending packet to 10.10.10.2 my_port 500 peer_port 500 (R) QM_IDLE
May 29 18:40:16.043: ISAKMP: (1001):Sending an IKE IPv4 Packet.
May 29 18:40:16.043: ISAKMP: (1001):purging node 3760900537
May 29 18:40:16.044: ISAKMP-ERROR: (1001):deleting node 578161319 error TRUE reason "QM rejected"

[Rob Ingram · Accepted solution]

I tested this in my lab. Tweak your ISAKMP profile to match on the exact address of the peer and then reference the ISAKMP profile in the crypto map. E.g:-

crypto isakmp profile customer-008-nl
 match identity address 10.10.10.2 255.255.255.255 dmz-outside

crypto map IPSEC-VPN 200 ipsec-isakmp
 set isakmp-profile customer-008-nl

HTH

[zaswadmin]

Hi,

Thanks very much for checking my config in your lab, much appreciated! Were you able to test with ios xe in your lab or classic ios?

I must have been tired yesterday, i did not notice the missing link to the isakmp profile in the crypto map at all. But i tried so many things during debug. I quickly made remote access to my test devices and applied your suggested changes. This time again strange behavior. I can now see something happening on router 2 when i initiate from router 1. No tunnel setup, but a strange error:

Ping from router 1:

L-RTM-VPN-RCL-01#ping vrf customer-008-nl 192.168.22.1
Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 192.168.22.1, timeout is 2 seconds:
...

Router 2 with isakmp and ipsec debug enabled:

L-RTM-VPN-RCL-02#
May 30 23:11:48.108 UTC: %IOSXE-3-PLATFORM: SIP1: cpp_cp: QFP:0.0 Thread:000 TS:00000091582327269953 %IPSEC-3-RECVD_PKT_NOT_IPSEC: Rec'd packet not an IPSEC packet, dest_addr= 192.168.22.1, src_addr= 192.168.11.1, prot= 1
May 30 23:13:12.351 UTC: %IOSXE-3-PLATFORM: SIP1: cpp_cp: QFP:0.0 Thread:000 TS:00000091666572599825 %IPSEC-3-RECVD_PKT_NOT_IPSEC: Rec'd packet not an IPSEC packet, dest_addr= 192.168.22.1, src_addr= 192.168.11.1, prot= 1

When i do a ping from router 2 i do not see the error on router 1. It seems it does not do anything.

I am getting more convinced i am running into a bug or a hardware issue. Will try to lookup the error meaning, hopefully it will give me a pointer.

Again thanks, if you have anymore pointers or suggestions, they are very welcome!

Br

[zaswadmin]

Found the mistake on my end.

Typo in crypto map bound to outside interface:

crypto map IPSEC-VPN 200 ipsec-isakmp
 description customer-008-nl
 ...
!
interface GigabitEthernet0/0/0
 description DMZ-outside
 ...
 crypto map VPN-IPSEC
!
end

Traffic arrived therefore unencrypted on other router which recognized it shoudl match a crypto setup due to matching acl.

Following message appears when this happens:

%IPSEC-3-RECVD_PKT_NOT_IPSEC: Rec'd packet not an IPSEC packet

VPN tunnel now works fine!