Issue with the DMVPN.

[SampathMuvva]

Hi all,

I am having issue with my DMVPN tunnel. It is in QM_IDLE mode.

Please find the debug logs below. Please advise.

000825: Feb 12 11:40:24.886 IST: ISAKMP: Created a peer struct for 168.65.64.231, peer port 500
000826: Feb 12 11:40:24.886 IST: ISAKMP: New peer created peer = 0x3C662EA8 peer_handle = 0x80020A88
000827: Feb 12 11:40:24.886 IST: ISAKMP: Locking peer struct 0x3C662EA8, refcount 1 for isakmp_initiator
000828: Feb 12 11:40:24.886 IST: ISAKMP: local port 500, remote port 500
000829: Feb 12 11:40:24.886 IST: ISAKMP: set new node 0 to QM_IDLE      
000830: Feb 12 11:40:24.886 IST: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = 2101DA60
000831: Feb 12 11:40:24.886 IST: ISAKMP:(0):Can not start Aggressive mode, trying Main mode.
000832: Feb 12 11:40:24.886 IST: ISAKMP:(0):found peer pre-shared key matching 168.65.64.231
000833: Feb 12 11:40:24.886 IST: ISAKMP:(0): constructed NAT-T vendor-rfc3947 ID
000834: Feb 12 11:40:24.886 IST: ISAKMP:(0): constructed NAT-T vendor-07 ID
000835: Feb 12 11:40:24.886 IST: ISAKMP:(0): constructed NAT-T vendor-03 ID
000836: Feb 12 11:40:24.886 IST: ISAKMP:(0): constructed NAT-T vendor-02 ID
000837: Feb 12 11:40:24.886 IST: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM
000838: Feb 12 11:40:24.886 IST: ISAKMP:(0):Old State = IKE_READY  New State = IKE_I_MM1 

000839: Feb 12 11:40:24.886 IST: ISAKMP:(0): beginning Main Mode exchange
000840: Feb 12 11:40:24.886 IST: ISAKMP:(0): sending packet to 168.65.64.231 my_port 500 peer_port 500 (I) MM_NO_STATE
000841: Feb 12 11:40:24.886 IST: ISAKMP:(0):Sending an IKE IPv4 Packet.
000842: Feb 12 11:40:25.078 IST: ISAKMP (0): received packet from 168.65.64.231 dport 500 sport 500 Global (I) MM_NO_STATE
000843: Feb 12 11:40:25.078 IST: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
000844: Feb 12 11:40:25.078 IST: ISAKMP:(0):Old State = IKE_I_MM1  New State = IKE_I_MM2 

000845: Feb 12 11:40:25.078 IST: ISAKMP:(0): processing SA payload. message ID = 0
000846: Feb 12 11:40:25.078 IST: ISAKMP:(0): processing vendor id payload
000847: Feb 12 11:40:25.078 IST: ISAKMP:(0): vendor ID seems Unity/DPD but major 69 mismatch
000848: Feb 12 11:40:25.078 IST: ISAKMP (0): vendor ID is NAT-T RFC 3947
000849: Feb 12 11:40:25.078 IST: ISAKMP:(0):found peer pre-shared key matching 168.65.64.231
000850: Feb 12 11:40:25.078 IST: ISAKMP:(0): local preshared key found
000851: Feb 12 11:40:25.078 IST: ISAKMP : Scanning profiles for xauth ...
000852: Feb 12 11:40:25.078 IST: ISAKMP:(0):Checking ISAKMP transform 1 against priority 10 policy
000853: Feb 12 11:40:25.078 IST: ISAKMP:      encryption 3DES-CBC
000854: Feb 12 11:40:25.078 IST: ISAKMP:      hash MD5
000855: Feb 12 11:40:25.078 IST: ISAKMP:      default group 2
000856: Feb 12 11:40:25.078 IST: ISAKMP:      auth pre-share
000857: Feb 12 11:40:25.078 IST: ISAKMP:      life type in seconds
000858: Feb 12 11:40:25.078 IST: ISAKMP:      life duration (VPI) of  0x0 0x1 0x51 0x80 
000859: Feb 12 11:40:25.078 IST: ISAKMP:(0):atts are acceptable. Next payload is 0
000860: Feb 12 11:40:25.078 IST: ISAKMP:(0):Acceptable atts:actual life: 0
000861: Feb 12 11:40:25.078 IST: ISAKMP:(0):Acceptable atts:life: 0
000862: Feb 12 11:40:25.078 IST: ISAKMP:(0):Fill atts in sa vpi_length:4
000863: Feb 12 11:40:25.078 IST: ISAKMP:(0):Fill atts in sa life_in_seconds:86400
000864: Feb 12 11:40:25.078 IST: ISAKMP:(0):Returning Actual lifetime: 86400
000865: Feb 12 11:40:25.078 IST: ISAKMP:(0)::Started lifetime timer: 86400.

