VPN Site to Site Phase 1 stuck on MM_WAIT_MSG3

Hassan Chalabi · ‎06-06-2018

Hi,

this tunnel fails frequently, not sure what could cause, but here is the output of the debug

2 IKE Peer: 123.123.123.123
Type : user Role : responder
Rekey : no State : MM_WAIT_MSG3

Jun 06 11:02:45 [IKEv1]IP = 123.123.123.123, IKE_DECODE RESENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 132
Jun 06 11:02:53 [IKEv1]IP = 123.123.123.123, Duplicate first packet detected. Ignoring packet.
Jun 06 11:02:53 [IKEv1]IP = 123.123.123.123, IKE_DECODE RESENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 132
Jun 06 11:03:01 [IKEv1 DEBUG]IP = 123.123.123.123, IKE MM Responder FSM error history (struct &0x00007f6f922c08c0) <state>, <event>: MM_DONE, EV_ERROR-->MM_WAIT_MSG3, EV_TIMEOUT-->MM_WAIT_MSG3, NullEvent-->MM_SND_MSG2, EV_SND_MSG-->MM_SND_MSG2, EV_START_TMR-->MM_SND_MSG2, EV_RESEND_MSG-->MM_WAIT_MSG3, EV_TIMEOUT-->MM_WAIT_MSG3, NullEvent
Jun 06 11:03:01 [IKEv1 DEBUG]IP = 123.123.123.123, IKE SA MM:5f35d57e terminating: flags 0x01000002, refcnt 0, tuncnt 0
Jun 06 11:03:01 [IKEv1 DEBUG]IP = 123.123.123.123, sending delete/delete with reason message
Jun 06 11:03:29 [IKEv1]IP = 123.123.123.123, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 820
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, processing SA payload
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, Oakley proposal is acceptable
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, processing VID payload
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, Received NAT-Traversal ver 02 VID
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, processing VID payload
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, Received NAT-Traversal ver 03 VID
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, processing VID payload
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, Received NAT-Traversal RFC VID
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, processing VID payload
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, Received Fragmentation VID
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, IKE Peer included IKE fragmentation capability flags: Main Mode: True Aggressive Mode: True
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, processing IKE SA payload
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, IKE SA Proposal # 1, Transform # 1 acceptable Matches global IKE entry # 14
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, constructing ISAKMP SA payload
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, constructing NAT-Traversal VID ver RFC payload
Jun 06 11:03:29 [IKEv1 DEBUG]IP = 123.123.123.123, constructing Fragmentation VID + extended capabilities payload
Jun 06 11:03:29 [IKEv1]IP = 123.123.123.123, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 132
Jun 06 11:03:37 [IKEv1]IP = 123.123.123.123, Duplicate first packet detected. Ignoring packet.
Jun 06 11:03:37 [IKEv1]IP = 123.123.123.123, IKE_DECODE RESENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 132
Jun 06 11:03:45 [IKEv1]IP = 123.123.123.123, Duplicate first packet detected. Ignoring packet.
Jun 06 11:03:45 [IKEv1]IP = 123.123.123.123, IKE_DECODE RESENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 132
Jun 06 11:03:53 [IKEv1]IP = 123.123.123.123, Duplicate first packet detected. Ignoring packet.
Jun 06 11:03:53 [IKEv1]IP = 123.123.123.123, IKE_DECODE RESENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 132
Jun 06 11:04:01 [IKEv1 DEBUG]IP = 123.123.123.123, IKE MM Responder FSM error history (struct &0x00007f6f8dd75bf0) <state>, <event>: MM_DONE, EV_ERROR-->MM_WAIT_MSG3, EV_TIMEOUT-->MM_WAIT_MSG3, NullEvent-->MM_SND_MSG2, EV_SND_MSG-->MM_SND_MSG2, EV_START_TMR-->MM_SND_MSG2, EV_RESEND_MSG-->MM_WAIT_MSG3, EV_TIMEOUT-->MM_WAIT_MSG3, NullEvent
Jun 06 11:04:01 [IKEv1 DEBUG]IP = 123.123.123.123, IKE SA MM:ea0ba28a terminating: flags 0x01000002, refcnt 0, tuncnt 0
Jun 06 11:04:01 [IKEv1 DEBUG]IP = 123.123.123.123, sending delete/delete with reason message
Jun 06 11:04:29 [IKEv1]IP = 123.123.123.123, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 820
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, processing SA payload
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, Oakley proposal is acceptable
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, processing VID payload
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, Received NAT-Traversal ver 02 VID
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, processing VID payload
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, Received NAT-Traversal ver 03 VID
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, processing VID payload
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, Received NAT-Traversal RFC VID
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, processing VID payload
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, Received Fragmentation VID
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, IKE Peer included IKE fragmentation capability flags: Main Mode: True Aggressive Mode: True
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, processing IKE SA payload
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, IKE SA Proposal # 1, Transform # 1 acceptable Matches global IKE entry # 14
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, constructing ISAKMP SA payload
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, constructing NAT-Traversal VID ver RFC payload
Jun 06 11:04:29 [IKEv1 DEBUG]IP = 123.123.123.123, constructing Fragmentation VID + extended capabilities payload
Jun 06 11:04:29 [IKEv1]IP = 123.123.123.123, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 132
Jun 06 11:04:37 [IKEv1]IP = 123.123.123.123, Duplicate first packet detected. Ignoring packet.
Jun 06 11:04:37 [IKEv1]IP = 123.123.123.123, IKE_DECODE RESENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 132
Jun 06 11:04:45 [IKEv1]IP = 123.123.123.123, Duplicate first packet detected. Ignoring packet.
Jun 06 11:04:45 [IKEv1]IP = 123.123.123.123, IKE_DECODE RESENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 132
Jun 06 11:04:53 [IKEv1]IP = 123.123.123.123, Duplicate first packet detected. Ignoring packet.
Jun 06 11:04:53 [IKEv1]IP = 123.123.123.123, IKE_DECODE RESENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 132
Jun 06 11:05:01 [IKEv1 DEBUG]IP = 123.123.123.123, IKE MM Responder FSM error history (struct &0x00007f6f87122290) <state>, <event>: MM_DONE, EV_ERROR-->MM_WAIT_MSG3, EV_TIMEOUT-->MM_WAIT_MSG3, NullEvent-->MM_SND_MSG2, EV_SND_MSG-->MM_SND_MSG2, EV_START_TMR-->MM_SND_MSG2, EV_RESEND_MSG-->MM_WAIT_MSG3, EV_TIMEOUT-->MM_WAIT_MSG3, NullEvent
Jun 06 11:05:01 [IKEv1 DEBUG]IP = 123.123.123.123, IKE SA MM:3947d835 terminating: flags 0x01000002, refcnt 0, tuncnt 0
Jun 06 11:05:01 [IKEv1 DEBUG]IP = 123.123.123.123, sending delete/delete with reason message

Rob Ingram · ‎06-06-2018

Hi,
I assume the tunnel has previously worked and this issue is intermittent?

From the debug output, it looks like it's re-sending the messages. Is there full and reliable communication between the routers? Could there be an issue with the circuit on either end?

Hassan Chalabi · ‎06-06-2018

yes the peer is reachable, issue is intermittent, I am trying to isolate the issue before I contact the other side, they dont seem to communicate very well.