Expiring DHCP lease due to inactive dhclient



  • 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):
    
    


  • 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.



  • Sent private E-Mail.



  • 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.



  • 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.



  • 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.