Re: DMVPN needs reload for tunnel to come up

weedywhizz · ‎01-26-2014

Hi,

I'm having issues getting one of my backup hub routers tunnel come up after 24 hours of connection time.

The router worked nicely before I changed the WAN interface from a switch interface to the WAN interface on my 881. It worked as a trunk with vlan 7 configured for VDSL connected to a modem. Now the modem handles the VLAN and the proper WAN interface is used.

Every 24 hours the the DMVPN turns into "IKE" state and doesn't come up again. I need to reload the router and everything is fine again for 24 hours.

Please give me a hint. I already copied the configuration from my primary hub except some details like IP adresses but still no joy.

I attached the configs of the primary and secondary hub.

A debug crypto isakmp mentions MM_NO_STATE - I will post more tomorrow when the problem occurs again.

Thank you very very much.

Kind regards

weedywhizz · ‎01-28-2014

Ok here's a debug crypto isakmp. It might me important to notice that the primary hub doesn't receive any packets when doing a debug crypto isakmp. But why does it work when restarting the secondary hub ?

Jan 28 22:40:21.694: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...

.Jan 28 22:40:21.694: ISAKMP (0): incrementing error counter on sa, attempt 1 of 5: retransmit phase 1

.Jan 28 22:40:21.694: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE

.Jan 28 22:40:21.694: ISAKMP:(0): sending packet to 87.138.xxx.xxx my_port 500 peer_port 500 (I) MM_NO_STATE

.Jan 28 22:40:21.694: ISAKMP:(0):Sending an IKE IPv4 Packet.

HAM1-RTR#

.Jan 28 22:40:31.694: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...

.Jan 28 22:40:31.694: ISAKMP (0): incrementing error counter on sa, attempt 2 of 5: retransmit phase 1

.Jan 28 22:40:31.694: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE

.Jan 28 22:40:31.694: ISAKMP:(0): sending packet to 87.138.xxx.xxx my_port 500 peer_port 500 (I) MM_NO_STATE

.Jan 28 22:40:31.694: ISAKMP:(0):Sending an IKE IPv4 Packet.

HAM1-RTR#

.Jan 28 22:40:41.694: ISAKMP: set new node 0 to QM_IDLE

.Jan 28 22:40:41.694: ISAKMP:(0):SA is still budding. Attached new ipsec request to it. (local 80.147.yyy.yyy, remote 87.138.xxx.xxx)

.Jan 28 22:40:41.694: ISAKMP: Error while processing SA request: Failed to initialize SA

.Jan 28 22:40:41.694: ISAKMP: Error while processing KMI message 0, error 2.

.Jan 28 22:40:41.694: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...

.Jan 28 22:40:41.694: ISAKMP (0): incrementing error counter on sa, attempt 3 of 5: retransmit phase 1

.Jan 28 22:40:41.694: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE

HAM1-RTR#

.Jan 28 22:40:41.694: ISAKMP:(0): sending packet to 87.138.xxx.xxx my_port 500 peer_port 500 (I) MM_NO_STATE

.Jan 28 22:40:41.694: ISAKMP:(0):Sending an IKE IPv4 Packet.

HAM1-RTR#

.Jan 28 22:40:51.694: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...

.Jan 28 22:40:51.694: ISAKMP (0): incrementing error counter on sa, attempt 4 of 5: retransmit phase 1

.Jan 28 22:40:51.694: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE

.Jan 28 22:40:51.694: ISAKMP:(0): sending packet to 87.138.xxx.xxx my_port 500 peer_port 500 (I) MM_NO_STATE

.Jan 28 22:40:51.694: ISAKMP:(0):Sending an IKE IPv4 Packet.

HAM1-RTR#

.Jan 28 22:40:57.178: ISAKMP:(0):purging node -1327079417

.Jan 28 22:40:57.178: ISAKMP:(0):purging node 461208000

HAM1-RTR#

.Jan 28 22:41:01.694: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...

.Jan 28 22:41:01.694: ISAKMP (0): incrementing error counter on sa, attempt 5 of 5: retransmit phase 1

.Jan 28 22:41:01.694: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE

.Jan 28 22:41:01.694: ISAKMP:(0): sending packet to 87.138.xxx.xxx my_port 500 peer_port 500 (I) MM_NO_STATE

.Jan 28 22:41:01.694: ISAKMP:(0):Sending an IKE IPv4 Packet.

HAM1-RTR#

.Jan 28 22:41:07.178: ISAKMP:(0):purging SA., sa=87BF98C8, delme=87BF98C8