000866: Feb 12 11:40:25.082 IST: ISAKMP:(0): processing vendor id payload
000867: Feb 12 11:40:25.082 IST: ISAKMP:(0): vendor ID seems Unity/DPD but major 69 mismatch
000868: Feb 12 11:40:25.082 IST: ISAKMP (0): vendor ID is NAT-T RFC 3947
000869: Feb 12 11:40:25.082 IST: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
000870: Feb 12 11:40:25.082 IST: ISAKMP:(0):Old State = IKE_I_MM2  New State = IKE_I_MM2 

000871: Feb 12 11:40:25.082 IST: ISAKMP:(0): sending packet to 168.65.64.231 my_port 500 peer_port 500 (I) MM_SA_SETUP
000872: Feb 12 11:40:25.082 IST: ISAKMP:(0):Sending an IKE IPv4 Packet.
000873: Feb 12 11:40:25.082 IST: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
000874: Feb 12 11:40:25.082 IST: ISAKMP:(0):Old State = IKE_I_MM2  New State = IKE_I_MM3 

000875: Feb 12 11:40:25.258 IST: ISAKMP (0): received packet from 168.65.64.231 dport 500 sport 500 Global (I) MM_SA_SETUP
000876: Feb 12 11:40:25.258 IST: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
000877: Feb 12 11:40:25.258 IST: ISAKMP:(0):Old State = IKE_I_MM3  New State = IKE_I_MM4 

000878: Feb 12 11:40:25.258 IST: ISAKMP:(0): processing KE payload. message ID = 0
000879: Feb 12 11:40:25.278 IST: ISAKMP:(0): processing NONCE payload. message ID = 0
000880: Feb 12 11:40:25.278 IST: ISAKMP:(0):found peer pre-shared key matching 168.65.64.231
000881: Feb 12 11:40:25.278 IST: ISAKMP:(7673): processing vendor id payload
000882: Feb 12 11:40:25.278 IST: ISAKMP:(7673): vendor ID is Unity
000883: Feb 12 11:40:25.278 IST: ISAKMP:(7673): processing vendor id payload
000884: Feb 12 11:40:25.278 IST: ISAKMP:(7673): vendor ID is DPD
000885: Feb 12 11:40:25.278 IST: ISAKMP:(7673): processing vendor id payload
000886: Feb 12 11:40:25.278 IST: ISAKMP:(7673): speaking to another IOS box!
000887: Feb 12 11:40:25.278 IST: ISAKMP:received payload type 20
000888: Feb 12 11:40:25.278 IST: ISAKMP (7673): His hash no match - this node outside NAT
000889: Feb 12 11:40:25.278 IST: ISAKMP:received payload type 20
000890: Feb 12 11:40:25.278 IST: ISAKMP (7673): No NAT Found for self or peer
000891: Feb 12 11:40:25.278 IST: ISAKMP:(7673):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
000892: Feb 12 11:40:25.278 IST: ISAKMP:(7673):Old State = IKE_I_MM4  New State = IKE_I_MM4 
          
000893: Feb 12 11:40:25.278 IST: ISAKMP:(7673):Send initial contact
000894: Feb 12 11:40:25.278 IST: ISAKMP:(7673):SA is doing pre-shared key authentication using id type ID_IPV4_ADDR
000895: Feb 12 11:40:25.278 IST: ISAKMP (7673): ID payload 
        next-payload : 8
        type         : 1 
        address      : 202.56.255.211 
        protocol     : 17 
        port         : 500 
        length       : 12
