DHCP dynamic clients not showing as expected

sec-con · 9 April 2023 13:20

@bonnietwin
So lets see if I can check what you asked for and provide info.

Dynamic DHCP entries are still not showing.

Below should be answers to you questions, I hope.

Bootp is enabled because it was a setting that was necessary at work (with completely different equipment) for the printers to update properly, but I can probably disable it and have now done so.
ARP has some dynamic addresses labelled as FAILED, which is probably correct, since those devices, I can double check looking up the device IP in Lansweeper, are offline or got another dynamic IP.
ARP has some STATIC entries marked as STALE, which I frankly do not know what it means, but the devices with those IP addresses are online.
ARP has some STATIC entries marked as DELAY, the device is live and works.
ARP has the rest of the static addresses as REACHABLE which seems ok, after checking them.
header.pl - see below

 b2sum /var/ipfire/header.pl
09b8de0e33ad64a22e6cc4421259cd2e2e01c9d3e8d7eb2b97d29434ea5c5d1e239eaf4865863ce720abd84b4d7233a4b4ff6d15cebc59036c36f84dca9f1942  /var/ipfire/header.pl

That is still the case, but I would have to check each individually to make sure it is valid for all. BLUE (Wifi) come and go as people enter and leave the house with their equipment.

sec-con · 9 April 2023 13:35

BTW

Rebooting
…
Starting dhcpd on the red0 interface… [ FAIL ]
Error: ipv4: FIB table does not exist

Rebooting again… works.

I am monitoring all reboots via IPMI since that is an error I noticed recently. First I just rebooted without checking, but now I have this occurring sometimes.

bonnietwin · 9 April 2023 13:42

REACHABLE means that it has just had some communication with the client and can confirm access is good.

STALE means that some time has past since the last communication so the condition of the connection is not certain but it has not been confirmed as REACHABLE or FAILED but will be updated when the next communication occurs. Usually something like the 50% of default lease time renewal request from the client.

So your info for the ARP table looks normal.

Also the b2 sum for your header.pl file is correct.

Having or not having the bootp option selected would not be expected to affect what is shown in the Current dynamic leases table.
I also tried my vm testbed setup with Allow bootp clients checked but everything worked still as expected. None of my clients are using bootp so I would not expect anything to be affected by it being unchecked.
If all of your clients are using bootp then I would expect that you have a problem with the option unchecked and not when it is checked.

I am running out of ideas of how to fault find this.

I will come back if I think of anything.

bonnietwin · 9 April 2023 13:53

That is something different and not related.

I am presuming that you have made a typo when you have

Starting dhcpd on the red0 interface

as it should be

Starting dhcpcd on the red0 interface

which is a different program.

For the red interface dhcpcd is used as a client to get the dhcp info from the ISP.
For the green and blue interfaces dhcpd is used as a server to provide dhcp info to the clients.

They are two separate software programs.

For the failure with the red interface you need to look in the WUI menmu Logs - System Logs and select RED in the Section: drop down box and press the Update button.

That should give more info on the messages that occurred before it failed.

sec-con · 9 April 2023 13:58

Yeah it was the typo. Typed a bit to fast since the window is only 640x480 on my 4K monitor so I almost need a microscope.

You now have the logs.

tphz · 9 April 2023 23:31

I wonder if changing the resolution of IPFire will help.

sec-con · 10 April 2023 05:54

Na, that is due to IPMI (SuperMicro) and Java. AFAIK there is no setting I can mess with to improve that. Maybe if IPFire setup forced a higher res, I have seen some distros that do that, but I know to little on how that works.

bonnietwin · 11 April 2023 12:12

Have gone through the logs.

For the problem you had with dhcpcd on red I found the following log entries for April 9th with the newest message at the bottom:-

