23.1.8: dhcp6c script race condition causes hundreds of dpinger processes?

[franco]

As an extra data point would you mind switching to the development version? Because I've rewritten the gateway watcher monitoring/alert and merged it into a single service that would be more deterministic at least from the side we can control. IPv4 and IPv6 could still race depending on the timing with the ISP but it would be good to have that data point as well.


Cheers,
Franco

[rssor]

Sure thing. Should I revert all the various patches first, or can I just flip it over just fine?

I'm unsure if I was supposed to revert any of the patches before the last upgrade to 23.1.9 too.

[franco]

Every time you install a package (and this includes the core package for stable or development) all known files are reset to their known state undoing all patches (except the ones that have been added into the package in between).

Mileage may vary here depending on where and when patches were committed and when the last release build was. One handy but sometimes counter-intuitive feature of opnsense-patch (or "patch" in general) is that it will reverse a patch already in place so sometimes people get confused by installing a version that already has the change and then undoing it and testing again to see it fail.

But since we talk mostly about minor glitches here I think it's not that imperative. All patches discussed here will be in the community version 23.1.10 anyway. No need to retest these


Cheers,
Franco

[rssor]

No such luck, got a broken dpinger on the first reboot.

Code: [Select]

2023-06-06T16:47:45-04:00 Notice opnsense-devel /usr/local/etc/rc.newwanipv6: plugins_configure monitor (execute task : dpinger_configure_do(,WAN_DHCP6))
2023-06-06T16:47:44-04:00 Notice opnsense-devel /usr/local/etc/rc.routing_configure: plugins_configure monitor (execute task : dpinger_configure_do(1))
2023-06-06T16:47:44-04:00 Notice opnsense-devel /usr/local/etc/rc.newwanipv6: plugins_configure monitor (execute task : dpinger_configure_do(,WAN_DHCP6))
2023-06-06T16:47:43-04:00 Notice opnsense-devel /usr/local/etc/rc.newwanip: plugins_configure monitor (execute task : dpinger_configure_do(,WAN_DHCP))
2023-06-06T16:47:43-04:00 Notice opnsense-devel /usr/local/etc/rc.routing_configure: plugins_configure monitor (execute task : dpinger_configure_do(1))
2023-06-06T16:47:43-04:00 Notice opnsense-devel /usr/local/etc/rc.newwanipv6: plugins_configure monitor (execute task : dpinger_configure_do(,WAN_DHCP6))
2023-06-06T16:47:43-04:00 Notice opnsense-devel /usr/local/etc/rc.newwanipv6: plugins_configure monitor (execute task : dpinger_configure_do(,WAN2_DHCP6))
2023-06-06T16:47:43-04:00 Notice opnsense-devel /usr/local/etc/rc.newwanip: plugins_configure monitor (execute task : dpinger_configure_do(,WAN2_DHCP))
2023-06-06T16:47:42-04:00 Notice opnsense-devel /usr/local/etc/rc.bootup: plugins_configure monitor (execute task : dpinger_configure_do(1,null,1))

WAN2_DHCP6's dpinger service shows as not running in the dashboard and the gateway shows as failed with no stats.

[rssor]

In fact, I'm not sure if this is new or if this has been happening, but for some reason opnsense is now sending DHCP (IPv4) renewal requests for WAN2 out of my WAN interface with my WAN2 IP as the source address.

It looks like this is caused by the route to the DHCP server being covered by my primary WAN interface:

Code: [Select]

root@gw:/var/etc # route get 72.31.136.237
   route to: 072-031-136-237.res.spectrum.com
destination: default
       mask: default
    gateway: 104-56-90-1.lightspeed.dybhfl.sbcglobal.net
        fib: 0
  interface: hn1
      flags: <UP,GATEWAY,DONE,STATIC>
 recvpipe  sendpipe  ssthresh  rtt,msec    mtu        weight    expire

EDIT: Actually, I think this is an upstream bug: https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=266508

Except that it's not quite root caused correctly, it's not because they're both on the same subnet, it's because one of the interfaces already has a route to the server in question. Since my Spectrum DHCP server isn't on the same subnet as my Spectrum WAN IP, it winds up trying to renew out the wrong interface because the primary gateway is the route. It's smart enough to use the right source IP, but not smart enough to only send it out the interface that's allowed to originate traffic with that IP. Brilliant.

That seems particularly egregious as upstream bugs go, but upstream is gonna upstream I guess.

EDIT 2: And it seems I can’t try to work around this with policy based routing, because primary WAN also uses DHCP and thus has the automatic firewall rule that immediately allows all outgoing DHCP before my rule can redirect it out WAN2 where it belongs.