000896: Feb 12 11:40:25.278 IST: ISAKMP:(7673):Total payload length: 12
000897: Feb 12 11:40:25.278 IST: ISAKMP:(7673): sending packet to 168.65.64.231 my_port 500 peer_port 500 (I) MM_KEY_EXCH
000898: Feb 12 11:40:25.278 IST: ISAKMP:(7673):Sending an IKE IPv4 Packet.
000899: Feb 12 11:40:25.278 IST: ISAKMP:(7673):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
000900: Feb 12 11:40:25.278 IST: ISAKMP:(7673):Old State = IKE_I_MM4  New State = IKE_I_MM5 

000901: Feb 12 11:40:25.446 IST: ISAKMP (7673): received packet from 168.65.64.231 dport 500 sport 500 Global (I) MM_KEY_EXCH
000902: Feb 12 11:40:25.446 IST: ISAKMP:(7673): processing ID payload. message ID = 0
000903: Feb 12 11:40:25.446 IST: ISAKMP (7673): ID payload 
        next-payload : 8
        type         : 1 
        address      : 168.65.64.231 
        protocol     : 17 
        port         : 500 
        length       : 12
000904: Feb 12 11:40:25.446 IST: ISAKMP:(0):: peer matches *none* of the profiles
000905: Feb 12 11:40:25.446 IST: ISAKMP:(7673): processing HASH payload. message ID = 0
000906: Feb 12 11:40:25.446 IST: ISAKMP:(7673):SA authentication status:
        authenticated
000907: Feb 12 11:40:25.446 IST: ISAKMP:(7673):SA has been authenticated with 168.65.64.231
000908: Feb 12 11:40:25.446 IST: ISAKMP: Trying to insert a peer 202.56.255.211/168.65.64.231/500/,  and inserted successfully 3C662EA8.
000909: Feb 12 11:40:25.446 IST: ISAKMP:(7673):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
000910: Feb 12 11:40:25.446 IST: ISAKMP:(7673):Old State = IKE_I_MM5  New State = IKE_I_MM6 

000911: Feb 12 11:40:25.446 IST: ISAKMP:(7673):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
000912: Feb 12 11:40:25.446 IST: ISAKMP:(7673):Old State = IKE_I_MM6  New State = IKE_I_MM6 

000913: Feb 12 11:40:25.446 IST: ISAKMP:(7673):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
000914: Feb 12 11:40:25.446 IST: ISAKMP:(7673):Old State = IKE_I_MM6  New State = IKE_P1_COMPLETE 

000915: Feb 12 11:40:25.446 IST: ISAKMP:(7673):IKE_DPD is enabled, initializing timers
000916: Feb 12 11:40:25.446 IST: ISAKMP:(7673):beginning Quick Mode exchange, M-ID of 1706195204
000917: Feb 12 11:40:25.446 IST: ISAKMP:(7673):QM Initiator gets spi
000918: Feb 12 11:40:25.446 IST: ISAKMP:(7673): sending packet to 168.65.64.231 my_port 500 peer_port 500 (I) QM_IDLE      
000919: Feb 12 11:40:25.446 IST: ISAKMP:(7673):Sending an IKE IPv4 Packet.
000920: Feb 12 11:40:25.446 IST: ISAKMP:(7673):Node 1706195204, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
000921: Feb 12 11:40:25.446 IST: ISAKMP:(7673):Old State = IKE_QM_READY  New State = IKE_QM_I_QM1
000922: Feb 12 11:40:25.446 IST: ISAKMP:(7673):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE
000923: Feb 12 11:40:25.446 IST: ISAKMP:(7673):Old State = IKE_P1_COMPLETE  New State = IKE_P1_COMPLETE 

000924: Feb 12 11:40:25.610 IST: ISAKMP (7673): received packet from 168.65.64.231 dport 500 sport 500 Global (I) QM_IDLE      
000925: Feb 12 11:40:25.610 IST: ISAKMP: set new node 860875375 to QM_IDLE      
000926: Feb 12 11:40:25.610 IST: ISAKMP:(7673): processing HASH payload. message ID = 860875375
000927: Feb 12 11:40:25.610 IST: ISAKMP:(7673): processing DELETE payload. message ID = 860875375
000928: Feb 12 11:40:25.610 IST: ISAKMP:(7673):peer does not do paranoid keepalives.

