DHCP dynamic clients not showing as expected

bonnietwin · 8 April 2023 08:32

I have no idea really. I have not experienced anything like this on my system but all of my systems have a fixed lease. Dynamic leases are only given out when I have friends or family visiting but never noticed a problem at those times.

Need to understand the details of the setup. I will look back through this thread to see if I can duplicate it on my vm testbed and see if I can reproduce the effect. Problem is that it seems to be intermittent over a long time period, like days or weeks. That is difficult to test as my vm testbed is not running 24/7

Do those clients show as being FAILED, STALE or UNREACHABLE in the ARP table at the bottom of the WUI menu Status - Network (other).

Are the clients still connected as far as they are concerned. Can you still browse with them. What do they say if you look with ip address show or the equivalent for the OS on them.

sec-con · 8 April 2023 09:09

Is there anything I can help you with, perhaps send you a backup of my configuration?

As I believe I have mentioned before I only use fixed leases for a few items. That list has since expanded a bit, and the addition of BLUE has also added that part, but I believe most other info I posted above to be still relevant. I will have to revise it though and will get back later or tomorrow with more info.

bonnietwin · 8 April 2023 21:28

As a simple first test I set my vm testbed up with 2 Linux clients on Green and three Linux clients on Blue running with Dynamic IP assignment, So no Fixed Leases and a Dynamic Pool defined on both Green and Blue.

Immediately I started up the clients they got an IP address from IPFire and also they showed up in the Current dynamic leases table. They have stayed there for 10.5 hours with no problem. The Default Lease time is set to 60 mins, so every 30 mins (50% of the default lease time) the client asks for the lease to be renewed and you see that in the Current dynamic leases table with the periodic increase of the Lease Time Expires info.

For a period of three hours I shutdown one of the Green and one of the Blue clients. The lease info stayed showing in the list for the default lease time (60 mins) and then the entry was changed to the lease info with a line through it. That stayed in position for the following two hours.

So a simple standard setup is not able to reproduce the issue you are experiencing.

Maybe a copy of the backup of your configuration might be of use. At least I can see what I can duplicate on my vm testbed.
The other area there could be differences is in the clients. Is there any commonality in the clients that show the problem or is it a mixture of computer based clients with various OS’s and IoT systems?

EDIT:
One thing I have noticed in your post 4 is that you have checked the Allow bootp clients option. Are your clients setup to use bootp. That is an option That I don’t have set on any of my systems. None of my clients are set up to use bootp.

bonnietwin · 9 April 2023 10:47

Looking through the thread I see that when you had no dynamic clients showing in the Current dynamic clients table that you could find the client connection in the wio arp table.

Can you confirm that you also see them in the Web User Interface menu Status - Network (other) - ARP table at the end of the page.

If both of these are showing the client connections and they are working but not being shown in the DHCP Current dynamic clients then it could be that the code for that table has been corrupted somehow.

Presuming you have Core Update 173 then you can check the hash of the header.pl file which contains the code for the Current dynamic clients to confirm it is the same as the file in the Core Update 173 git branch which has the hash shown below.

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

That is the same b2 hash that I have on my vm testbed system.

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.