DMVPN - IPSEC packet has invalid spi

[petenixon]

Hi all,

I'm looking for some advice with an issue i'm having with my DMVPN peers. I'm getting, periodically, the following log message on my hub router (ASR 1000) which is causing a BGP flap everytime it happens (which is around every 7-8 hours daily):

%CRYPTO-4-RECVD_PKT_INV_SPI: decaps: rec'd IPSEC packet has invalid spi for destaddr=X.X.X.X, prot=50, spi=0x1F670EE6(526847718), srcaddr=X.X.X.X, input interface=Tunnel402

My initial step was to upgrade the IOS on a spoke router (which was running on old code) which seemed to solve the problem for a day or two, but the problem soon re-occured.

I've ran a debug on the hub router and I think i understand what's happening, but i'm not sure why it's happening:

1. DPD times out and deletes the SA:
Oct 2 09:09:17.464 GMT: ISAKMP:(57964):DPD incrementing error counter (5/5)
Oct 2 09:09:17.464 GMT: ISAKMP:(57964):peer X.X.X.X not responding!
Oct 2 09:09:17.465 GMT: ISAKMP:(57964):peer does not do paranoid keepalives.
Oct 2 09:09:17.465 GMT: ISAKMP:(57964):deleting SA reason "End of ipsec tunnel" state (R) QM_IDLE (peer X.X.X.X)
Oct 2 09:09:17.465 GMT: ISAKMP:(57964):Input = IKE_MESG_FROM_TIMER, IKE_TIMER_PEERS_ALIVE
Oct 2 09:09:17.465 GMT: ISAKMP:(57964):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE
Oct 2 09:09:17.465 GMT: Delete IPsec SA by DPD, local X.X.X.X remote X.X.X.X peer port 49919
Oct 2 09:09:17.465 GMT: IPSEC(delete_sa): SA found saving DEL kmi
Oct 2 09:09:17.466 GMT: ISAKMP: set new node 4281106041 to QM_IDLE
Oct 2 09:09:17.466 GMT: ISAKMP:(57964): sending packet to X.X.X.X my_port 4500 peer_port 49919 (R) QM_IDLE

2. Recieve a packet from the spoke which generates the invalid SPI log message as the SA has been deleted:
Oct  2 09:09:18.131 GMT: %CRYPTO-4-RECVD_PKT_INV_SPI: decaps: rec'd IPSEC packet has invalid spi for destaddr=X.X.X.X, prot=50, spi=0x1F670EE6(526847718), srcaddr=X.X.X.X, input interface=Tunnel402

3. Initial contact for main mode:

Oct 2 09:09:37.522 GMT: ISAKMP (57964): received packet from X.X.X.X dport 4500 sport 49993 DMVPN (R) MM_NO_STATE
Oct 2 09:09:42.522 GMT: ISAKMP (57964): received packet from X.X.X.X dport 4500 sport 49993 DMVPN (R) MM_NO_STATE
Oct 2 09:09:47.522 GMT: ISAKMP (57964): received packet from X.X.X.X dport 4500 sport 49993 DMVPN (R) MM_NO_STATE
Oct 2 09:09:52.521 GMT: ISAKMP (57964): received packet from X.X.X.X dport 4500 sport 49993 DMVPN (R) MM_NO_STATE
Oct 2 09:09:57.521 GMT: ISAKMP (57964): received packet from X.X.X.X dport 4500 sport 49993 DMVPN (R) MM_NO_STATE
Oct 2 09:10:02.523 GMT: ISAKMP (57964): received packet from X.X.X.X dport 4500 sport 49993 DMVPN (R) MM_NO_STATE
Oct 2 09:10:02.524 GMT: ISAKMP (57964): received packet from X.X.X.X dport 4500 sport 49993 DMVPN (R) MM_NO_STATE