000929: Feb 12 11:40:25.610 IST: ISAKMP:(7673):deleting node 860875375 error FALSE reason "Informational (in) state 1"
000930: Feb 12 11:40:35.446 IST: ISAKMP:(7673): retransmitting phase 2 QM_IDLE       1706195204 ...
000931: Feb 12 11:40:35.446 IST: ISAKMP (7673): incrementing error counter on node, attempt 1 of 5: retransmit phase 2
000932: Feb 12 11:40:35.446 IST: ISAKMP (7673): incrementing error counter on sa, attempt 1 of 5: retransmit phase 2
000933: Feb 12 11:40:35.446 IST: ISAKMP:(7673): retransmitting phase 2 1706195204 QM_IDLE      
000934: Feb 12 11:40:35.446 IST: ISAKMP:(7673): sending packet to 168.65.64.231 my_port 500 peer_port 500 (I) QM_IDLE      
000935: Feb 12 11:40:35.446 IST: ISAKMP:(7673):Sending an IKE IPv4 Packet.
000936: Feb 12 11:40:44.886 IST: ISAKMP:(7672):purging node -1350985705
000937: Feb 12 11:40:44.886 IST: ISAKMP:(7672):purging node -1192339487
000938: Feb 12 11:40:45.446 IST: ISAKMP:(7673): retransmitting phase 2 QM_IDLE       1706195204 ...
000939: Feb 12 11:40:45.446 IST: ISAKMP (7673): incrementing error counter on node, attempt 2 of 5: retransmit phase 2
000940: Feb 12 11:40:45.446 IST: ISAKMP (7673): incrementing error counter on sa, attempt 2 of 5: retransmit phase 2
000941: Feb 12 11:40:45.446 IST: ISAKMP:(7673): retransmitting phase 2 1706195204 QM_IDLE      
000942: Feb 12 11:40:45.446 IST: ISAKMP:(7673): sending packet to 168.65.64.231 my_port 500 peer_port 500 (I) QM_IDLE      
000943: Feb 12 11:40:45.446 IST: ISAKMP:(7673):Sending an IKE IPv4 Packet.
000944: Feb 12 11:40:54.886 IST: ISAKMP:(7672):purging SA., sa=39E8A984, delme=39E8A984
000945: Feb 12 11:40:55.446 IST: ISAKMP:(7673): retransmitting phase 2 QM_IDLE       1706195204 ...
000946: Feb 12 11:40:55.446 IST: ISAKMP (7673): incrementing error counter on node, attempt 3 of 5: retransmit phase 2
000947: Feb 12 11:40:55.446 IST: ISAKMP (7673): incrementing error counter on sa, attempt 3 of 5: retransmit phase 2
000948: Feb 12 11:40:55.446 IST: ISAKMP:(7673): retransmitting phase 2 1706195204 QM_IDLE      
000949: Feb 12 11:40:55.446 IST: ISAKMP:(7673): sending packet to 168.65.64.231 my_port 500 peer_port 500 (I) QM_IDLE      
000950: Feb 12 11:40:55.446 IST: ISAKMP:(7673):Sending an IKE IPv4 Packet.
000951: Feb 12 11:41:05.446 IST: ISAKMP:(7673): retransmitting phase 2 QM_IDLE       1706195204 ...
000952: Feb 12 11:41:05.446 IST: ISAKMP (7673): incrementing error counter on node, attempt 4 of 5: retransmit phase 2
000953: Feb 12 11:41:05.446 IST: ISAKMP (7673): incrementing error counter on sa, attempt 4 of 5: retransmit phase 2
000954: Feb 12 11:41:05.446 IST: ISAKMP:(7673): retransmitting phase 2 1706195204 QM_IDLE      
000955: Feb 12 11:41:05.446 IST: ISAKMP:(7673): sending packet to 168.65.64.231 my_port 500 peer_port 500 (I) QM_IDLE      
000956: Feb 12 11:41:05.446 IST: ISAKMP:(7673):Sending an IKE IPv4 Packet.
000957: Feb 12 11:41:15.446 IST: ISAKMP:(7673): retransmitting phase 2 QM_IDLE       1706195204 ...
000958: Feb 12 11:41:15.446 IST: ISAKMP (7673): incrementing error counter on node, attempt 5 of 5: retransmit phase 2
000959: Feb 12 11:41:15.446 IST: ISAKMP (7673): incrementing error counter on sa, attempt 5 of 5: retransmit phase 2
000960: Feb 12 11:41:15.446 IST: ISAKMP:(7673): retransmitting phase 2 1706195204 QM_IDLE      
000961: Feb 12 11:41:15.446 IST: ISAKMP:(7673): sending packet to 168.65.64.231 my_port 500 peer_port 500 (I) QM_IDLE      
000962: Feb 12 11:41:15.446 IST: ISAKMP:(7673):Sending an IKE IPv4 Packet.
000963: Feb 12 11:41:15.610 IST: ISAKMP:(7673):purging node 860875375
000964: Feb 12 11:41:16.030 IST: ISAKMP: set new node 0 to QM_IDLE      
000965: Feb 12 11:41:16.030 IST: SA has outstanding requests  (local 33.1.220.44 port 500, remote 33.1.220.16 port 500)
000966: Feb 12 11:41:16.030 IST: ISAKMP:(7673): sitting IDLE. Starting QM immediately (QM_IDLE      )
000967: Feb 12 11:41:16.030 IST: ISAKMP:(7673):beginning Quick Mode exchange, M-ID of 792907629
000968: Feb 12 11:41:16.030 IST: ISAKMP:(7673):QM Initiator gets spi
000969: Feb 12 11:41:16.030 IST: ISAKMP:(7673):peer does not do paranoid keepalives.