HAM1-RTR#

.Jan 28 22:41:11.694: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...

.Jan 28 22:41:11.694: ISAKMP:(0):peer does not do paranoid keepalives.

.Jan 28 22:41:11.694: ISAKMP:(0):deleting SA reason "Death by retransmission P1" state (I) MM_NO_STATE (peer 87.138.xxx.xxx)

.Jan 28 22:41:11.694: ISAKMP: Unlocking peer struct 0x8D666AF0 for isadb_mark_sa_deleted(), count 0

.Jan 28 22:41:11.694: ISAKMP: Deleting peer node by peer_reap for 87.138.xxx.xxx: 8D666AF0

.Jan 28 22:41:11.694: ISAKMP:(0):deleting node 812459300 error FALSE reason "IKE deleted"

.Jan 28 22:41:11.694: ISAKMP:(0):deleting node -460999307 error FALSE reason "IKE deleted"

.Jan 28 22:41:11.694: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL

.Jan 28 22:41:11.694: ISAKMP:(0):Old State = IKE_I_MM1 New State = IKE_DEST_SA

.Jan 28 22:41:12.006: ISAKMP:(0): SA request profile is DMVPN_SPOKES

.Jan 28 22:41:12.006: ISAKMP: Created a peer struct for 87.138.xxx.xxx, peer port 500

.Jan 28 22:41:12.006: ISAKMP: New peer created peer = 0x8D666AF0 peer_handle = 0x80000039

.Jan 28 22:41:12.006: ISAKMP: Locking peer struct 0x8D666AF0, refcount 1 for isakmp_initiator

.Jan 28 22:41:12.006: ISAKMP: local port 500, remote port 500

.Jan 28 22:41:12.006: ISAKMP: set new node 0 to QM_IDLE

.Jan 28 22:41:12.006: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = 8CEE3E78

.Jan 28 22:41:12.006: ISAKMP:(0):Can not start Aggressive mode, trying Main mode.

.Jan 28 22:41:12.006: ISAKMP:(0):Found ADDRESS key in keyring DMVPN_KEY

.Jan 28 22:41:12.006: ISAKMP:(0): constructed NAT-T vendor-rfc3947 ID

.Jan 28 22:41:12.006: ISAKMP:(0): constructed NAT-T vendor-07 ID

.Jan 28 22:41:12.006: ISAKMP:(0): constructed NAT-T vendor-03 ID

.Jan 28 22:41:12.006: ISAKMP:(0): constructed NAT-T vendor-02 ID

.Jan 28 22:41:12.006: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM

HAM1-RTR#

.Jan 28 22:41:12.006: ISAKMP:(0):Old State = IKE_READY New State = IKE_I_MM1

.Jan 28 22:41:12.006: ISAKMP:(0): beginning Main Mode exchange

.Jan 28 22:41:12.006: ISAKMP:(0): sending packet to 87.138.xxx.xxx my_port 500 peer_port 500 (I) MM_NO_STATE

.Jan 28 22:41:12.006: ISAKMP:(0):Sending an IKE IPv4 Packet.

HAM1-RTR#

.Jan 28 22:41:22.006: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...

.Jan 28 22:41:22.006: ISAKMP (0): incrementing error counter on sa, attempt 1 of 5: retransmit phase 1

.Jan 28 22:41:22.006: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE

.Jan 28 22:41:22.006: ISAKMP:(0): sending packet to 87.138.xxx.xxx my_port 500 peer_port 500 (I) MM_NO_STATE

.Jan 28 22:41:22.006: ISAKMP:(0):Sending an IKE IPv4 Packet.

HAM1-RTR#un

.Jan 28 22:41:32.006: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...

.Jan 28 22:41:32.006: ISAKMP (0): incrementing error counter on sa, attempt 2 of 5: retransmit phase 1

.Jan 28 22:41:32.006: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE

.Jan 28 22:41:32.006: ISAKMP:(0): sending packet to 87.138.xxx.xxx my_port 500 peer_port 500 (I) MM_NO_STATE

.Jan 28 22:41:32.006: ISAKMP:(0):Sending an IKE IPv4 Packet.

weedywhizz · ‎01-30-2014

Update:

I used "debug ip udp address 87.138.xxx.xxx" on the primary hub router to check if there is isakmp traffic coming in...no it does not even though the secondary hub sends IKE messages as you can see in the above output of "debug crypto isakmp".

When I ping the primary hub from the secondary there is icmp traffic being blocked so traffic is arriving. No block messages for isakmp...

Still no joy.