[franco]

Thanks for testing... it's strange that this pops up now if it's a fundamental issue. Switching back to community will work around this?

For dpinger at least it looks like it's trying to set it up but failing eventually. Might have been started but stopped later on. A lingering PID file would tell us perhaps.


Cheers,
Franco

[rssor]

After reverting back to community I seem to have seen a duplicate dpinger once again, on WAN_DHCP, on a boot where WAN2_DHCP6 also failed to start as it did on devel:

This is from community, apologies for not having a set of this output pidfiles from devel. I can try switching back again tomorrow.

Code: [Select]

root@gw:~ # ps aux | grep dpin
root     4197   0.0  0.1  13504  2580  -  Is   08:15    0:00.05 /usr/local/bin/dpinger -f -S -r 0 -i WAN_DHCP6 -B fe80::215:5dff:fe01:2405%hn1 -p /var/run/dpinger_WAN_DHCP6.pid -u /var/run/dpinger_WAN_DHCP6.sock -C /usr/local/etc/rc.syshook monitor -s 1s -l 2s -t 60s -A 1s -D 500 -L 20 -d 0 fe80::12c4:caff:fe39:8051%hn1
root     4433   0.0  0.1  13504  2548  -  Is   08:15    0:00.05 /usr/local/bin/dpinger -f -S -r 0 -i WAN_DHCP -B 104.WAN -p /var/run/dpinger_WAN_DHCP.pid -u /var/run/dpinger_WAN_DHCP.sock -C /usr/local/etc/rc.syshook monitor -s 1s -l 2s -t 60s -A 1s -D 500 -L 20 -d 0 104.56.90.1
root     5337   0.0  0.1  13504  2548  -  Is   08:15    0:00.04 /usr/local/bin/dpinger -f -S -r 0 -i WAN2_DHCP -B 67.WA2 -p /var/run/dpinger_WAN2_DHCP.pid -u /var/run/dpinger_WAN2_DHCP.sock -C /usr/local/etc/rc.syshook monitor -s 1s -l 2s -t 60s -A 1s -D 500 -L 20 -d 0 67.8.168.1
root    98809   0.0  0.1  13504  2548  -  Is   08:15    0:00.04 /usr/local/bin/dpinger -f -S -r 0 -i WAN_DHCP -B 104.WAN -p /var/run/dpinger_WAN_DHCP.pid -u /var/run/dpinger_WAN_DHCP.sock -C /usr/local/etc/rc.syshook monitor -s 1s -l 2s -t 60s -A 1s -D 500 -L 20 -d 0 104.56.90.1
root    59089   0.0  0.1  12752  2228  0  S+   08:26    0:00.00 grep dpin
root@gw:~ # ls -l /var/run/dping*
-rw-r-----  1 root  wheel  5 Jun  7 08:15 /var/run/dpinger_WAN2_DHCP.pid
srw-rw-rw-  1 root  wheel  0 Jun  7 08:15 /var/run/dpinger_WAN2_DHCP.sock
-rw-r-----  1 root  wheel  5 Jun  7 08:15 /var/run/dpinger_WAN_DHCP.pid
srw-rw-rw-  1 root  wheel  0 Jun  7 08:15 /var/run/dpinger_WAN_DHCP.sock
-rw-r-----  1 root  wheel  5 Jun  7 08:15 /var/run/dpinger_WAN_DHCP6.pid
srw-rw-rw-  1 root  wheel  0 Jun  7 08:15 /var/run/dpinger_WAN_DHCP6.sock

For that DHCP wrong interface thing, there probably aren't a lot people doing multi-wan with:

• Primary and failover interfaces as DHCP clients
• Failover interface ISP DHCP server not on the same subnet as the failover interface address

I do have some pcaps of that DHCP behavior over both interfaces, and essentially while all the unicast request attempts go out the wrong interface it does eventually go back to a broadcast (with the same transaction ID) which is going out the right interface at which point the request goes through.

I can think of a few ways to work around the issue, but it would involve an option that makes the existing allow outgoing DHCP automatic rules more specific or an option to add even earlier automatic floating rules to implement policy based routing for the unicast requests.

[rssor]

Wait, some of this is an error on my part, I went back to community but I did not apply the three most recent patches again, false alarm on the duplicate dpinger!

[rssor]

I think the DHCP issues are even more fundamental on multi-WAN setups, and it's even present on community. Here's en example of me attempting a 'Reload' in the Interface Overview for WAN2:

WAN2 PCAP:

Code: [Select]