000970: Feb 12 11:41:16.030 IST: ISAKMP:(7673):deleting SA reason "Death by retransmission throw" state (I) QM_IDLE       (peer 168.65.64.231)
000971: Feb 12 11:41:16.030 IST: ISAKMP:(7673):Node 792907629, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
000972: Feb 12 11:41:16.030 IST: ISAKMP:(7673):Old State = IKE_QM_READY  New State = IKE_QM_I_QM1
000973: Feb 12 11:41:16.030 IST: ISAKMP: set new node 202449001 to QM_IDLE      
000974: Feb 12 11:41:16.030 IST: ISAKMP:(7673): sending packet to 168.65.64.231 my_port 500 peer_port 500 (I) QM_IDLE      
000975: Feb 12 11:41:16.030 IST: ISAKMP:(7673):Sending an IKE IPv4 Packet.
000976: Feb 12 11:41:16.030 IST: ISAKMP:(7673):purging node 202449001
000977: Feb 12 11:41:16.030 IST: ISAKMP:(7673):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL
000978: Feb 12 11:41:16.030 IST: ISAKMP:(7673):Old State = IKE_P1_COMPLETE  New State = IKE_DEST_SA 

000979: Feb 12 11:41:16.030 IST: ISAKMP:(7673):deleting SA reason "Death by retransmission throw" state (I) QM_IDLE       (peer 168.65.64.231) 
000980: Feb 12 11:41:16.030 IST: ISAKMP: Unlocking peer struct 0x3C662EA8 for isadb_mark_sa_deleted(), count 0
000981: Feb 12 11:41:16.030 IST: ISAKMP: Deleting peer node by peer_reap for 168.65.64.231: 3C662EA8
000982: Feb 12 11:41:16.030 IST: ISAKMP:(7673):deleting node 1706195204 error FALSE reason "IKE deleted"
000983: Feb 12 11:41:16.030 IST: ISAKMP:(7673):deleting node 792907629 error FALSE reason "IKE deleted"
000984: Feb 12 11:41:16.030 IST: ISAKMP:(7673):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
000985: Feb 12 11:41:16.030 IST: ISAKMP:(7673):Old State = IKE_DEST_SA  New State = IKE_DEST_SA 

000986: Feb 12 11:41:16.850 IST: ISAKMP (7673): received packet from 168.65.64.231 dport 500 sport 500 Global (I) MM_NO_STATE

[Nagendra Kumar Nainar]

I think it will be more appropriate to ask this query in Security section.

-Nagendra

[paul driver]

Hello

"peer does not do paranoid keepalives"

Do you have Perfect Forward Secrecy(PFS) enabled one of the tunnels and not the other? If so try disabling it or applying on both sides

res

Paul