Bug #9267
closed
dhclient does not handle protocol timeouts or script failures correctly
0%
Description
pfSense-dhclient-script fails to return nonzero in the case where a DHCP timeout occurs and the cached gateway address is not pingable. This results in a case where the cached IP is removed from the interface, but dhclient is informed via the exit status of 0 that the IP was added successfully. As a result, the impacted interface remains without an IPv4 address until either the DHCP lease expires, the link flaps, or the DHCP lease is renewed manually, instead of the expected behavior of the DHCP protocol being restarted after the defined retry interval.
After addressing this with the patch 'pfsense-dhclient-script-patch.txt', I uncovered another apparent issue where the function 'priv_script_go' in dhclient.c does not correctly isolate and return the child process exit code from the return value of the wait() call.
This was further confirmed by verifying the current implementation in dhclient.c:
(wstatus & 0xff)
is not functionally equivalent to the definition of the WEXITSTATUS macro, which is defined as
((x) >> 8)
To address this, I have applied patch 'dhclient-patch.txt' to the FreeBSD 11.2 source tree, rebuilt dhclient, and installed the new binary to the pfSense appliance.After performing both of these actions, dhclient and the associated script now behave as expected when a protocol timeout occurs and the cached gateway IP is not pingable, where a timeout is indicated in the relevant logs and the DHCP protocol restarted after the defined retry interval.
Files
Updated by Nash Kaminski almost 6 years ago
Also to add, this is seen on version 2.4.4-RELEASE-p1 (amd64),
FreeBSD 11.2-RELEASE-p4, but affects versions back at least as far as 2.4.0.
Updated by Steve Wheeler over 5 years ago
See also: https://lists.freebsd.org/pipermail/freebsd-net/2019-February/052894.html
This appears to have been committed in 12 stable:
https://github.com/freebsd/freebsd/commit/eb327bd11b28ce1442cab508695cd6af172cb815
But not did not make 12.0 release.
Updated by Jim Pingle over 5 years ago
- Category set to Interfaces
- Priority changed from High to Normal
- Target version set to 2.5.0
- Affected Version set to All
- Affected Architecture All added
- Affected Architecture deleted (
)
Updated by Patrick Staton about 5 years ago
Any status on this? It pretty much breaks our router being able to handle power outages.
Updated by Jim Pingle about 5 years ago
The change is included in FreeBSD 12.1. Once we move pfSense to FreeBSD 12.1 (which will happen before 2.5.0-RELEASE), we'll pick this up naturally from upstream. So it won't be too much longer now.
Updated by Steve Wheeler over 4 years ago
This looks good in 2.4.5 with the patch to the script and the patched binary in place.
Without the patches dhclient incorrectly shows the lease as bound using a recorded lease previously used:
Mar 15 21:20:48 1100 dhclient: PREINIT Mar 15 21:20:48 1100 dhclient[82426]: DHCPREQUEST on mvneta0 to 255.255.255.255 port 67 Mar 15 21:20:50 1100 dhclient[82426]: DHCPREQUEST on mvneta0 to 255.255.255.255 port 67 Mar 15 21:20:52 1100 dhclient[82426]: DHCPREQUEST on mvneta0 to 255.255.255.255 port 67 Mar 15 21:20:55 1100 dhclient[82426]: DHCPREQUEST on mvneta0 to 255.255.255.255 port 67 Mar 15 21:21:02 1100 dhclient[82426]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 2 Mar 15 21:21:04 1100 dhclient[82426]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 2 Mar 15 21:21:06 1100 dhclient[82426]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 3 Mar 15 21:21:09 1100 dhclient[82426]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 8 Mar 15 21:21:17 1100 dhclient[82426]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 14 Mar 15 21:21:31 1100 dhclient[82426]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 11 Mar 15 21:21:42 1100 dhclient[82426]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 16 Mar 15 21:21:58 1100 dhclient[82426]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 5 Mar 15 21:22:03 1100 dhclient[82426]: No DHCPOFFERS received. Mar 15 21:22:03 1100 dhclient[82426]: Trying recorded lease 172.21.16.190 Mar 15 21:22:03 1100 dhclient: TIMEOUT Mar 15 21:22:03 1100 dhclient: Starting add_new_address() Mar 15 21:22:03 1100 dhclient: ifconfig mvneta0 inet 172.21.16.190 netmask 255.255.255.0 broadcast 172.21.16.255 Mar 15 21:22:03 1100 dhclient: New IP Address (mvneta0): 172.21.16.190 Mar 15 21:22:03 1100 dhclient: New Subnet Mask (mvneta0): 255.255.255.0 Mar 15 21:22:03 1100 dhclient: New Broadcast Address (mvneta0): 172.21.16.255 Mar 15 21:22:03 1100 dhclient: New Routers (mvneta0): 172.21.16.1 Mar 15 21:22:04 1100 dhclient: New Routers (mvneta0): 172.21.16.1 Mar 15 21:22:05 1100 dhclient: Deleting old routes Mar 15 21:22:05 1100 dhclient[82426]: bound: renewal in 2839 seconds.
It is then stuck there, until the lease expires or dhclient is restarted in some way, without an IP on the interface. It does not try to pull a new lease so even if the dhcp server becomes available it will not get that IP for 47mins in this case.
With the patches it behaves as expected:
Mar 15 21:41:34 1100 dhclient: PREINIT Mar 15 21:41:34 1100 dhclient[81105]: DHCPREQUEST on mvneta0 to 255.255.255.255 port 67 Mar 15 21:41:36 1100 dhclient[81105]: DHCPREQUEST on mvneta0 to 255.255.255.255 port 67 Mar 15 21:41:39 1100 dhclient[81105]: DHCPREQUEST on mvneta0 to 255.255.255.255 port 67 Mar 15 21:41:47 1100 dhclient[81105]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 1 Mar 15 21:41:48 1100 dhclient[81105]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 2 Mar 15 21:41:50 1100 dhclient[81105]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 4 Mar 15 21:41:54 1100 dhclient[81105]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 4 Mar 15 21:41:58 1100 dhclient[81105]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 9 Mar 15 21:42:07 1100 dhclient[81105]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 10 Mar 15 21:42:17 1100 dhclient[81105]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 13 Mar 15 21:42:30 1100 dhclient[81105]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 15 Mar 15 21:42:45 1100 dhclient[81105]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 3 Mar 15 21:42:48 1100 dhclient[81105]: No DHCPOFFERS received. Mar 15 21:42:48 1100 dhclient[81105]: Trying recorded lease 172.21.16.190 Mar 15 21:42:48 1100 dhclient: TIMEOUT Mar 15 21:42:48 1100 dhclient: Starting add_new_address() Mar 15 21:42:48 1100 dhclient: ifconfig mvneta0 inet 172.21.16.190 netmask 255.255.255.0 broadcast 172.21.16.255 Mar 15 21:42:48 1100 dhclient: New IP Address (mvneta0): 172.21.16.190 Mar 15 21:42:48 1100 dhclient: New Subnet Mask (mvneta0): 255.255.255.0 Mar 15 21:42:48 1100 dhclient: New Broadcast Address (mvneta0): 172.21.16.255 Mar 15 21:42:48 1100 dhclient: New Routers (mvneta0): 172.21.16.1 Mar 15 21:42:49 1100 dhclient: New Routers (mvneta0): 172.21.16.1 Mar 15 21:42:50 1100 dhclient: Deleting old routes Mar 15 21:42:50 1100 dhclient[81105]: Trying recorded lease 192.168.140.10 Mar 15 21:42:50 1100 dhclient: TIMEOUT Mar 15 21:42:50 1100 dhclient: Starting add_new_address() Mar 15 21:42:50 1100 dhclient: ifconfig mvneta0 inet 192.168.140.10 netmask 255.255.255.0 broadcast 192.168.140.255 Mar 15 21:42:50 1100 dhclient: New IP Address (mvneta0): 192.168.140.10 Mar 15 21:42:50 1100 dhclient: New Subnet Mask (mvneta0): 255.255.255.0 Mar 15 21:42:50 1100 dhclient: New Broadcast Address (mvneta0): 192.168.140.255 Mar 15 21:42:50 1100 dhclient: New Routers (mvneta0): 192.168.140.1 Mar 15 21:42:51 1100 dhclient: New Routers (mvneta0): 192.168.140.1 Mar 15 21:42:52 1100 dhclient: Deleting old routes Mar 15 21:42:52 1100 dhclient[81105]: No working leases in persistent database - sleeping. Mar 15 21:42:52 1100 dhclient: FAIL Mar 15 21:43:03 1100 dhclient[17438]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 2
It fails to find a dhcp server or previous leases/gateways responding to ping and sleeps before restarting. Repeat.
Thus when the dhcp server is available again:
Mar 15 21:46:56 1100 dhclient[17438]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 5 Mar 15 21:47:01 1100 dhclient[17438]: DHCPDISCOVER on mvneta0 to 255.255.255.255 port 67 interval 10 Mar 15 21:47:02 1100 dhclient[17438]: DHCPOFFER from 192.168.140.1 Mar 15 21:47:02 1100 dhclient: ARPSEND Mar 15 21:47:04 1100 dhclient: ARPCHECK Mar 15 21:47:04 1100 dhclient[17438]: DHCPREQUEST on mvneta0 to 255.255.255.255 port 67 Mar 15 21:47:04 1100 dhclient[17438]: DHCPACK from 192.168.140.1 Mar 15 21:47:04 1100 dhclient: BOUND Mar 15 21:47:04 1100 dhclient: Deleting old routes Mar 15 21:47:04 1100 dhclient: Starting add_new_address() Mar 15 21:47:04 1100 dhclient: ifconfig mvneta0 inet 192.168.140.10 netmask 255.255.255.0 broadcast 192.168.140.255 Mar 15 21:47:04 1100 dhclient: New IP Address (mvneta0): 192.168.140.10 Mar 15 21:47:04 1100 dhclient: New Subnet Mask (mvneta0): 255.255.255.0 Mar 15 21:47:04 1100 dhclient: New Broadcast Address (mvneta0): 192.168.140.255 Mar 15 21:47:04 1100 dhclient: New Routers (mvneta0): 192.168.140.1 Mar 15 21:47:04 1100 dhclient: Adding new routes to interface: mvneta0 Mar 15 21:47:04 1100 dhclient: /sbin/route add default 192.168.140.1 Mar 15 21:47:04 1100 dhclient: Creating resolv.conf Mar 15 21:47:04 1100 dhclient[17438]: bound to 192.168.140.10 -- renewal in 3238 seconds.
Tested:
2.4.5-RC (arm64) built on Sun Mar 15 06:05:30 EDT 2020 FreeBSD 11.3-STABLE
With patch: https://redmine.pfsense.org/attachments/download/2682/pfsense-dhclient-script-patch.txt
Updated by Renato Botelho over 4 years ago
Patch to pfSense-dhclient-script was applied on 2.4.5 as well
Updated by Jim Pingle over 4 years ago
- Target version changed from 2.5.0 to 2.4.5