dhcpcd-9.4.1 starting
DUID xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:dxx:xx
red0: waiting for carrier
red0: carrier acquired
red0: IAID xx:xx:xx:xx
red0: soliciting a DHCP lease
timed out
dhcpcd exited
dhcpcd-9.4.1 starting
DUID xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:dxx:xx
red0: waiting for carrier
red0: carrier acquired
red0: IAID xx:xx:xx:xx
red0: soliciting a DHCP lease
red0: offered yyy.yyy.yyy.yyy from zzz.zzz.zzz.zzz
red0: probing address yyy.yyy.yyy.yyy/ww
red0: leased yyy.yyy.yyy.yyy for 1200 seconds
red0: adding route to yyy.yyy.yyy.yyy/ww
red0: adding default route via yyy.yyy.yyy.yyy
red0 has been (re)configured with IP=yyy.yyy.yyy.yyy

From the first boot the carrier was aquired. The IAID was sent and IPFire solicited a DHCP lease from your ISP. Your ISP had not replied after 60 secs so dhcpcd timed out.

Then you did a reboot and with this run after soiciting a DHCP lease your ISP responded with an offer immediately. The time stamp is the same to the second.

There is no indication why your ISP did not respond.

You could try changing the timeout number at the end of the /var/ipfire/dhcpc/dhcpcd.conf file from 60 to 300. That would give your ISP 5 mins to respond before dhcpcd times out. Of course if the ISP doesn’t respond then IPFire will wait at the getting a lease on red for 5 mins.

Based on the above log this looks like a problem with your ISP. If it regularly happens that the first reboot times out and the second is then responded to in less than a second then you probably need to discuss with your ISP.

Regarding the dhcp logs and setup. The dynamic clients seem to get their IP’s successfully based on the log entries.

The only error message is due to your fixed leases being defined in the dynamic range.

Every fixed lease assignment gets the following messages in the logs from the dhcpd server package.

dhcpd: Dynamic and static leases present for 192.168.1.10.
dhcpd: Remove host declaration fix1 or remove 192.168.1.10
dhcpd: from the dynamic address pool for 192.168.1.0/24

I can’t imagine how having the fixed leases overlap with the dynamic leases would cause the Current dynamic leases to not be shown in the table but we are getting to the point that changing this situation is becoming one of the few things left to test.

I will set up a vm with some fixed leases in the dynamic range and see what happens with the dynamic leases table and if that causes me to be able to duplicate the effect.

In Core Update 174 all fixed leases that overlap with the Dynamic lease range will be coloured red in the Fixed Leases table.

sec-con · 11 April 2023 13:34

Thanks for your extensive answer about that. I find it puzzling, because I would only expect it to take above 60 seconds had I reset the ISP hardware equipment, but that never happened. Any chance it could be related to the NIC in the IPFire box? It is one NIC with 4 ports after all, perhaps there are some delays.

This NIC:

C2000 SoC I354 Quad GbE Controller (MACs)
Virtual Machine Device Queues reduce I/O overhead
Supports 10BASE-T, 100BASE-TX, and 1000BASE-T, RJ45 output

As for the DHCP issue, I understand you are still investigating, and have not yet found an answer that I could implement.

bonnietwin · 11 April 2023 14:06

I am not familiar enough with NIC’s to be able to comment on that although I would feel that if there were delays they should not be in the order of 60 secs but more in the milli secs.

sec-con · 18 April 2023 11:23

I do not want to give the impression of being a nuisance or nagging, but seeing as this is still an ongoing issue “pending investigation” so to speak, I wonder if you have been able to find any possible issues that may cause this behaviour.

My system has been pretty much static since the last post, and is still refusing to show dhcp leases, as described, both for GREEN or BLUE.

bonnietwin · 18 April 2023 13:36

Everything that I have tried so far has not been able to reproduce the problem you are experiencing.

I have tried setting up my vm system as close to the setup of your system that I am able to, including creating fixed leases that are within the IP range defined for the Dynamic leases.

Everything has always ended up showing all the actual machines that had been assigned dynamic leases in the Current dynamic leases table.
You have mentioned that at first you do see the dynamic leases but then after some time in the range of days or weeks then the table no longer shows anything. I am unable to test out in that way as my vm testbed is not running 24/7.

You also tested the b2 hash for the header.pl file which contains the code that writes the dynamic leases to that table and it was the correct value.

