Expiring DHCP lease due to inactive dhclient

mschilling

With my cable provider Unitymedia in Germany the IPv4 WAN DHCP lease expires approximately every two days.

Capturing DHCP traffic and inspecting log files revealed the following:

The DHCP server of Unitymedia never replies to the unicast DHCP request in the renew phase. So afterwards the rebind phase starts always, where DHCP request are sent by broadcasts.

The problem: Sometimes dhclient of pfSense does not emit a DHCP request in the rebind phase. As a consequence the lease expires.

List of unsuccessful attempts to solve the problem:

Making dhclient more aggressive by using the configuration presented by https://calomel.org/dhclient.html
Attempt to map the unicasts in the renew phase to broadcasts by extending dhclient.conf with the option
supersede dhcp-server-identifier 255.255.255.255;
This option had no effect.

So I reverted to the unmodified version of dhclient.conf.

I have no more ideas and ask for help.

Information about the last expiring today at local time 14:09:20 (= 12:09:20 UTC)

syslog

Jul  6 12:15:46 a4a24a3f762a dhclient: RENEW
Jul  6 12:15:46 a4a24a3f762a dhclient: Creating resolv.conf
Jul  6 13:09:20 a4a24a3f762a dhclient: RENEW
Jul  6 13:09:20 a4a24a3f762a dhclient: Creating resolv.conf
Jul  6 14:09:21 a4a24a3f762a dhclient: EXPIRE
Jul  6 14:09:21 a4a24a3f762a dhclient: Starting delete_old_states()
Jul  6 14:09:21 a4a24a3f762a dhclient: Comparing IPs: Old: 109.90.124.158 New:
Jul  6 14:09:21 a4a24a3f762a dhclient: Removing states from old IP '109.90.124.158' (new IP '')
Jul  6 14:09:21 a4a24a3f762a dhclient: Deleting old routes
Jul  6 14:09:21 a4a24a3f762a dhclient: PREINIT
Jul  6 14:09:21 a4a24a3f762a dhclient: Starting delete_old_states()
Jul  6 14:09:21 a4a24a3f762a dhclient: ARPSEND
Jul  6 14:09:23 a4a24a3f762a dhclient: ARPCHECK
Jul  6 14:09:23 a4a24a3f762a dhclient: BOUND
Jul  6 14:09:23 a4a24a3f762a dhclient: Starting add_new_address()
Jul  6 14:09:23 a4a24a3f762a dhclient: ifconfig vr0 inet 109.90.124.158 netmask 255.255.252.0 broadcast 255.255.255.255
Jul  6 14:09:23 a4a24a3f762a dhclient: New IP Address (vr0): 109.90.124.158
Jul  6 14:09:23 a4a24a3f762a dhclient: New Subnet Mask (vr0): 255.255.252.0
Jul  6 14:09:23 a4a24a3f762a dhclient: New Broadcast Address (vr0): 255.255.255.255
Jul  6 14:09:23 a4a24a3f762a dhclient: New Routers (vr0): 109.90.124.1
Jul  6 14:09:23 a4a24a3f762a dhclient: Adding new routes to interface: vr0
Jul  6 14:09:23 a4a24a3f762a dhclient: /sbin/route add default 109.90.124.1
Jul  6 14:09:23 a4a24a3f762a dhclient: Creating resolv.conf
Jul  6 15:02:44 a4a24a3f762a dhclient: RENEW
Jul  6 15:02:44 a4a24a3f762a dhclient: Creating resolv.conf
Jul  6 15:55:32 a4a24a3f762a dhclient: RENEW
Jul  6 15:55:32 a4a24a3f762a dhclient: Creating resolv.conf

tcpdump

[2.1.4-RELEASE][root@a4a24a3f762a]/tmp(10): tcpdump -l -n -i vr0 -s 1500 '((port 67 or port 68) and (udp[38:4] = 0xb91cdbe0))' | tee tcpdump-01.cap
…

