DHCP started acting weird, "unknown lease"

baf · Dec 7, 2022, 2:51 AM

Hi everyone,

I have one device that DHCP on my SG-1100 has started to not get along with for some reason. That device is an EVSE, which previously has worked fine for almost a year and a half. This didn't start happening until I installed a second EVSE of the same brand, though I'm not sure why they would interfere with each other (no MAC address clash or anything like that).

What I'm seeing is that the device will initially get an address just fine from DHCP, and will renew that lease hourly:

Dec 5 10:19:03	dhcpd	83574	DHCPACK on 192.168.201.97 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 10:19:03	dhcpd	83574	DHCPREQUEST for 192.168.201.97 from c0:ee:40:86:e2:2c (WB097893) via mvneta0.201

This continues, as expected, until it misses renewing the lease at some point in time. Then it will send one or two DHCPDISCOVER messages. Sometimes two discover messages get logged before the DHCP server responds. Then the DHCP server sends an offer, and then when the client responds with a request for that new address, I see an 'unknown lease' log message

Dec 5 12:19:10	dhcpd	83574	DHCPREQUEST for 192.168.201.99 (192.168.201.1) from c0:ee:40:86:e2:2c via mvneta0.201: unknown lease 192.168.201.99.
Dec 5 12:19:10	dhcpd	83574	DHCPOFFER on 192.168.201.99 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 12:19:09	dhcpd	83574	DHCPDISCOVER from c0:ee:40:86:e2:2c via mvneta0.201
Dec 5 12:19:05	dhcpd	83574	DHCPDISCOVER from c0:ee:40:86:e2:2c via mvneta0.201

The request messages will continue being sent by the client and the 'unknown lease' log messages continue until I restart the client so it initiates a new lease. Then it is offered the same lease again, and the DHCPREQUEST is ACKed, and things work fine again for a little while (could be a few hours, could be a day) until it all repeats again.

Dec 5 18:30:57	dhcpd	14393	DHCPACK on 192.168.201.99 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 18:30:57	dhcpd	14393	DHCPREQUEST for 192.168.201.99 (192.168.201.1) from c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 18:30:57	dhcpd	14393	DHCPOFFER on 192.168.201.99 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 18:30:56	dhcpd	14393	DHCPDISCOVER from c0:ee:40:86:e2:2c (WB097893) via mvneta0.201

Here is the full 'cycle' for the above address (from when the .99 lease is granted to when a new address is offered and 'unknown lease' begins being logged):

Dec 6 03:49:19	dhcpd	14393	DHCPREQUEST for 192.168.201.100 (192.168.201.1) from c0:ee:40:86:e2:2c via mvneta0.201: unknown lease 192.168.201.100.
Dec 6 03:49:19	dhcpd	14393	DHCPOFFER on 192.168.201.100 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 6 03:49:18	dhcpd	14393	DHCPDISCOVER from c0:ee:40:86:e2:2c via mvneta0.201
Dec 6 03:49:13	dhcpd	14393	DHCPDISCOVER from c0:ee:40:86:e2:2c via mvneta0.201
Dec 6 01:49:11	dhcpd	14393	DHCPACK on 192.168.201.99 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 6 01:49:11	dhcpd	14393	DHCPREQUEST for 192.168.201.99 from c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 6 00:31:02	dhcpd	14393	DHCPACK on 192.168.201.99 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 6 00:31:02	dhcpd	14393	DHCPREQUEST for 192.168.201.99 (192.168.201.1) from c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 6 00:31:02	dhcpd	14393	DHCPOFFER on 192.168.201.99 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 6 00:31:01	dhcpd	14393	DHCPDISCOVER from c0:ee:40:86:e2:2c via mvneta0.201
Dec 5 22:30:58	dhcpd	14393	DHCPACK on 192.168.201.99 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 22:30:58	dhcpd	14393	DHCPREQUEST for 192.168.201.99 (192.168.201.1) from c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 22:30:58	dhcpd	14393	DHCPOFFER on 192.168.201.99 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 22:30:58	dhcpd	14393	DHCPDISCOVER from c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 20:31:00	dhcpd	14393	DHCPACK on 192.168.201.99 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 20:31:00	dhcpd	14393	DHCPREQUEST for 192.168.201.99 (192.168.201.1) from c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 20:31:00	dhcpd	14393	DHCPOFFER on 192.168.201.99 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 20:30:59	dhcpd	14393	DHCPDISCOVER from c0:ee:40:86:e2:2c via mvneta0.201
Dec 5 18:30:57	dhcpd	14393	DHCPACK on 192.168.201.99 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 18:30:57	dhcpd	14393	DHCPREQUEST for 192.168.201.99 (192.168.201.1) from c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 18:30:57	dhcpd	14393	DHCPOFFER on 192.168.201.99 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201
Dec 5 18:30:56	dhcpd	14393	DHCPDISCOVER from c0:ee:40:86:e2:2c (WB097893) via mvneta0.201