38 11:38:43.310005 0.0.0.0 255.255.255.255 DHCP 342 DHCP Request  - Transaction ID 0x81518a2f
39 11:38:43.390628 72.31.136.237 67.WAN2_IP DHCP 359 DHCP ACK      - Transaction ID 0x81518a2f

Out of WAN1:

Code: [Select]

91 11:38:43.390695 72.31.136.237 67.WAN2_IP DHCP 359 DHCP ACK      - Transaction ID 0x81518a2f

In summary:
Sends the request from 0.0.0.0 out WAN2, gets the response to WAN address (I'm assuming it cleared the address from that interface first), and immediately routes it back out the other WAN interface.

Code: [Select]

WAN 2023-06-07T11:48:34-04:00 <- 72.31.136.237:67 67.WAN2_IP:68 udp let out anything from firewall host itself
WAN2 2023-06-07T11:48:34-04:00 -> 72.31.136.237:67 67.WAN2_IP:68 udp allow DHCP client on WAN2


The rules making this happen are so early I'm not sure I can even prevent this from happening.

Also hitting 'Reload' on the interface overview is one of the things that can make WAN2_DHCP6's dpinger instance fail and not recover.

EDIT: and, to follow up on the /var/run dpinger pidfiles for WAN2_DHCP6 when it fails: they are missing, so I think something deleted them.

[franco]

It might make sense to wait for 23.1.10 and test more on the community version to reproduce the renew/rebind issue you are seeing. I've added the updaterrd/dpinger patches to that upcoming version to avoid more manual patching.


Cheers,
Franco

[rssor]

Sure. I suspect reproducing the DHCPv4 stuff will be no problem at all, and with longer-running pcaps I think I've got it figured out. I don't think it's new, I just hadn't used OPNSense before the end of May.

Given:

• Multi-WAN configuration
• Failover WAN (called WAN2) ISP uses DHCP relay for DHCP server not on WAN2's net

Once the lease T1 timer is hit, dhclient attempts a unicast renewal to the DHCP server. FreeBSD kernel elects to deliver this out WAN1 based on the default route, despite using WAN2's address as the source IP. Primary WAN ISP clearly just drops this.

Once the lease T2 timer is hit, dhclient reverts to broadcasts and this does go out the right interface, crisis is averted.

dhclient's behavior of unicast renewals at T1 and broadcasts after T2 is correct, the only error is the interface used. With freebsd not having SO_BINDTODEVICE or an equivalent, I'm not sure dhclient can even be fixed directly.

This also explains why nobody has noticed: upstream ISP likely just drops the bad traffic and dhclient is able to renew at T2, so people wouldn't notice T1 renewals failing in this kind of a multi-wan setup.

Additionally, the automatic rules are a bit too loose and inadvertently allow received DHCP messages to be reflected from one WAN interface to the other. as a result, it's not possible to manually add a firewall rule to implement policy based routing.

I'd need a rule like "src: WAN2 address dest: * gateway: WAN2" as (I think) a floating rule (or at least WAN_GROUP) to stop this from happening.

Assuming I'm not wildly off this probably warrants its own separate issue. A slightly stricter outgoing dhcp allow rule would allow me to work around the issue with a manual policy based route, without having to fight upstream.

[billimek]

I found this thread after experiencing the same symptoms.  Running 23.1.9 with no patches.  I had a system load of over 100 and rebooted to try to fix it before finding this thread.

I have gateway configuration set-up but don't really need it, and wondering if I disable that feature, if this will solve the problem?

[rssor]

If your issue is the same as mine, then you need up to the three patches in

Code: [Select]

opnsense-patch 74c3125e0d2f
opnsense-patch fdf46f317c3 0200f79a19
The first one at minimum.

To determine if your issue is the same as mine, look at the start time of the dpinger processes, then look through your logs for RENEW. If the new dpingers are starting when DHCPv6 renewals occur then it might be the same issue.

That said 23.1.9 did prevent the underlying cause from being triggered from the DHCPv6 renewals, at least for me.

My issue at least was not caused by multiple gateways, but rather the monitoring on its own in combination with the newwanipv6 logic running multiple times simultaneously.

[franco]

About the unicast routing issue I think this is a little difficult to address it judging by the past unsolved problems not just in FreeBSD:

2013: https://lists.isc.org/pipermail/dhcp-users/2013-February/016398.html
2016: https://bugzilla.redhat.com/show_bug.cgi?id=1297445
2022: https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=266508 (mentioned by rssor before)


Cheers,
Franco

[franco]

Only chance that I see here... not sure if this works... hard to test...

https://github.com/opnsense/src/commit/5dc1ca155bf1e5

I'm going to let this run locally for the time being to see what happens on renewal WRT the warning() log message.


Cheers,
Franco