Dhcp lease client hostname missing (with 2.3)

vynce

Interesting. I'll have to take a closer look at dhcpd.leases~. Unless some other tool is writing to dhcpd.leases, it seems like it must be a problem with dhcpd itself. It's strange that I haven't come across reports of this issue anywhere else online or in the ISC dhcp mailing list archives yet though.

I took this script and trimmed it down to just poll for changes in dhcpd.leases and archive off a snapshot whenever it changed:


#!/bin/sh

outdir="/tmp/dhcpd_snapshots"
watchcmnd="cat /var/dhcpd/var/db/dhcpd.leases | md5"
execcmnd="cp /var/dhcpd/var/db/dhcpd.leases $outdir/dhcpd_\`date +%F_%T\`.leases"

mkdir -p $outdir
md5=`eval $watchcmnd`
md5Now=$md5
echo "`date +%F_%T`"
eval $execcmnd

while [ true ] ; do
    while [ $md5Now = $md5 ] ; do
        sleep 1
        md5Now=`eval $watchcmnd`
    done

    echo "`date +%F_%T`"
    eval $execcmnd

    md5=$md5Now
done

Looking at these snapshots, the dhcpd log, and a packet capture log, here's what I'm seeing so far:

ClientA sends a DHCP request at 02:37:59 UTC.
This client already has a lease, so dhcpd just renews it by updating the starts, ends, and cltt fields for its lease in dhcpd.leases.
At the same time, it updates the cltt field on ClientB's lease from 00:15:13 to 01:14:25 and deletes its client-hostname field at the same time.

Since there's no dhcpd.leases file snapshot at anywhere near 01:14:25, dhcpd must be caching some non-critical changes in memory and only writing them out in batches when one of the leases actually change – that doesn't really explain why AsgardianFW only saw a hostname disappear by itself when compared to the backup leases file though.

cltt is the client's last transaction time (man), so looking back in the packet capture log to 01:14:25, there are two DHCP broadcast requests (and associated ACKs) from ClientB. Both requests and ACKs are identical (except for the IP IDs, transaction IDs, checksums, etc).

The dhcpd log matches up:


01:14:25 pfsense dhcpd: reuse_lease: lease age 3552 (secs) under 25% threshold, reply with unaltered, existing lease
01:14:25 pfsense dhcpd: DHCPREQUEST for 192.168.1.149 from Apple:ClientB via re1
01:14:25 pfsense dhcpd: DHCPACK on 192.168.1.149 to Apple:ClientB via re1
01:14:25 pfsense dhcpd: reuse_lease: lease age 3552 (secs) under 25% threshold, reply with unaltered, existing lease
01:14:25 pfsense dhcpd: DHCPREQUEST for 192.168.1.149 from Apple:ClientB via re1
01:14:25 pfsense dhcpd: DHCPACK on 192.168.1.149 to Apple:ClientB via re1

One odd thing is that the two requests are only ~3ms apart (associated ACKs are sent within ~0.6ms). Since this is UDP and I'm doing the packet capture on pfSense itself and in this case ClientB is an iPhone on wifi, perhaps the first ACK just got lost or delayed long enough that ClientB sent another request (?).

According to the packet capture, both requests include the client hostname. I'm guessing there's something about those requests that dhcpd isn't handling well. Maybe it's dropping the hostname from the leases file whenever it responds with an unaltered existing lease?

I'll need to dig through my logs some more to see how closely other instances of disappearing hostnames match up with this pattern.

vynce

pfSense 2.3.1 is running ISC DHCP Server 4.3.3-P1. Looking through the 4.3.4+ release notes, the only item that stood out to me was:


