Possible DHCP Issues

divsys

My DHCP lease time is 24 hours, so the phone wouldn't normally attempt any further DHCP communication until 11:27 the next day

Small aside - many (most?) devices will attempt to re-establish their DHCP lease well ahead of it's expiry.
It's not uncommon to see a lease attempt at 1/3 to 1/2 the expiry time.

That may affect your view of the relevant logs.
$.02

AsgardianFW

divsys, you are correct. I have ascertained that my phone will refresh its lease at 1/2 time which is why I didn't expect anything until 11:37. My phrasing may have been unclear. The point I was trying to make is that there was no communication between the phone and DHCP server (and nor was there any expected), but somehow the DHCP server dropped the hostname. I'm going to test this theory later, but I am guessing that the hostname will reappear at the 1/2 time renegotiation. I'm also going to track more closely exactly when the DHCP server drops the hostname to see if the timing correlates with anything.

Also, no one else is chiming in reporting similar issues, so I'm left to wonder if it's just me. Or perhaps the default shorter lease doesn't show the problem as often. If no one else can confirm, then perhaps I should reimage my box from the latest snap to see if the problem goes away. This is a relatively minor problem, but it makes our reports harder to read because it shows IP addresses instead of names. MarksiPhone is clear. 10.11.12.210 is unclear.

cmb

That log snippet shows it is sending a hostname, "android-dc49b48ab4ff452". What do its lease entries in /var/dhcpd/var/db/dhcpd.leases look like?

AsgardianFW

The entries are consistent with what I see in the web gui. When the gui shows the hostname, there is a hostname line for that device in the file. When the gui doesn't show the hostname, the file does not have a hostname line. Currently, the hostname is still in there (but neither me nor my phone have been there since around 7:30 this morning):

lease 10.11.12.224 {
  starts 4 2016/02/25 12:23:31;
  ends 5 2016/02/26 12:23:31;
  cltt 4 2016/02/25 12:23:31;
  binding state active;
  next binding state free;
  rewind binding state free;
  hardware ethernet 24:da:3b:a9:5f:1b;
  uid "\001$\332\073\251\137\033";
  set vendor-class-identifier = "dhcpcd-5.5.6";
  client-hostname "android-dc49b48ab4ff452";
}

cmb

So that shows dhcpd is using what's given to it, and dhcpleases process is using what's available to it. Has to be the client in that case, or I guess it's feasible some intermediate device is manipulating the DHCP requests though that seems unlikely. Packet capture DHCP requests to verify.

AsgardianFW

It will take me 2-5 days to get the packet capture as I have to go to another office for a few days. Are you interested in all DHCP (which will be very verbose as we have quite a few Windows machine and they seem to speak DHCP way too often) or are you just interested in my phone's chatter?

cmb

Just the requests from the phone would suffice, but it might be hard to filter strictly on that. I'd probably filter with just 'port 67 or port 68' on tcpdump, even across days of DHCP requests with hundreds of clients, that wouldn't add up to anything really significant. Something like the following via SSH:

tcpdump -i igb0 -s 0 -w dhcp.pcap port 67 or port 68

where igb0 is the LAN NIC. ctrl-c to stop that after you've replicated the problem, then you can open that dhcp.pcap file in Wireshark and clearly see whether or not it's sending a client-hostname.

AsgardianFW

