Interesting case of WAN dropping daily/DHCP being blocked by firewall?



  • My pfsense box is dropping the WAN connection daily at random times. When it happens nothing being changed in pfsense with a following DHCP release/renew will fix it. I have to turn off my modem and then turn it back on AND reboot pfsense to regain connectivity.

    ISP (Spectrum) -> Netgear C6300 (bridged) -> pfsense box -> LAN

    I have tried a multitude of things so far but nothing has solved the problem as every 12-24 hours pfsense will fail to get internet connectivity. I've verified it's the pfsense box because I can plug a laptop directly into Port 1 of the bridged modem and ping/surf the internet just fine after pfsense goes down.

    I've tried:
    Non-standard gateway latency probe intervals/etc
    Changing firewall mode from 'normal' to 'high latency'
    Disabling the gateway monitoring (did this today, still monitoring if this will fix it but I would rather have this enabled)
    Adding a firewall WAN rule allowing a 'blocked' DHCP IP from the log below to 'pass' to the 'firewall (self)' destination

    Notes:
    According to my ISP (spectrum) there is no special MAC/static IP/hostname to be entered, it's all through their DHCP

    Here is the gateway log sample from the last outage:

    
    Feb 16 14:19:07	dpinger		WAN_DHCP 97.XXX.XXX.X: sendto error: 65
    Feb 16 14:19:10	dpinger		WAN_DHCP 97.XXX.XXX.X: sendto error: 65
    Feb 16 14:19:13	dpinger		WAN_DHCP 97.XXX.XXX.X: sendto error: 65
    Feb 16 14:19:16	dpinger		WAN_DHCP 97.XXX.XXX.X: sendto error: 65
    *added note - this repeats 100x times*
    Feb 16 14:21:44	dpinger		send_interval 3000ms loss_interval 6000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 8000ms latency_alarm 500ms loss_alarm 20% dest_addr 97.XXX.XXX.X bind_addr 97.XXX.XXX.XXX2 identifier "WAN_DHCP "
    Feb 16 14:22:00	dpinger		WAN_DHCP 97.XXX.XXX.X: Alarm latency 0us stddev 0us loss 100%
    Feb 16 14:25:33	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 97.XXX.XXX.X bind_addr 97.XXX.XXX.XXX2 identifier "WAN_DHCP "
    Feb 16 14:25:35	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 97.XXX.XXX.X bind_addr 97.XXX.XXX.XXX2 identifier "WAN_DHCP "
    Feb 16 14:25:39	dpinger		WAN_DHCP 97.XXX.XXX.X: Alarm latency 0us stddev 0us loss 100%
    
    

    Routing log:

    
    Feb 16 14:52:07	radvd	34097	sendmsg: Operation not permitted
    Feb 16 14:52:15	radvd	34097	sendmsg: Operation not permitted
    Feb 16 14:52:23	radvd	34097	sendmsg: Operation not permitted
    Feb 16 14:52:32	radvd	34097	sendmsg: Operation not permitted
    Feb 16 14:52:42	radvd	34097	sendmsg: Operation not permitted
    Feb 16 14:52:47	radvd	34097	sendmsg: Operation not permitted
    Feb 16 14:52:55	radvd	34097	sendmsg: Operation not permitted
    

    Any ideas what's causing it?



  • Also in my firewall logs I'm getting some blocking of port 67/68 traffic (DHCP)

    Feb 16 23:01:29	WAN	  10.209.64.1:67	  255.255.255.255:68
    


  • No one? :/



  • Purchased a surfboard 6141 to replace the netgear bridged C6300 and it looks like the problem is fixed so far, it's been 12 hours without a drop.



  • I have the same problem but it seems to occur every few days for me. Using SG-1000.

    • Rebooting modem does not work.
    • The only remedy is rebooting pfsense.
    • Interestingly, the Gateway Status still shows "Online".
    • The latency alarm does not seem to do anything.

    From the logs it looks like:

    1. The ISP is trying to assign a new IP address
    2. For some reason that cannot happen
    3. Connection "dies" probably because ISP stops routing

    Gateway Logs:

    
    ... LOTS of previous instances of sendto error: 65 and before that 2 days earlier sendto error: 55...
    
    Apr 16 13:31:53 Heimdall dpinger: WAN_PPPOE {ISP Primary Gateway}: sendto error: 65
    Apr 16 13:31:54 Heimdall dpinger: WAN_PPPOE {ISP Primary Gateway}: sendto error: 65
    Apr 16 13:31:54 Heimdall dpinger: WAN_PPPOE {ISP Primary Gateway}: sendto error: 65
    Apr 16 13:31:55 Heimdall dpinger: WAN_PPPOE {ISP Primary Gateway}: sendto error: 65
    Apr 16 13:31:55 Heimdall dpinger: WAN_PPPOE {ISP Primary Gateway}: sendto error: 65
    Apr 16 13:31:56 Heimdall dpinger: WAN_PPPOE {ISP Primary Gateway}: sendto error: 65
    Apr 16 13:31:56 Heimdall dpinger: WAN_PPPOE {ISP Primary Gateway}: sendto error: 65
    Apr 16 13:31:57 Heimdall dpinger: WAN_PPPOE {ISP Primary Gateway}: sendto error: 65
    Apr 16 13:31:57 Heimdall dpinger: WAN_PPPOE {ISP Primary Gateway}: sendto error: 65
    Apr 16 13:31:58 Heimdall dpinger: send_interval 500ms  loss_interval 2000ms  time_period 60000ms  report_interval 0ms  data_len 0  alert_interval 1000ms  latency_alarm 500ms  loss_alarm 20%  dest_addr {ISP Secondary Gateway}  bind_addr {Valid WAN IP - 1}  identifier "WAN_PPPOE "
    Apr 16 13:36:06 Heimdall dpinger: send_interval 500ms  loss_interval 2000ms  time_period 60000ms  report_interval 0ms  data_len 0  alert_interval 1000ms  latency_alarm 500ms  loss_alarm 20%  dest_addr {ISP Primary Gateway}  bind_addr {Valid WAN IP - 2}  identifier "WAN_PPPOE "
    Apr 16 13:42:02 Heimdall dpinger: send_interval 500ms  loss_interval 2000ms  time_period 60000ms  report_interval 0ms  data_len 0  alert_interval 1000ms  latency_alarm 500ms  loss_alarm 20%  dest_addr {ISP Secondary Gateway}  bind_addr {Valid WAN IP - 3}  identifier "WAN_PPPOE "
    Apr 16 13:42:08 Heimdall dpinger: send_interval 500ms  loss_interval 2000ms  time_period 60000ms  report_interval 0ms  data_len 0  alert_interval 1000ms  latency_alarm 500ms  loss_alarm 20%  dest_addr {ISP Secondary Gateway}  bind_addr {Valid WAN IP - 3}  identifier "WAN_PPPOE "
    
    

    Routing Logs:

    
    Apr 16 13:10:05 Heimdall miniupnpd[47123]: remove port mapping 58698 TCP because it has expired
    Apr 16 13:10:05 Heimdall miniupnpd[47123]: remove port mapping 58698 UDP because it has expired
    Apr 16 13:11:20 Heimdall miniupnpd[47123]: upnp_event_process_notify: connect(172.16.10.15:2869): Operation timed out
    Apr 16 13:11:20 Heimdall miniupnpd[47123]: upnp_event_process_notify: connect(172.16.10.99:2869): Operation timed out
    Apr 16 13:15:39 Heimdall miniupnpd[47123]: ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
    Apr 16 13:15:39 Heimdall miniupnpd[47123]: Failed to get IP for interface pppoe0
    Apr 16 13:15:39 Heimdall miniupnpd[47123]: SendNATPMPPublicAddressChangeNotification: cannot get public IP address, stopping
    Apr 16 13:16:17 Heimdall miniupnpd[47123]: ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
    Apr 16 13:16:17 Heimdall miniupnpd[47123]: Failed to get IP for interface pppoe0
    Apr 16 13:16:17 Heimdall miniupnpd[47123]: SendNATPMPPublicAddressChangeNotification: cannot get public IP address, stopping
    Apr 16 13:18:05 Heimdall miniupnpd[47123]: SendNATPMPPublicAddressChangeNotification: sendto(s_udp=10): No route to host
    Apr 16 13:18:05 Heimdall miniupnpd[47123]: SendNATPMPPublicAddressChangeNotification: sendto(s_udp=10): No route to host
    Apr 16 13:29:22 Heimdall miniupnpd[47123]: ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
    Apr 16 13:29:22 Heimdall miniupnpd[47123]: Failed to get IP for interface pppoe0
    Apr 16 13:29:22 Heimdall miniupnpd[47123]: SendNATPMPPublicAddressChangeNotification: cannot get public IP address, stopping
    Apr 16 13:30:02 Heimdall miniupnpd[47123]: ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
    Apr 16 13:30:02 Heimdall miniupnpd[47123]: Failed to get IP for interface pppoe0
    Apr 16 13:30:02 Heimdall miniupnpd[47123]: SendNATPMPPublicAddressChangeNotification: cannot get public IP address, stopping
    Apr 16 13:31:52 Heimdall miniupnpd[47123]: SendNATPMPPublicAddressChangeNotification: sendto(s_udp=10): No route to host
    Apr 16 13:31:52 Heimdall miniupnpd[47123]: SendNATPMPPublicAddressChangeNotification: sendto(s_udp=10): No route to host
    Apr 16 13:36:22 Heimdall miniupnpd[47279]: HTTP listening on port 2189
    Apr 16 13:36:22 Heimdall miniupnpd[47279]: no HTTP IPv6 address, disabling IPv6
    Apr 16 13:36:22 Heimdall miniupnpd[47279]: Listening for NAT-PMP/PCP traffic on port 5351
    Apr 16 13:36:23 Heimdall miniupnpd[47279]: upnp_event_recv: recv(): Connection reset by peer
    
    


  • I know this is old but I'm pretty sure the solution to these troubles is to do with the link speed negotiation:

    This exact behaviour happened on a connection I'm working with, after I explicitly set the WAN link's ethernet speed negotiation to 100BaseT Full Duplex.

    The link then began going up and down like a yo-yo. If you refresh your browser every few seconds on interfaces>WAN this becomes clear. You do see the ISP's assigned IP come up as it should, but of course, then it drops out. On the cable modem you can also see the interface's link light turn off each time the link is dropped.

    The Logs>Gateway shows 2 dpinger entries every second:
    WAN_DHCP XXX.XXX.XXX.XXX: sendto error: 65
    WAN_DHCP XXX.XXX.XXX.XXX: sendto error: 65
    WAN_DHCP XXX.XXX.XXX.XXX: sendto error: 65

    Until you set the link speed neg:
    In Logs>Gateway you might see something like
    Oct 10 14:22:16 dpinger WAN_DHCP XXX.XXX.XXX.XXX: Alarm latency 9596us stddev 2791us loss 30%

    Then, no more errors.

    FYI: If you read the notice on the interface>link setting, "WARNING: MUST be set to autoselect (automatically negotiate speed) unless the port this interface connects to has its speed and duplex forced", you may get the hint when trying to resolve the problem.

    I tried many settings, finding that neither autoselect or 'autoselect flowcontrol' work.  It only worked with: 'AutoSelect 1000BaseT full-duplex,master', or the default option.

    As the current default option works, most people should not see this (bug?). Certainly, no autoselect option works!

    Above true for:
    pfS 2.3.4-RELEASE-p1 (amd64),
    Intel bge on-board interface,
    Netgear 'Telstra Gateway MAX' C6300BD on a DOCSIS 3.0 network

    I originally set the link speed in order to save power on two interfaces that don't need to negotiate a 1Gb speed. So much for that great idea ;-)



  • I'm experiencing this as well. Setting the link speed didn't do it for me.

    My first attempt was to pass 192.168.100.1 (my modem) to 192.168.100.20 67/68 UDP. Noticed in the logs, but doesn't make sense as there are no other devices. Set top box perhaps?

    Now I am getting Rule (12000) blocking source 10.240.160.225:67 destination: my public ip:68 So, I deselected Block private networks on WAN and rebooted.

    Looks like the dhcp requests are not being blocked now, but I am still getting latency alerts.

    recently upgraded to 2.3.4-release-p1

    Overnight, another latency error and dpinger sendto error 65.
    Noticed this in firewall log.

    Oct 12 07:10:02 WAN block bogon IPv6 networks from WAN (11000) 0.0.0.0:68 255.255.255.255:67 UDP

    Has my ISP changed the way they are doling out addresses?

    Update: Had cable dude come out and string a new line to the pole and have had no drops for 24 hours.

    Update 2: It's back. Not as bad but this is definitely getting annoying. Time to dump Optimum Cable for FIOS perhaps.

    Oct 16 15:24:28 	dpinger 		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 68.196.96.1 bind_addr 68.196.101.146 identifier "WAN_DHCP "
    Oct 16 15:24:23 	dpinger 		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 68.196.96.1 bind_addr 68.196.101.146 identifier "WAN_DHCP "
    Oct 16 15:24:18 	dpinger 		WAN_DHCP 68.196.96.1: sendto error: 65
    Oct 16 15:24:17 	dpinger 		WAN_DHCP 68.196.96.1: sendto error: 65