How often 'should' clients be making DHCPREQUEST queries?
-
It's been a bunch of fun setting up my new pfsense router. All sorts of discoveries like devices ignoring DHCP-provided DNS server info and making direct requests (chromecast, hue, blink etc).
As I delve through the various logs I happened to notice a lot of what look like repetitive DHCP negotiations. Like these:
Feb 9 10:06:41 dhcpd DHCPACK on 192.168.12.50 to 2c:54:91:13:d2:70 via igb1 Feb 9 10:07:15 dhcpd DHCPDISCOVER from 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:07:15 dhcpd DHCPOFFER on 192.168.12.22 to 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:07:15 dhcpd DHCPREQUEST for 192.168.12.22 (192.168.12.1) from 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:07:15 dhcpd DHCPACK on 192.168.12.22 to 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:07:25 dhcpd DHCPREQUEST for 192.168.12.28 from 00:0b:82:c3:80:3a via igb1 Feb 9 10:07:25 dhcpd DHCPACK on 192.168.12.28 to 00:0b:82:c3:80:3a via igb1 Feb 9 10:08:35 dhcpd DHCPREQUEST for 192.168.12.47 from 00:23:38:11:cd:0c via igb1 Feb 9 10:08:35 dhcpd DHCPACK on 192.168.12.47 to 00:23:38:11:cd:0c via igb1 Feb 9 10:08:36 dhcpd DHCPREQUEST for 192.168.12.40 from 94:10:3e:30:c4:ad via igb1 Feb 9 10:08:36 dhcpd DHCPACK on 192.168.12.40 to 94:10:3e:30:c4:ad via igb1 Feb 9 10:09:01 dhcpd DHCPREQUEST for 192.168.12.84 from 00:11:d9:61:e6:f5 via igb1 Feb 9 10:09:01 dhcpd DHCPACK on 192.168.12.84 to 00:11:d9:61:e6:f5 via igb1 Feb 9 10:09:21 dhcpd DHCPDISCOVER from 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:09:21 dhcpd DHCPOFFER on 192.168.12.22 to 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:09:21 dhcpd DHCPREQUEST for 192.168.12.22 (192.168.12.1) from 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:09:21 dhcpd DHCPACK on 192.168.12.22 to 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:10:57 dhcpd DHCPREQUEST for 192.168.12.19 from 00:17:eb:0e:29:d0 via igb1 Feb 9 10:10:57 dhcpd DHCPACK on 192.168.12.19 to 00:17:eb:0e:29:d0 via igb1 Feb 9 10:11:28 dhcpd DHCPDISCOVER from 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:11:28 dhcpd DHCPOFFER on 192.168.12.22 to 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:11:28 dhcpd DHCPREQUEST for 192.168.12.22 (192.168.12.1) from 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:11:28 dhcpd DHCPACK on 192.168.12.22 to 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:11:44 dhcpd DHCPREQUEST for 192.168.12.151 (192.168.12.1) from 02:42:a2:eb:cb:5e via igb1 Feb 9 10:11:44 dhcpd DHCPACK on 192.168.12.151 to 02:42:a2:eb:cb:5e via igb1 Feb 9 10:11:44 dhcpleases Sending HUP signal to dns daemon(74966) Feb 9 10:13:07 dhcpd DHCPREQUEST for 192.168.12.75 from 00:e0:4c:36:43:ef via igb1 Feb 9 10:13:07 dhcpd DHCPACK on 192.168.12.75 to 00:e0:4c:36:43:ef via igb1 Feb 9 10:13:34 dhcpd DHCPDISCOVER from 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:13:34 dhcpd DHCPOFFER on 192.168.12.22 to 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:13:34 dhcpd DHCPREQUEST for 192.168.12.22 (192.168.12.1) from 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:13:34 dhcpd DHCPACK on 192.168.12.22 to 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:14:35 dhcpd DHCPREQUEST for 192.168.12.51 from 28:18:78:ea:aa:1e via igb1 Feb 9 10:14:35 dhcpd DHCPACK on 192.168.12.51 to 28:18:78:ea:aa:1e via igb1 Feb 9 10:15:41 dhcpd DHCPDISCOVER from 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:15:41 dhcpd DHCPOFFER on 192.168.12.22 to 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:15:41 dhcpd DHCPREQUEST for 192.168.12.22 (192.168.12.1) from 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:15:41 dhcpd DHCPACK on 192.168.12.22 to 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:17:47 dhcpd DHCPDISCOVER from 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:17:47 dhcpd DHCPOFFER on 192.168.12.22 to 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:17:47 dhcpd DHCPREQUEST for 192.168.12.22 (192.168.12.1) from 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:17:47 dhcpd DHCPACK on 192.168.12.22 to 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:19:51 dhcpd DHCPREQUEST for 192.168.12.122 from 00:0e:58:71:74:f8 via igb1 Feb 9 10:19:51 dhcpd DHCPACK on 192.168.12.122 to 00:0e:58:71:74:f8 via igb1 Feb 9 10:19:54 dhcpd DHCPDISCOVER from 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:19:54 dhcpd DHCPOFFER on 192.168.12.22 to 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:19:54 dhcpd DHCPREQUEST for 192.168.12.22 (192.168.12.1) from 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:19:54 dhcpd DHCPACK on 192.168.12.22 to 00:03:7f:1b:4c:b2 via igb1 Feb 9 10:20:59 dhcpd DHCPREQUEST for 192.168.12.60 from 00:23:24:ae:e8:20 via igb1 Feb 9 10:20:59 dhcpd DHCPACK on 192.168.12.60 to 00:23:24:ae:e8:20 via igb1
These are all devices that have DHCP leases set up for them. They're on the leased addresses. They're all 'devices' not computers. Various gizmos like Sonos speakers, camera gateways, thermostats and the like. None are PCs, at least not in the sense that they have any sort of on-board log or UI that would assist in explaining themselves. They're not emitting errors or otherwise malfunctioning. They're just repeatedly making the DHCP negotiations and I'm curious as to why.
They're not even all coming through the same network path to the router. Although I do have to revisit the rats nest of cabling leading to all the various switches and access points. Things 'grow' over time and I'd wonder if this is a 'canary in the coal mine' telling me there's a switch somewhere in the mix that's acting up?
So let me ask, what's a normal amount of DHCP negotiation for a LAN client? And where would I properly determine/debug when something's abnormal?
-
Normally, a client will renew the lease part way through, perhaps 1/2 or 2/3, of the lease time. What's the lease time set for? Normally, it's 7200 seconds (2 hours).
-
As the client gets closer to the end of the lease it will start to panic and send out lots of requests for renewal.. When the lease finally expires then it would send out discover..
Looks like your clients are getting offers and asking for them and even getting back the ack, etc. Its possible you just have set a really short lease time? Look to the actual lease for these clients you can view the leases on pfsense.
-
There's no entry in the default least time field in the pfsense, the caption text indicates the default is 7200 seconds.
When I check on a client win7 PC it states: "Lease Obtained: Thursday, January 25, 2018 5:29:39 PM Lease Expires: Saturday, February 10, 2018 8:07:48 AM". Which I have to think the 1/25 date being when it was initial obtained, not necessarily the current lease origination. When I check on the router itself I see another dynamic lease as "2018/02/10 06:16:43 2018/02/10 08:16:43"… the two hour window.
Curiously, the static leases (on the /status_dhcp_leases.php page) show no Start/End timestamps, just online or offline. I get that they're static, and not bound by a timeframe, but is there a way to see when they were issued?
It's possible that might matter as the devices spewing these requests ARE all on static leases.
I generally prefer to put all my devices on static leases, if just to make it simpler to tell distinguish devices when looking at logs and such. Whenever possible I manually configure them (on device) as static, but many newer gizmos don't always have a UI for setting that up. Thus static leases handle it.
-
I rarely set anything static on the device and always just do a reservation in the dhcp server for what IP I want them to have..
That lease windows seems to be an odd length of time? Jan 25th to odd time on feb 10th?? Normally they would be in even increments.. Off the top of the head I do not believe dhcpd keeps a copy of static leases (reservations) in the .leases or .leases~ files
It think its up to the client in such cases on keeping track.. Its quite possible could be something going funky on there - what if you do a full release and renew on the client, this should get you a new lease with new obtained and expired times that match up exactly with whatever your lease times are set for, etc.
My box is actually showing odd times as well..
Lease Obtained. . . . . . . . . . : Monday, January 29, 2018 5:45:44 AM
Lease Expires . . . . . . . . . . : Thursday, February 15, 2018 5:45:44 AMAt most it should be 4 days.. So I just did a renew
Lease Obtained. . . . . . . . . . : Monday, January 29, 2018 5:45:44 AM
Lease Expires . . . . . . . . . . : Thursday, February 15, 2018 10:34:20 AMAnd while the obtained date did not change since it was a renew and not a discover, etc. The new expired jumped by 2 days… I would have to sniff and see what actually happened.
If you have a client that just keeps asking and asking for renewal, etc.. I would prob release it at the client and let it do a new discover, etc.
-
I would prob release it at the client and let it do a new discover, etc.
Hard to do sometimes on devices that have no UI. Many are typically set up via an app on a phone/tablet or sometimes via on-device web server page. But few, if any, offer actual release/renew features on what little UI they offer.
I've shelved this into the "it ain't broke, don't fix it" slot for now. At some point I'd like to figure it out, but stuff's working so I'm going to stop looking at the log…