The device itself does seem to be acting strange (sometimes it renews the lease hourly, and other times it misses and instead sends a DHCPDISCOVER), but the behavior of the server also seems strange here in that sometimes it will offer a new address and then immediately log 'unknown lease' for it.

The device is very close to an outdoor AP (next to the newly installed EVSE), and never had any issues at this location until recently. Even still, I don't see any evidence of poor or dropping connection, and the EVSE it is next (same device, same firmware version) to has been rock solid since installation. I can't rule out interference, however, I'm confused as to why the DHCP server is behaving this way.

I also notice that I see .99 and .100 both listed on the leases list with a lease time of 24 hours (versus the 2 hours configured by default), but with no associated MAC address. I see .101 listed with an expiration time of 2 minutes after the start time (.101 was the latest IP offered that resulted in 'unknown lease', and I ended up just setting a static IP temporarily to get the device online).

Any ideas?

Gertjan · Dec 8, 2022, 11:37 AM

@baf

Are there any VLANs used ?

Lest take a look at this sequence :

The DHCP server receives :
Dec 6 01:49:11 dhcpd 14393 DHCPREQUEST for 192.168.201.99 from c0:ee:40:86:e2:2c (WB097893) via mvneta0.201

This REQUEST was emitted from the device, and it already knows it's IP, .99, so this is a DHCP renew.

And the DHCP server replies :
Dec 6 01:49:11 dhcpd 14393 DHCPACK on 192.168.201.99 to c0:ee:40:86:e2:2c (WB097893) via mvneta0.201

Which means : OK (ACK) for a new period.

2 seconds later, the device "c0:ee:40:86:e2:2c" starts to send DHCPDISCOVERs.

Dec 6 03:49:13	dhcpd	14393	DHCPDISCOVER from c0:ee:40:86:e2:2c via mvneta0.201
Dec 6 03:49:18	dhcpd	14393	DHCPDISCOVER from c0:ee:40:86:e2:2c via mvneta0.201

I've two observations :
The device "c0:ee:40:86:e2:2c" never received the DHCPACK 6 seconds earlier, so it restarts the entire DHCP process by sending out initial DHCPDISCOVER - is there a bad connection ?
Or
The device rebooted, and then its normal that it starts with DHCPDISCOVER.

Remember : when the Wifi connection goes bad, there is a moment that de Wifi radio/NIC driver resets the Ethernet connection (the radio device, IP settings etc) and a DHCP DHCPDISCOVER starts everything all over again.

Consider checking : the entire radio wave spectrum around you ;)
Channels used etc.

@baf said in DHCP started acting weird, "unknown lease":

and I ended up just setting a static IP temporarily to get the device online

Remove the word 'temporarily' and you'll have a good solution.
Or set up a static MAC lease on the pfSense DHCP server side.
And yes, it happens, there are devices out there that have a pretty broken DHCP client implementation.

baf · Dec 19, 2022, 9:53 PM

Yes, there are VLANs at play here.

The device is on wifi, though it hasn't moved and a new identical device newly installed right next to it is not exhibiting this issue. The logs from my wireless infrastructure don't suggest any major connection blips either.

I also don't believe the device rebooted, though that is possible.

I ended up, rather than setting up a static IP on the lease (that particular vlan is for IoT stuff and has no extra room on its subnet that isn't allocated to the DHCP pool), just setting a static lease that overrides the DHCP lease time to one day. And now I see daily DHCP renewals with no problems.

Odd though that this worked fine with hourly lease renewals for a couple of years before this problem arose.