Buy or Renew
Buy or Renew
Duo Security forums now LIVE! Get answers to all your Duo Security questions. Learn more
cancel
Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
Showing results for 
Search instead for 
Did you mean: 
cancel
Start a conversation
4533
Views
0
Helpful
12
Replies

DMVPN Spoke Issues after migrating dual hub from ISR2 3925 to ASR-1001X

Go to solution
k.carlbark
Beginner
Beginner

‎06-25-2015 05:34 AM - edited ‎02-21-2020 08:18 PM

Hello world,

 

After migrating our dual DMVPN hub solution from ISR2 3925 to ASR-1001X (running asr1001x-universalk9.03.12.03.S.154-2.S3-std.SPA.bin) we started having some issues with spokes tunnels flapping (going up and down) and sometime never come up.

Running 'show dmvpn' the spoke is stuck in NHRP state toward our hub. To resolve the issue we run 'shutdown' and then 'no shutdown' on the tunnel interface of the spoke the DMVPN goes up. Also running 'clear crypto session <remote hub nbma>' on the spoke often solves the problem. So it seems the issue has something to do with IPSEC.

When the problem is occurring and when debugging crypto ipsec, crypto socket, crypto isakmp and crypto engine the following can be seen on the hub:

Jun 25 10:01:41 SUMMERT: ISAKMP:(46580):Sending NOTIFY DPD/R_U_THERE protocol 1
    spi 140130067548488, message ID = 629121681
Jun 25 10:01:41 SUMMERT: ISAKMP:(46580): seq. no 0x64B2238C
Jun 25 10:01:41 SUMMERT: ISAKMP:(46580): sending packet to <spoke nbma> my_port 500 peer_port 500 (I) QM_IDLE
Jun 25 10:01:41 SUMMERT: ISAKMP:(46580):Sending an IKE IPv4 Packet.
Jun 25 10:01:41 SUMMERT: ISAKMP:(46580):purging node 629121681
Jun 25 10:01:41 SUMMERT: ISAKMP:(46580):Input = IKE_MESG_FROM_TIMER, IKE_TIMER_IM_ALIVE
Jun 25 10:01:41 SUMMERT: ISAKMP:(46580):Old State = IKE_P1_COMPLETE  New State = IKE_P1_COMPLETE

Jun 25 10:01:41 SUMMERT: ISAKMP (46580): received packet from <spoke nbma> dport 500 sport 500 ISP1-DMVPN (I) QM_IDLE
Jun 25 10:01:41 SUMMERT: ISAKMP: set new node 3442686097 to QM_IDLE
Jun 25 10:01:41 SUMMERT: ISAKMP:(46580): processing HASH payload. message ID = 3442686097
Jun 25 10:01:41 SUMMERT: ISAKMP:(46580): processing NOTIFY DPD/R_U_THERE_ACK protocol 1
    spi 0, message ID = 3442686097, sa = 0x7F72986867D0
