IPSEC Tunnel Drops Occasionally



  • Hi,

    I took over IT at this company a few months ago, and part of this has been migrating our sonicwall-based routing system to pfSense. We have one remote worker who connects to our network (for his phone - avaya 9608 to a ip500v2 located here - and file sharing). He currently has a Sonicwall SOHO Wireless-N behind a NAT on his end (but he does have a static WAN ip).

    For a bit I was seeing frequent disconnects and reconnects, which was fixed by enabling the keepalive ping, but since then there still have been a few disconnects. I've been on the phone with him while the connection re-keys, and there is no drop, but these disconnects will cut the audio straight out of his active call (so it's not a no-traffic issue).

    Here are some relevant log lines from this morning's disconnect:

    Apr 30 08:34:44	charon		13[ENC] <con1|3000> generating INFORMATIONAL request 99 [ ]
    Apr 30 08:34:44	charon		13[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:34:44	charon		13[NET] <con1|3000> received packet: from 184.188.xx.xx[4500] to 206.168.xx.xx[4500] (76 bytes)
    Apr 30 08:34:44	charon		13[ENC] <con1|3000> parsed INFORMATIONAL response 99 [ ]
    Apr 30 08:34:44	charon		13[IKE] <con1|3000> activating new tasks
    Apr 30 08:34:44	charon		13[IKE] <con1|3000> nothing to initiate
    Apr 30 08:34:44	charon		13[NET] <con1|3000> received packet: from 184.188.xx.xx[4500] to 206.168.xx.xx[4500] (76 bytes)
    Apr 30 08:34:44	charon		13[ENC] <con1|3000> parsed INFORMATIONAL request 130 [ ]
    Apr 30 08:34:44	charon		13[ENC] <con1|3000> generating INFORMATIONAL response 130 [ ]
    Apr 30 08:34:44	charon		13[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:34:54	charon		13[IKE] <con1|3000> sending DPD request
    Apr 30 08:34:54	charon		13[IKE] <con1|3000> queueing IKE_DPD task
    Apr 30 08:34:54	charon		13[IKE] <con1|3000> activating new tasks
    Apr 30 08:34:54	charon		13[IKE] <con1|3000> activating IKE_DPD task
    Apr 30 08:34:54	charon		13[ENC] <con1|3000> generating INFORMATIONAL request 100 [ ]
    Apr 30 08:34:54	charon		13[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:34:58	charon		13[IKE] <con1|3000> retransmit 1 of request with message ID 100
    Apr 30 08:34:58	charon		13[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:34:58	charon		13[NET] <con1|3000> received packet: from 184.188.xx.xx[4500] to 206.168.xx.xx[4500] (64 bytes)
    Apr 30 08:34:58	charon		13[ENC] <con1|3000> not enough input to parse rule 3 CHUNK_DATA
    Apr 30 08:34:58	charon		13[ENC] <con1|3000> payload type ENCRYPTED could not be parsed
    Apr 30 08:34:58	charon		13[IKE] <con1|3000> message parsing failed
    Apr 30 08:34:58	charon		13[IKE] <con1|3000> INFORMATIONAL response with message ID 100 processing failed
    Apr 30 08:35:04	charon		13[NET] <con1|3000> received packet: from 184.188.xx.xx[4500] to 206.168.xx.xx[4500] (76 bytes)
    Apr 30 08:35:04	charon		13[ENC] <con1|3000> parsed INFORMATIONAL request 131 [ ]
    Apr 30 08:35:04	charon		13[ENC] <con1|3000> generating INFORMATIONAL response 131 [ ]
    Apr 30 08:35:04	charon		13[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:35:05	charon		13[IKE] <con1|3000> retransmit 2 of request with message ID 100
    Apr 30 08:35:05	charon		13[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:35:18	charon		13[IKE] <con1|3000> retransmit 3 of request with message ID 100
    Apr 30 08:35:18	charon		13[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:35:24	charon		07[NET] <con1|3000> received packet: from 184.188.xx.xx[4500] to 206.168.xx.xx[4500] (76 bytes)
    Apr 30 08:35:24	charon		07[ENC] <con1|3000> parsed INFORMATIONAL request 132 [ ]
    Apr 30 08:35:24	charon		07[ENC] <con1|3000> generating INFORMATIONAL response 132 [ ]
    Apr 30 08:35:24	charon		07[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:35:41	charon		07[IKE] <con1|3000> retransmit 4 of request with message ID 100
    Apr 30 08:35:41	charon		07[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:35:44	charon		07[NET] <con1|3000> received packet: from 184.188.xx.xx[4500] to 206.168.xx.xx[4500] (76 bytes)
    Apr 30 08:35:44	charon		07[ENC] <con1|3000> parsed INFORMATIONAL request 133 [ ]
    Apr 30 08:35:44	charon		07[ENC] <con1|3000> generating INFORMATIONAL response 133 [ ]
    Apr 30 08:35:44	charon		07[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:36:04	charon		07[NET] <con1|3000> received packet: from 184.188.xx.xx[4500] to 206.168.xx.xx[4500] (76 bytes)
    Apr 30 08:36:04	charon		07[ENC] <con1|3000> parsed INFORMATIONAL request 134 [ ]
    Apr 30 08:36:04	charon		07[ENC] <con1|3000> generating INFORMATIONAL response 134 [ ]
    Apr 30 08:36:04	charon		07[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:36:23	charon		07[IKE] <con1|3000> retransmit 5 of request with message ID 100
    Apr 30 08:36:23	charon		07[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:36:24	charon		07[NET] <con1|3000> received packet: from 184.188.xx.xx[4500] to 206.168.xx.xx[4500] (76 bytes)
    Apr 30 08:36:24	charon		07[ENC] <con1|3000> parsed INFORMATIONAL request 135 [ ]
    Apr 30 08:36:24	charon		07[ENC] <con1|3000> generating INFORMATIONAL response 135 [ ]
    Apr 30 08:36:24	charon		07[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:36:44	charon		11[NET] <con1|3000> received packet: from 184.188.xx.xx[4500] to 206.168.xx.xx[4500] (76 bytes)
    Apr 30 08:36:44	charon		11[ENC] <con1|3000> parsed INFORMATIONAL request 136 [ ]
    Apr 30 08:36:44	charon		11[ENC] <con1|3000> generating INFORMATIONAL response 136 [ ]
    Apr 30 08:36:44	charon		11[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:37:04	charon		11[NET] <con1|3000> received packet: from 184.188.xx.xx[4500] to 206.168.xx.xx[4500] (76 bytes)
    Apr 30 08:37:04	charon		11[ENC] <con1|3000> parsed INFORMATIONAL request 137 [ ]
    Apr 30 08:37:04	charon		11[ENC] <con1|3000> generating INFORMATIONAL response 137 [ ]
    Apr 30 08:37:04	charon		11[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:37:24	charon		11[NET] <con1|3000> received packet: from 184.188.xx.xx[4500] to 206.168.xx.xx[4500] (76 bytes)
    Apr 30 08:37:24	charon		11[ENC] <con1|3000> parsed INFORMATIONAL request 138 [ ]
    Apr 30 08:37:24	charon		11[ENC] <con1|3000> generating INFORMATIONAL response 138 [ ]
    Apr 30 08:37:24	charon		11[NET] <con1|3000> sending packet: from 206.168.xx.xx[4500] to 184.188.xx.xx[4500] (76 bytes)
    Apr 30 08:37:39	charon		11[IKE] <con1|3000> giving up after 5 retransmits
    Apr 30 08:37:39	charon		11[IKE] <con1|3000> IKE_SA con1[3000] state change: ESTABLISHED => DESTROYING
    Apr 30 08:37:39	charon		11[CHD] <con1|3000> CHILD_SA con1{463} state change: INSTALLED => DESTROYING
    Apr 30 08:41:37	charon		08[NET] <3001> received packet: from 184.188.xx.xx[500] to 206.168.xx.xx[500] (316 bytes)
    Apr 30 08:41:37	charon		08[ENC] <3001> parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) V ]
    Apr 30 08:41:37	charon		08[CFG] <3001> looking for an ike config for 206.168.xx.xx...184.188.xx.xx
    Apr 30 08:41:37	charon		08[CFG] <3001> candidate: 206.168.xx.xx...184.188.xx.xx, prio 3096
    Apr 30 08:41:37	charon		08[CFG] <3001> found matching ike config: 206.168.xx.xx...184.188.xx.xx with prio 3096
    Apr 30 08:41:37	charon		08[ENC] <3001> received unknown vendor ID: 2a:67:75:d0:ad:2a:a7:88:7c:33:fe:1d:68:ba:f3:08:96:6f:00:01
    Apr 30 08:41:37	charon		08[IKE] <3001> 184.188.xx.xx is initiating an IKE_SA
    Apr 30 08:41:37	charon		08[IKE] <3001> IKE_SA (unnamed)[3001] state change: CREATED => CONNECTING</con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000></con1|3000>
    

    The way I interpret this is that it seems like the sonicwall (on the 184.188.xx.xx side, if it wasn't obvious) is sending some sort of message that pfSense doesn't know about, and after trying 5 times to understand it just restarts the connection. Googling the CHUNK_DATA and payload type ENCRYPTED lines gives approximately no results.

    I'm not against throwing a bit of money towards one of those microfirewall deals, but I would much rather fix this in software for now rather than coordinate mailing the thing out and setting it up over the phone.

    Any ideas?



  • I can't comment on your specific case, but here are a few things I did (they may work for you, or they may make things worse!)…

    system > advanced > networking > all hardware offloading options: tick (disable)
    vpn > ipsec > advanced settings > enable maximum mss: tick
    vpn > ipsec > advanced settings > maximum mss: 1400
    vpn > ipsec > advanced settings > make before break: tick
    vpn > ipsec > tunnels > edit phase 1 > disable rekey: untick
    vpn > ipsec > tunnels > edit phase 1 > margintime: 60
    vpn > ipsec > tunnels > edit phase 2 > pfs key group: off
    vpn > ipsec > tunnels > edit phase 2 > automatically ping host: ip within remote subnet

    Good luck, and take a backup first.