OK. I started a packet capture when pfSense was showing hostnames for all my devices (except the ones I know don't provide hostnames). Just 15 minutes into the packet capture and pfSense "lost" the hostnames for 2 devices. Only 18 DHCP packets were captured and I was able to study each one carefully (in Wireshark). For the 2 devices that lost their hostname, there were no DHCP packets that referenced the devices MAC address or IP address.

Note this was in the DHCP log a few minutes into the packet capture:

Feb 28 20:18:37	dhcpd		Wrote 22 leases to leases file.
Feb 28 20:18:37	dhcpd		Wrote 0 new dynamic host decls to leases file.
Feb 28 20:18:37	dhcpd		Wrote 0 deleted host decls to leases file.
.
.
Feb 28 20:22:20	dhclient	Creating resolv.conf
Feb 28 20:22:20	dhclient	RENEW

AsgardianFW

Perhaps more info in addition to previous post. I was going to start another packet capture test for overnight. The starting state is no hostname for my phone. I was going to start packet capture, switch phone from WiFi to cell and the back to WiFi (which usually gets the hostname back into pfSense) and then wait until the hostname is dropped again. While doing this procedure, I noticed that the dhcp.leases file has 2 entries for my phone (1 with hostname and 1 without). I'm not sure if this is expected behavior or not.

lease 10.11.12.224 {
  starts 0 2016/02/28 21:23:22;
  ends 1 2016/02/29 21:23:22;
  cltt 1 2016/02/29 00:33:55;
  binding state active;
  next binding state free;
  rewind binding state free;
  hardware ethernet 24:da:3b:a9:5f:1b;
  uid "\001$\332\073\251\137\033";
  set vendor-class-identifier = "dhcpcd-5.5.6";
}
.
.
.
lease 10.11.12.224 {
  starts 1 2016/02/29 04:51:32;
  ends 2 2016/03/01 04:51:32;
  cltt 1 2016/02/29 04:51:32;
  binding state active;
  next binding state free;
  rewind binding state free;
  hardware ethernet 24:da:3b:a9:5f:1b;
  uid "\001$\332\073\251\137\033";
  set vendor-class-identifier = "dhcpcd-5.5.6";
  client-hostname "android-dc49b48ab4ff452";
}

AsgardianFW

I completed my overnight test and replicated the problem again.

Start in no hostname state
Start packet capture
Switch cell phone from WiFi to Cell to WiFi to force a DHCP request and to make pfSense pick up hostname (verified)
Sleep 7.5 hours
Verify pfSense lost the hostname for cell phone in gui and dhcp.leases file
Stop packet capture (40 total packets)

When looking through all 40 packets, everything looks normal. I see the initial packets from step 3 above which do indeed include the hostname. The remaining packets also look normal but are for other devices. Besides the initial request, there are no other packets for the phone's MAC or IP yet it still lost the hostname. Same as the first (shorter) test.

I'd be open to other ideas to help figure out why pfSense is dropping the hostname for some devices.

MikeV7896

Just thought I'd mention that I'm seeing this issue as well. I have two Apple devices that usually show hostnames (and always did under 2.2.6), but now after running 2.3 for a few days, neither is showing a hostname in the DHCP Leases table.

cmb

Anything that's happening here is something to do with dhcpd itself, nothing in our code has any relation. The change from dhcpd 4.2 to 4.3 is probably at fault I'd guess, since that's the only thing that's changed. After a bit of searching I don't see any mention of issues along those lines in dhcpd or any relevant changes in behavior.

MikeV7896

Now that you've mentioned that, I checked the dhcpd.leases file and it doesn't have hostnames for the (now) three devices that don't have hostnames in the pfSense list… so I guess it must be something in dhcpd...

AsgardianFW

Is dhcpd capable of doing any kind of debug logging so that we can ascertain under what conditions it feels obligated to remove the hostname? If so, how can I enable it?
In a previous post, I mentioned that the same IP lease will be listed twice in dhcp.leases (one with a hostname and one without and each entry has different lease/expire times). Is this expected behavior?

(Please forgive my ignorant questions. I'm a Windows developer and FreeBSD isn't in my core skill set.)

AsgardianFW

As an added FYI…I checked a couple of my 2.2.5 installations and while the dhcp.leases file seems correct all the time on those, the /var/unbound/dhcpleases_entries.conf file seems to lose the occasional entry similar to the way 2.3 does in both files.

AsgardianFW

I'm still interested in trying to diagnose this problem. Is it possible for me to go back to dhcpd 4.2 in pfSense 2.3 to see if the problem still happens? This could help narrow down if there were changes in 4.3 that caused this.

gsiemon

I've just upgraded from 2.2.6 to 2.3 over the weekend and I'm seeing the same problem. Some of my devices are no longer showing hostnames in dhcpd.leases. This seems to affect all of our iOS and OS X devices

I have managed to get them to show up for a short time by editing their hostnames and then forcing a lease renewal on the client but a short time later (I suspect its when the device sleeps or goes out of range) it disappears again. I never saw this behaviour on 2.2.6.

dhcpd is configured with default settings for lease times etc. I do register the leases in a DNS server (not pfsense) and the leases file correctly lists the hostname in the FQDN registered in DNS for every device (affected or otherwise).

The only common thing I can see at the moment (and this may be a red herring) is that all of the devices that seem to have missing hostnames have 24 hour leases. The ones that seem to have sticky hostnames only have 2 hour leases.

cmb

I found one situation where it'll put in a lease entry with no hostname. If you 'ipconfig/release' on Windows, you end up with a "binding state free" lease entry like:

lease 192.168.1.100 {
  starts 2 2016/03/08 00:45:14;
  ends 2 2016/03/08 01:10:17;
  tstp 2 2016/03/08 01:10:17;
  cltt 2 2016/03/08 00:45:14;
  binding state free;
  hardware ethernet 00:0c:29:49:35:f4;
  uid "\001\000\014)I5\364";
}

but dhcpleases still finds the earlier leases and registers the hostname from the leases prior to the release.

Asgardian: if you still have the pcap files from earlier, could you send me those?

The full contents of your dhcpd.leases file from anyone that's affected would be helpful as well.

AsgardianFW

cmb,
I was just checking in to see if you figured out anything from the info I sent? I can still do more debugging for you if needed. Just let me know. Thanks.

cmb

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