Jun 25 10:01:41 SUMMERT: ISAKMP:(46580): DPD/R_U_THERE_ACK received from peer <spoke nbma>, sequence 0x64B2238C
Jun 25 10:01:41 SUMMERT: ISAKMP:(46580):deleting node 3442686097 error FALSE reason "Informational (in) state 1"
Jun 25 10:01:41 SUMMERT: ISAKMP:(46580):Input = IKE_MESG_FROM_PEER, IKE_INFO_NOTIFY
Jun 25 10:01:41 SUMMERT: ISAKMP:(46580):Old State = IKE_P1_COMPLETE  New State = IKE_P1_COMPLETE
Jun 25 10:01:42 SUMMERT: IPSEC: delete incomplete sa: 0x7F729923A438
Jun 25 10:01:42 SUMMERT: IPSEC(send_delete_notify_kmi): not sending KEY_ENGINE_DELETE_SAS
Jun 25 10:01:42 SUMMERT: ISAKMP:(46580):purging node 1111296046
Jun 25 10:01:44 SUMMERT: ISAKMP (46580): received packet from <spoke nbma> dport 500 sport 500 ISP1-DMVPN (I) QM_IDLE
Jun 25 10:01:44 SUMMERT: ISAKMP: set new node 928225319 to QM_IDLE
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580): processing HASH payload. message ID = 928225319
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580): processing SA payload. message ID = 928225319
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):Checking IPSec proposal 1
Jun 25 10:01:44 SUMMERT: ISAKMP: transform 1, ESP_AES
Jun 25 10:01:44 SUMMERT: ISAKMP:   attributes in transform:
Jun 25 10:01:44 SUMMERT: ISAKMP:      encaps is 2 (Transport)
Jun 25 10:01:44 SUMMERT: ISAKMP:      SA life type in seconds
Jun 25 10:01:44 SUMMERT: ISAKMP:      SA life duration (basic) of 3600
Jun 25 10:01:44 SUMMERT: ISAKMP:      SA life type in kilobytes
Jun 25 10:01:44 SUMMERT: ISAKMP:      SA life duration (VPI) of  0x0 0x46 0x50 0x0
Jun 25 10:01:44 SUMMERT: ISAKMP:      authenticator is HMAC-SHA
Jun 25 10:01:44 SUMMERT: ISAKMP:      key length is 256
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):atts are acceptable.
Jun 25 10:01:44 SUMMERT: CRYPTO_SS(TUNNEL SEC): Active open, socket info: local <hub nbma> <hub nbma>/255.255.255.255/0, remote <spoke nbma> <spoke nbma>/255.255.255.255/0,  prot 47, ifc Tu3300
Jun 25 10:01:44 SUMMERT: IPSEC(recalculate_mtu): reset sadb_root 7F7292E64990 mtu to 1500
Jun 25 10:01:44 SUMMERT: CRYPTO_SS(TUNNEL SEC): Sending Socket Ready message
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580): processing NONCE payload. message ID = 928225319
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580): processing ID payload. message ID = 928225319
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580): processing ID payload. message ID = 928225319
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):QM Responder gets spi
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):Node 928225319, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):Old State = IKE_QM_READY  New State = IKE_QM_SPI_STARVE
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):Node 928225319, Input = IKE_MESG_INTERNAL, IKE_GOT_SPI
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):Old State = IKE_QM_SPI_STARVE  New State = IKE_QM_IPSEC_INSTALL_AWAIT
Jun 25 10:01:44 SUMMERT: IPSEC(crypto_ipsec_sa_find_ident_head): reconnecting with the same proxies and peer <spoke nbma>
Jun 25 10:01:44 SUMMERT: IPSEC(crypto_ipsec_update_ident_tunnel_decap_oce): updating profile-shared Tunnel3300 ident 7F7298B2BF80 with lookup_oce 7F7296BF5440
Jun 25 10:01:44 SUMMERT: IPSEC(create_sa): sa created,
  (sa) sa_dest= <hub nbma>, sa_proto= 50,
    sa_spi= 0x14F40C56(351538262),
    sa_trans= esp-aes 256 esp-sha-hmac , sa_conn_id= 27873
    sa_lifetime(k/sec)= (4608000/3600),
  (identity) local= <hub nbma>:0, remote= <spoke nbma>:0,
    local_proxy= <hub nbma>/255.255.255.255/47/0,
    remote_proxy= <spoke nbma>/255.255.255.255/47/0
Jun 25 10:01:44 SUMMERT: IPSEC(create_sa): sa created,
  (sa) sa_dest= <spoke nbma>, sa_proto= 50,
    sa_spi= 0x3B4731D7(994521559),
    sa_trans= esp-aes 256 esp-sha-hmac , sa_conn_id= 27874
    sa_lifetime(k/sec)= (4608000/3600),
  (identity) local= <hub nbma>:0, remote= <spoke nbma>:0,
    local_proxy= <hub nbma>/255.255.255.255/47/0,
    remote_proxy= <spoke nbma>/255.255.255.255/47/0
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):Received IPSec Install callback... proceeding with the negotiation
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):Successfully installed IPSEC SA (SPI:0x14F40C56) on Tunnel3300
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580): sending packet to <spoke nbma> my_port 500 peer_port 500 (I) QM_IDLE
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):Sending an IKE IPv4 Packet.
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):Node 928225319, Input = IKE_MESG_FROM_IPSEC, IPSEC_INSTALL_DONE
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):Old State = IKE_QM_IPSEC_INSTALL_AWAIT  New State = IKE_QM_R_QM2
Jun 25 10:01:44 SUMMERT: ISAKMP (46580): received packet from <spoke nbma> dport 500 sport 500 ISP1-DMVPN (I) QM_IDLE
Jun 25 10:01:44 SUMMERT: ISAKMP: set new node 1979798297 to QM_IDLE
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580): processing HASH payload. message ID = 1979798297
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580): processing NOTIFY PROPOSAL_NOT_CHOSEN protocol 3
    spi 351538262, message ID = 1979798297, sa = 0x7F72986867D0
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580): deleting spi 351538262 message ID = 928225319
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):deleting node 928225319 error TRUE reason "Delete Larval"
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):peer does not do paranoid keepalives.
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):Enqueued KEY_MGR_DELETE_SAS for IPSEC SA (SPI:0x3B4731D7)
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):deleting node 1979798297 error FALSE reason "Informational (in) state 1"
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):Input = IKE_MESG_FROM_PEER, IKE_INFO_NOTIFY
Jun 25 10:01:44 SUMMERT: ISAKMP:(46580):Old State = IKE_P1_COMPLETE  New State = IKE_P1_COMPLETE
Jun 25 10:01:44 SUMMERT: IPSEC: delete incomplete sa: 0x7F729923A340
Jun 25 10:01:44 SUMMERT: IPSEC(key_engine_delete_sas): delete SA with spi 0x3B4731D7 proto 50 for <spoke nbma>
Jun 25 10:01:44 SUMMERT: IPSEC(update_current_outbound_sa): updated peer <spoke nbma> current outbound sa to SPI 0
Jun 25 10:01:44 SUMMERT: IPSEC(send_delete_notify_kmi): not sending KEY_ENGINE_DELETE_SAS
Jun 25 10:01:44 SUMMERT: CRYPTO_SS(TUNNEL SEC): Sending request for CRYPTO SS CLOSE SOCKET<spoke nbma>

 