Last thing I can think of, that just came to my mind. What is in the file

/var/state/dhcp/dhcpd.leases

That should contain all the dynamic leases that have been assigned. As an example, here is the one from my vm testbed that I just turned on.

'# The format of this file is documented in the dhcpd.leases(5) manual page.
'# This lease file was written by isc-dhcp-4.4.3-P1

'# authoring-byte-order entry is generated, DO NOT DELETE
authoring-byte-order little-endian;

lease 192.168.200.1 {
starts 2 2023/04/18 13:01:36;
ends 2 2023/04/18 14:01:36;
cltt 2 2023/04/18 13:01:36;
binding state active;
next binding state free;
rewind binding state free;
hardware ethernet 08:00:27:ba:48:47;
uid “\377’\272HG\000\004s\031l\233\222\221\334H\265\016\\237z\202c\316”;
client-hostname “green2”;
}
lease 192.168.220.1 {
starts 2 2023/04/18 13:02:26;
ends 2 2023/04/18 14:02:26;
cltt 2 2023/04/18 13:02:26;
binding state active;
next binding state free;
rewind binding state free;
hardware ethernet 08:00:27:2b:00:60;
uid “\377’+\000`\000\004I\305\034b[\011EJ\2232\203\211H6$\015”;
client-hostname “blue2”;
}
lease 192.168.220.2 {
starts 2 2023/04/18 13:02:56;
ends 2 2023/04/18 14:02:56;
cltt 2 2023/04/18 13:02:56;
binding state active;
next binding state free;
rewind binding state free;
hardware ethernet 08:00:27:51:88:6f;
uid “\377’Q\210o\000\004I\305\034b[\011EJ\2232\203\211H6$\015”;
client-hostname “blue3”;
}

I had to add a ’ at the front of the comment lines otherwise this post would have rendered the lines as large text.

What is in your file. Maybe for some reason it is empty which would be why the table doesn’t show anything but then we would need to figure out why it has been cleared, because that should not normally occur.

If your dhcpd.leases file does contain all the information then I have no idea what is happening.

EDIT:-
Also check what is in the previous dhcpd.leases file

/var/state/dhcp/dhcpd.leases~

especially if the dhcpd.leases file is empty. Also note the date/time of both files. If dhcpd.leases~ is not empty then the date/time would give an indication when the leases file was updated to empty it. That might help with checking in the logs for what happened around that time.

EDIT2:-
In the dhcpd.leases file you might find the same client in there multiple times depending on if the lease has expired and then a new one created or if the lease has been extended.

bonnietwin · 18 April 2023 15:58

Okay, I have been able to reproduce what you have seen.

To get it I to occur then if there is a dynamic lease showing in the table and I disable the green and blue networks in the dhcp page and press save and then re-enable both again and save then the table no longer shows any entries.

This is because when both the green and blue subnets are disabled in the dhcp page then the dhcp server is restarted which causes the dhcpd.leases file to be cleared.

This has been recommended in the past for when there are a large number of expired entries in the table but of course it clears all leases, not just the expired ones.

The working systems running with their existing leases will continue operating until they reach 50% of the default leasetime. At this point the client will ask for the existing lease to be renewed, at which point it should come back into the list.

The above was tested on my vm testbed and I have a 60 mins default lease time so after 30 mins the lease should show again.
I will report back when the time has gone past, although it won’t be till around 1.75 hours as I have an appointment to go to so will only be able to check after I come back.

Have you been disabling the green and blue subnets in the dhcp page?

bonnietwin · 18 April 2023 18:04

I can confirm that my Current dynamic leases table now shows all the dynamic leases again.

From your backup info you have the default lease time set to 3600 mins which would mean that the leases if deleted from the dhcpd.leases file should be visible again after 1800 mins (30 hours) but you seem to be talking about longer periods such as 7 days over which the Current dynamic leases table stays empty even though machines are connected and running.

It would be good to know if your dhcpd.leases and dhcpd.leases~ files are empty or not.

sec-con · 19 April 2023 07:18

I hear you, it will take a couple of days since I am traveling.

sec-con · 21 April 2023 06:14

 GNU nano 7.2                            dhcpd.leases
# The format of this file is documented in the dhcpd.leases(5) manual page.
# This lease file was written by isc-dhcp-4.4.3-P1

# authoring-byte-order entry is generated, DO NOT DELETE
authoring-byte-order little-endian;

lease 192.168.10.5 {
  starts 0 2023/03/19 09:29:31;
  ends 2 2023/03/21 21:29:31;
  tstp 2 2023/03/21 21:29:31;
  cltt 0 2023/03/19 10:21:25;
  binding state free;
  hardware ethernet 18:5e:0f:11:e7:43;
  uid "\001\030^\017\021\347C";
  set vendor-class-identifier = "MSFT 5.0";
}
lease 192.168.10.10 {
  starts 0 2023/03/19 09:41:04;
  ends 2 2023/03/21 21:41:04;
  tstp 2 2023/03/21 21:41:04;
  cltt 0 2023/03/19 09:41:04;
  binding state free;
  hardware ethernet c4:7d:9f:6f:67:35;
  uid "\001\304}\237og5";
  set vendor-class-identifier = "android-dhcp-13";
}
lease 192.168.10.14 {
  starts 1 2023/03/20 11:05:50;
  ends 3 2023/03/22 23:05:50;
  tstp 3 2023/03/22 23:05:50;
  cltt 1 2023/03/20 17:45:35;
  binding state free;
  hardware ethernet 52:e0:0c:a9:2f:84;
  uid "\001R\340\014\251/\204";
  set vendor-class-identifier = "android-dhcp-13";
}
lease 192.168.10.11 {
  starts 1 2023/03/20 18:48:08;
  ends 4 2023/03/23 06:48:08;
  tstp 4 2023/03/23 06:48:08;
  cltt 1 2023/03/20 18:48:08;
  binding state free;
  hardware ethernet be:43:2b:ab:03:83;
  uid "\001\276C+\253\003\203";
  set vendor-class-identifier = "android-dhcp-13";
}
lease 192.168.10.3 {
  starts 1 2023/03/20 15:39:45;
  ends 6 2023/03/25 15:39:45;
  tstp 6 2023/03/25 15:39:45;
  cltt 1 2023/03/20 15:39:45;
  binding state free;
  hardware ethernet 0a:a7:cb:4d:1e:e4;
  uid "\001\012\247\313M\036\344";
}
lease 192.168.10.9 {
  starts 1 2023/03/20 18:20:30;
  ends 6 2023/03/25 18:20:30;
  tstp 6 2023/03/25 18:20:30;
  cltt 1 2023/03/20 18:20:30;
  binding state free;
  hardware ethernet 1a:30:9a:c6:d0:24;
  uid "\001\0320\232\306\320$";
}
lease 192.168.10.24 {
  starts 6 2023/03/25 08:13:02;
  ends 4 2023/03/30 08:13:02;
  tstp 4 2023/03/30 08:13:02;
  cltt 6 2023/03/25 08:37:43;
  binding state free;
  hardware ethernet 32:92:c8:60:8e:42;
  uid "\0012\222\310`\216B";

and

dhcpd.leases~
EMPTY

So it only took a few of my BLUE devices there.

bonnietwin · 21 April 2023 07:14

So you have 7 clients listed in the leases file, all with leases that have expired after the full default lease time you have set.

What should normally happen is that after 50% of the lease time the dhcp client says to the dhcp server “hallo, I am still here, please continue my lease please”
The server then says “okay, I have updated your lease info here”.

What is interesting is that client IP’s 5, 10, 14 & 11 have the default lease time of 2.5 days between the start and end date/time. client IP’s 3, 9 & 24 have twice the default lease time (5 days) between the start and end date/time.

It looks like either the client never requested a renewal to the server or the server refused it for some reason and the lease just expired.

I also don’t understand why if the leases are still in the file but expired, why they don’t show up in your Current dynamic leases table but just crossed through because they are expired.

Anyway, let’s try and find out what happened with the renewal. Have a search in the dhcpd log on the System Logs WUI page, searching around 2023/03/20 21:29:00 (50% of the default lease time) and look for all the entries for 192.168.10.5

Those dhcpd messages should give some indication of why the leases were not renewed.

sec-con · 21 April 2023 08:45

Mind you, that is only the WiFi. Just saying so you don’t confuse GREEN with BLUE. Or BLUE with GREEN. I need more coffee.

No entries at all for around that time.

20:58:10	dhcpd:	DHCPREQUEST for 192.168.1.244 from 00:21:b7:8e:21:93 (Printer) via green0
20:58:10	dhcpd:	Wrote 0 deleted host decls to leases file.
20:58:10	dhcpd:	Wrote 0 new dynamic host decls to leases file.
20:58:10	dhcpd:	Wrote 56 leases to leases file.
20:58:10	dhcpd:	DHCPACK on 192.168.1.244 to 00:21:b7:8e:21:93 (Printer) via green0
22:37:38	dhcpd:	DHCPREQUEST for 192.168.1.30 from 0c:c4:7a:6e:45:34 via green0
22:37:38	dhcpd:	Wrote 0 deleted host decls to leases file.
22:37:38	dhcpd:	Wrote 0 new dynamic host decls to leases file.
22:37:38	dhcpd:	Wrote 56 leases to leases file.
22:37:39	dhcpd:	DHCPACK on 192.168.1.30 to 0c:c4:7a:6e:45:34 via green0

No entries at all for 192.168.10.5

bonnietwin · 21 April 2023 08:54

That means that client 192.168.10.5 never made any request to IPFire dhcp for a lease renewal.

You need to look at the dhcp logs on that client to see what is happening.

What sort of machine is that client? Is it a Linux, MAC or Windows PC or is it an IOT type device.

When you saw the entries in the Current dynamic leases table did you see both Green and Blue clients present or only the Blue ones?

The fact that there are no machines with IP’s from the Green network leads me to believe that they never got seen as dynamic leases. Are all the Green machines having fixed or static leases?

The dhcpd.lease~ being empty and only those 7 machines being in dhcpd.leases means that no other dynamic leases were requested and provided. As you can see it is a persistent file unless both the Green and Blue subnets have been disabled in the WUI page.

Here is the description of the dhcpd.leases file.

The Internet Systems Consortium DHCP Server keeps a persistent database of leases that it has assigned. This database is a free-form ASCII file containing a series of lease declarations. Every time a lease is acquired, renewed or released, its new value is recorded at the end of the lease file. So if more than one declaration appears for a given lease, the last one in the file is the current one.

In order to prevent the lease database from growing without bound, the file is rewritten from time to time. First, a temporary lease database is created and all known leases are dumped to it. Then, the old lease database is renamed DBDIR/dhcpd.leases~. Finally, the newly written lease database is moved into place.

The lease file is a log-structured file - whenever a lease changes, the contents of that lease are written to the end of the file. This means that it is entirely possible and quite reasonable for there to be two or more declarations of the same lease in the lease file at the same time. In that case, the instance of that particular lease that appears last in the file is the one that is in effect.

This would suggest to me that the leases file at that time had 56 leases written in it. As there are now only 7 leases in dhcpd.leases and 0 in dhcpd.leases~ that suggests to me that in the intervening period the green and blue subnets must have been disabled and dhcpd saved as this wipes clean the dhcpd.leases files.

I have also noticed that three of the 7 leases in your file are for the same device “android-dhcp-13” which has the changing MAC address for each connection it makes, hence it did not get a renewal of the lease but got a new lease.

sec-con · 21 April 2023 09:12

18:5e:0f:11:e7:43 / 192.168.10.5
Meh, that client is currently not available. Lansweeper or ARP has no entry for it either.

Lest try another one perhaps?

As for the DHCP leases, when they showed up last time it was a table in two sections. One for GREEN and one for BLUE, both in the lower section of the DHCP page. BLUE below GREEN, IIRC.