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 subnetGood luck, and take a backup first.