- Added the lease address to the end of the debug level log message
  emitted when an existing lease is renewed within the dhcp-cache-threshold.
  Thanks to Nathan Neulinger at Missouri S&T for suggesting the change.
  [ISC-Bugs #40598]

There are quite a few bug fixes, but it's difficult to tell if any of them are related to this issue.

cmb

Added a bug ticket for this issue, as there definitely is something to it.
https://redmine.pfsense.org/issues/6589

AsgardianFW

Vynce, perhaps you're on to something. I can add a little more evidence to the pile. For me, this only seems to happen for devices connected wirelessly. Although, I will confess that almost all of my wired devices have a static lease in DHCP. I do have 1 Windows desktop that is permanently connected via wire and has a dynamic lease. It has never exhibited this problem. I also have 1 Windows laptop that is connected wirelessly from time to time and I've never seen it lose its hostname (but the laptop isn't on all the time). 2 data points may not be enough to draw a proper conclusion, but so far the problem seems to target Android and Apple phones and tablets connected wirelessly (I have 6 different models of these devices so it doesn't appear model specific). At one point I thought it might be related to roaming between access points on my wireless network, but I did observe a loss of hostname of my phone while I was holding it in my hand sitting at the computer watching hostnames (so while I'm not 100% sure, I don't think it changed access points).

AsgardianFW

Please don't hate me for this, but I installed OPNSense (16.7 RC1) in a small, non-essential location (with 2 iPhone users) because it has ISC DHCP Server 4.3.4. I just confirmed that it, too, loses hostnames so the problem isn't addressed in the newer dhcp version.

cmb

@AsgardianFW:

For me, this only seems to happen for devices connected wirelessly.

I doubt it's wireless-related. dhcpd has no way of knowing how a device is connected, a wifi lease looks exactly the same as a wired lease.

Thanks for confirming the behavior hasn't changed in 4.3.4.

This probably needs to be escalated to the ISC dhcpd list to hopefully get feedback there.

AsgardianFW

cmb,
Who should do the escalation? One of us? You?

cmb

I'm not going to have time to see it to resolution with only 2 weeks left. If one of you can push it along, that'd help get to a faster resolution (I hope). Otherwise someone should get to it at some point.

vynce

Thanks Chris. I've posted to the dhcp-users mailing list. Hopefully they have some suggestions :)

cmb

@Vynce:

Thanks Chris. I've posted to the dhcp-users mailing list. Hopefully they have some suggestions :)

Thanks, I followed up on that thread with some specifics as well.

zxvv

Are you synchronizing two dhcpd servers that are doing dynamic dns registration?

I believe there is a known limitation in the isc-dhcpd sychronization, in that it transfers the lease between dhcpd servers, but fails to transfer the host name.

vynce

Thanks for the heads up on that sync issue. In my case it's just a super basic configuration – no redundancy, syncing, or anything.

vynce

Shawn Routhier (ISC DHCP lead engineer) suggested adding "dhcp-cache-threshold 0;" to dhcpd.conf to disable an optimization that allows dhcpd to skip updating dhcpd.leases when a client requests an updated lease after less than 25% of the lease time.

Here's how I made that change in case anyone else wants to give it a try. Not sure if it's the best way, but the setting has been added to dhcpd.conf at least.

Diagnostics -> Edit File.
Paste "/etc/inc/services.inc" in the box and click Load.
Add "dhcp-cache-threshold 0;" on line 541. There's another location around line 1285 for dhcpdv6 if that applies to your configuration.
Click save.
Services -> DHCP Server.
Click save to regenerate dhcpd.conf and kick dhcpd itself to reload its config.

Now to wait and see what happens :)

AsgardianFW

My setup is also pretty simple. The only non-default settings I have are some static leases and the default lease time is set to 86400 (24 hrs). The longer lease time makes is easier to see the problem because the hostname comes back after a lease renewal. The default time of 2 hours somewhat hides the hostname issue unless you're really watching it.

I have made the suggested change to disable the optimization and I'll report back within 24 hours.

AsgardianFW

So far this works at my smaller office. I'm deploying the "fix" to a larger office for additional verification.

vynce

This workaround fixed my two installations as well :D. I'll reply to the dhcp-users mailing list and hopefully we can come up with a proper fix for the next version of isc-dhcpd.

cmb

I implemented that workaround for 2.3.2, since disabling the cache threshold won't have any impact on our users' use cases and it does appear to avoid the root cause problem.

Thanks for getting the ball rolling on that one Vynce, had I realized a workaround would have come that easily, I'd have done so some time ago.

AsgardianFW

Thanks Vynce for championing this effort with ISC.

Thanks cmb for incorporating this into the next version. I wasn't looking forward to remembering to patch this in manually after every upgrade. I wish you the best of luck for whatever is next for you.

vynce

Thanks Chris! I've opened a bug ticket in the isc-dhcp project to address the root issue: [ISC-Bugs #42849]. Their bug tracker appears to be closed to the public due to privacy concerns. Do we need to try and get some pfSense project email address added as a watcher? Not sure if you intend for the workaround to be reverted when the root issue is fixed…

cmb

Thanks Vynce. Once it's fixed, please start a new ticket at redmine.pfsense.org to revert that change, as it would be preferable to go back to the default there once it doesn't break other things.