12:13:01.694809 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:15:46.041981 IP 109.90.124.158.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:15:46.274162 IP 10.156.192.1.67 > 109.90.124.158.68: BOOTP/DHCP, Reply, length 313
12:45:46.504088 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:45:48.731497 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:45:50.734922 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:45:52.964403 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:45:57.074286 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:46:03.004563 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:46:15.010139 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:46:39.859471 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:47:08.172549 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:47:20.852275 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:47:42.163853 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:47:57.657158 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:48:40.468438 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:49:07.117082 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:49:39.143037 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:50:55.578082 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:51:23.071927 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:51:53.952559 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:52:49.104474 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:52:58.653446 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:53:06.343074 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:53:18.290660 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:53:38.710045 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:53:45.570514 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:54:00.967821 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:54:30.423131 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:55:07.313146 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:55:58.161982 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
12:57:46.563670 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:00:09.036909 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:04:14.165545 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:09:20.033075 IP 109.90.124.158.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:09:20.247465 IP 10.156.192.1.67 > 109.90.124.158.68: BOOTP/DHCP, Reply, length 313
13:39:20.125182 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:39:21.128314 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:39:23.131742 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:39:26.030358 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:39:32.779820 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:39:41.954790 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:39:51.778900 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:40:01.265929 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:40:11.645161 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:40:28.645809 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:40:37.725762 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:40:52.867018 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:41:14.769691 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:41:35.173069 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:42:01.398710 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:43:13.351243 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:46:44.639286 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:49:24.003497 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:53:06.728317 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:54:48.113073 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:56:18.698530 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
13:58:28.372348 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:01:37.259921 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300  <== Last request in renew phase
14:09:21.246409 IP 0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300      <== Lease expired
14:09:21.464821 IP 10.156.192.1.67 > 109.90.124.158.68: BOOTP/DHCP, Reply, length 313
14:09:23.168828 IP 0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:09:23.183351 IP 10.156.192.1.67 > 109.90.124.158.68: BOOTP/DHCP, Reply, length 313
14:39:23.554974 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:39:25.558157 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:39:30.338053 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:39:42.954409 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:39:51.197993 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:40:00.257697 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:40:11.876888 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:40:20.910575 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:40:39.155058 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:40:56.364169 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:41:26.481264 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:41:54.827100 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:42:40.900086 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:43:18.112901 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:43:27.539072 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:43:42.938014 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:44:01.309313 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:44:44.014862 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:45:29.438813 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:45:55.753343 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:46:11.123818 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:46:53.093119 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:48:09.131303 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:49:59.550031 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:51:38.111347 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:51:57.163739 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:52:10.938546 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:52:31.519252 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:53:05.379815 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:53:25.992629 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:53:53.221394 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:54:17.547979 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:54:42.612741 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:54:54.497004 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:55:14.725849 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:55:50.215620 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:56:21.459546 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:57:27.520451 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
14:59:46.639752 IP 109.90.124.158.68 > 10.156.192.1.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
15:02:44.547265 IP 109.90.124.158.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 00:0d:b9:1c:db:e0, length 300
15:02:44.799893 IP 10.156.192.1.67 > 109.90.124.158.68: BOOTP/DHCP, Reply, length 313
…

Extract of the information about the failing lease in /var/db/dhclient.leases.vr0

lease {
  interface "vr0";
  fixed-address 109.90.124.158;
  option subnet-mask 255.255.252.0;
  option time-offset 7200;
  option routers 109.90.124.1;
  option domain-name-servers 80.69.102.158,80.69.103.78;
  option host-name "a4a24a3f762a";
  option domain-name "upc.de";
  option broadcast-address 255.255.255.255;
  option dhcp-lease-time 3600;
  option dhcp-message-type 5;
  option dhcp-server-identifier 10.156.192.1;
  renew 0 2014/7/6 11:39:20;
  rebind 0 2014/7/6 12:01:50;
  expire 0 2014/7/6 12:09:20;
}

dhclient.conf

[2.1.4-RELEASE][root@a4a24a3f762a]/root(2): cat /var/etc/dhclient_wan.conf
interface "vr0" {
timeout 60;
retry 15;
select-timeout 0;
initial-interval 1;

        script "/sbin/dhclient-script";
        reject 192.168.100.1;
}
[2.1.4-RELEASE][root@a4a24a3f762a]/root(3):

cmb

Do you have that tcpdump-01.cap file you can send me? Can email to cmb at pfsense dot org with a link to this thread.

mschilling

Sent private E-Mail.

cmb

Thanks, the second one with the binary contents is what I was looking for. The behavior by your ISP is odd. I'm running short on time for the day and will have to revisit this later to review in further detail.

If this is a system you can experiment with a bit with minimal consequences, would you mind giving a 2.2 snapshot from snapshots.pfsense.org a try on there and see if the behavior there differs? Much has changed in the base OS from FreeBSD 8.3 to 10.0 so it might. If it works there it's probably not worth looking into any further, though maybe that'll lead you to something that can be easily back-ported if you want a fix on 2.1.x.

mschilling

I agree that the behavior of my ISP is odd, but I think it does not violate the DHCP protocol (RFC 2131).

I will give a pfSense 2.2 snapshot a try after I will have succeeded in establishing a backup internet gateway. I already offloaded the important servers for my LAN (DNS, DHCP, NTP, SSH) to a Raspberry Pi with Raspbian. Hence the requirements to a backup internet gateway are lowered. A TP-Link TL-WDR3600 is already on the way from Amazon.

I will report in a few days.

Thank you.

mschilling

The results of trying pfSense 2.2 snapshot (pfSense-2.2-DEVELOPMENT-1g-i386-nanobsd-upgrade-20140711-1504.img.gz) are:

The problem is still existent.
The frequency of occurrence seems to be reduced.

The last statement is weak. Due to lack of time my test was run only over 2 sessions each comprising 2 days. Session #1 had no problems, #2 experienced one loss of DHCP lease. Unfortunately I already moved from the respective site and will not return before december. For reason of stability I replaced pfSense with the o.m. combination of a Raspberry Pi and a TP-LINK router. So at present I am not able perform further tests.