Oct 2 09:10:06.611 GMT: ISAKMP: local port 500, remote port 18246
Oct 2 09:10:06.611 GMT: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = 7FBDAE0C3008
Oct 2 09:10:06.611 GMT: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
Oct 2 09:10:06.611 GMT: ISAKMP:(0):Old State = IKE_READY New State = IKE_R_MM1
Oct 2 09:10:06.611 GMT: ISAKMP:(0): processing SA payload. message ID = 0
Oct 2 09:10:06.611 GMT: ISAKMP:(0): processing vendor id payload
Oct 2 09:10:06.611 GMT: ISAKMP:(0): vendor ID seems Unity/DPD but major 69 mismatch
Oct 2 09:10:06.611 GMT: ISAKMP (0): vendor ID is NAT-T RFC 3947
Oct 2 09:10:06.611 GMT: ISAKMP:(0): processing vendor id payload
Oct 2 09:10:06.611 GMT: ISAKMP:(0): vendor ID seems Unity/DPD but major 245 mismatch
Oct 2 09:10:17.468 GMT: ISAKMP:(57964):purging SA., sa=7FBDADB56050, delme=7FBDADB56050

4. BGP peer drops

5. VPN comes up and the BGP peering comes back up.

My current thinking is that there's (possibly) congestion at the spoke site that's causing the problem and increasing the keep-alive may solve the problem as the spoke does respond, although not before the SA is deleted?

Comments and suggestions are welcome.

Thanks.

[Francesco Molino]

Hi

What is your actual config for keepalives?
Have you tried forcing them periodically using the command:
crypro isakmp keepalive <threshold> <retry-interval> {[on-demand] | periodic}

If you have multiple isakmp profile, you can also change the keepalive threshold and retry under the crypto isakmp profile.

What would be interesting is to run a debug on both side and see if the remote end router is sending the reply when the hub says it didn't received it

[petenixon]

Hi Francesco,

Thanks for the reply. Keep-alive value is the same on both peers:

crypto isakmp keepalive 30 5

Unfortunately, we use only the one profile so any changes will affect all the peers. Although, in the grand scheme of things, all the peers are having the same problem so probably won't hurt to try.

It's a good idea with running the debug on the peer router as well as the hub, i think i'll do that first before i change the keepalive value.

Thanks.

[Francesco Molino]

Ok. Let me know after you tried.
Can you try by adding the keyword periodic on your crypto isakmp keepalive. By default, it's on demand.

[drivera_]

Hi Petenixon,

Did you solve your problem? I'm having the same issue and don't know what could it be.

[petenixon]

Hi Diego,

This issue took a great deal of my time and a large part of my sanity!

I tried all the things suggested by Francesco above, as well as upgrading the IOS on the hub and spoke routers, as well as running multiple debugs on both peers but I wasn't able to pin point the cause (I was able to rule out congestion on the spoke router too).

The issue disappeared about two weeks later, which made me suspect an issue in our provider network. However I was unable to prove it, and they didn't admit to any problems (make of that what you will).

I would certainly try the steps taken by myself and suggested by Francesco as your problem may be slightly different from my own.

[Deepak Kumar]

Hi,

I am looking at your message 

Oct 2 09:09:17.464 GMT: ISAKMP:(57964):DPD incrementing error counter (5/5)
Oct 2 09:09:17.464 GMT: ISAKMP:(57964):peer X.X.X.X not responding!
Oct 2 09:09:17.465 GMT: ISAKMP:(57964):peer does not do paranoid keepalives.
Oct 2 09:09:17.465 GMT: ISAKMP:(57964):deleting SA reason "End of ipsec tunnel" state (R) QM_IDLE (peer X.X.X.X)
Oct 2 09:09:17.465 GMT: ISAKMP:(57964):Input = IKE_MESG_FROM_TIMER, IKE_TIMER_PEERS_ALIVE
Oct 2 09:09:17.465 GMT: ISAKMP:(57964):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE
Oct 2 09:09:17.465 GMT: Delete IPsec SA by DPD, local X.X.X.X remote X.X.X.X peer port 49919
Oct 2 09:09:17.465 GMT: IPSEC(delete_sa): SA found saving DEL kmi
Oct 2 09:09:17.466 GMT: ISAKMP: set new node 4281106041 to QM_IDLE
Oct 2 09:09:17.466 GMT: ISAKMP:(57964): sending packet to X.X.X.X my_port 4500 peer_port 49919 (R) QM_IDLE

Can you check your NATing device for any port blocking or traffic dropping? 

Regards,

Deepak Kumar