Project

General

Profile

Actions
Copy link

Bug #9267

closed

dhclient does not handle protocol timeouts or script failures correctly

Added by Nash Kaminski over 5 years ago. Updated about 4 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
-
Category:
Interfaces
Target version:
2.4.5
Start date:
01/10/2019
Due date:
% Done:

0%

Estimated time:
Plus Target Version:
Release Notes:
Affected Version:
All
Affected Architecture:
All

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

Download all files
pfsense-dhclient-script-patch.txt (1.5 KB) pfsense-dhclient-script-patch.txt Nash Kaminski, 01/10/2019 06:59 PM
dhclient-patch.txt (327 Bytes) dhclient-patch.txt Nash Kaminski, 01/10/2019 07:38 PM
Actions
Copy link
 #1

Updated by Nash Kaminski over 5 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.

Actions
Copy link
 #3

Updated by Jim Pingle almost 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 ()
Actions
Copy link
 #4

Updated by Patrick Staton over 4 years ago

Any status on this? It pretty much breaks our router being able to handle power outages.

Actions
Copy link
 #5

Updated by Jim Pingle over 4 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.

Actions
Copy link
 #6

Updated by Steve Wheeler about 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

Actions
Copy link
 #7

Updated by Renato Botelho about 4 years ago

Patch to pfSense-dhclient-script was applied on 2.4.5 as well

Actions
Copy link
 #8

Updated by Jim Pingle about 4 years ago

  • Target version changed from 2.5.0 to 2.4.5
Actions
Copy link
 #9

Updated by Jim Pingle about 4 years ago

  • Status changed from New to Resolved
Actions
Copy link

Also available in: Atom PDF