#sh pl ha qf ac fe ipsec data drop
------------------------------------------------------------------------
Drop Type  Name                                     Packets
------------------------------------------------------------------------
        3  IN_US_V4_PKT_FOUND_IPSEC_NOT_ENABLED                   127672
       19  IN_OCT_ANTI_REPLAY_FAIL                                 13346
       20  IN_UNEXP_OCT_EXCEPTION                                   4224

       33  OUT_V4_PKT_HIT_IKE_START_SP                              1930

       62  IN_OCT_MAC_EXCEPTION                                        9

#sh plat hard qfp act stat drop | e _0_
-------------------------------------------------------------------------
Global Drop Stats                         Packets                  Octets
-------------------------------------------------------------------------
Disabled                                        1                      82
IpFragErr                                  170536               246635169
IpTtlExceeded                                4072                  343853
IpsecIkeIndicate                             1930                  269694
IpsecInput                                 145256                30071488
Ipv4Acl                                   2251965               215240194
Ipv4Martian                                  6248                  692010
Ipv4NoAdj                                   43188                 7627131
Ipv4NoRoute                                   278                   27913
Ipv4Unclassified                                6                     378
MplsNoRoute                                   790                   69130
MplsUnclassified                                1                      60
ReassTimeout                                   63                   10156
ServiceWireHdrErr                            2684                  585112

 

Also, after running 'logging dmvpn rate-limit 20' on the hub

 

 %DMVPN-3-DMVPN_NHRP_ERROR:  Tunnel292: NHRP Encap Error for  Resolution Request , Reason:  protocol generic error (7) on (Tunnel: <hub-tunnel-ip> NBMA: <hub nbma>)

 

On the spoke at the time the following can be seen from debugging as well:

*Jun 25 09:17:26.884: ISAKMP:(1032): sitting IDLE. Starting QM immediately (QM_IDLE      )
*Jun 25 09:17:26.884: ISAKMP:(1032):beginning Quick Mode exchange, M-ID of 1599359281
*Jun 25 09:17:26.884: ISAKMP:(1032):QM Initiator gets spi
*Jun 25 09:17:26.884: ISAKMP:(1032): sending packet to <hub nbma> my_port 500 peer_port 500 (R) QM_IDLE
*Jun 25 09:17:26.884: ISAKMP:(1032):Sending an IKE IPv4 Packet.
*Jun 25 09:17:26.884: ISAKMP:(1032):Node 1599359281, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
*Jun 25 09:17:26.884: ISAKMP:(1032):Old State = IKE_QM_READY  New State = IKE_QM_I_QM1
*Jun 25 09:17:26.940: ISAKMP (1032): received packet from <hub nbma> dport 500 sport 500 Global (R) QM_IDLE
*Jun 25 09:17:26.940: ISAKMP:(1032): processing HASH payload. message ID = 1599359281
*Jun 25 09:17:26.940: ISAKMP:(1032): processing SA payload. message ID = 1599359281
*Jun 25 09:17:26.940: ISAKMP:(1032):Checking IPSec proposal 1
*Jun 25 09:17:26.940: ISAKMP: transform 1, ESP_AES
*Jun 25 09:17:26.940: ISAKMP:   attributes in transform:
*Jun 25 09:17:26.940: ISAKMP:      encaps is 2 (Transport)