@pavlos - Since you are seeing the same issue, can you add comments to the bugzilla? Thank you!
This seems to be repeatable with NOT recently plugged in devices.
I just added a raspberry pi RPI3B+ that has not been on the network in a month (maybe more). The RPI3B+ grabbed a DHCP’d IP address as expected.
I quickly see the new lease info on the dhcp.cgi
:
And I quickly see the new lease in the /var/state/dhcp/dhcpd.leases
file:
ls -al /var/state/dhcp/dhcpd.leases
-rw-r--r-- 1 root root 17907 Oct 17 14:40 /var/state/dhcp/dhcpd.leases
lease 192.168.60.120 {
starts 0 2021/10/17 19:40:48;
ends 1 2021/10/18 01:40:48;
cltt 0 2021/10/17 19:40:48;
binding state active;
next binding state free;
rewind binding state free;
hardware ethernet xx:xx:xx:x8:03:08;
uid "\000\000\000\000\200\003\000";
set vendor-class-identifier = "dhcpcd-6.11.5:Linux-4.19.66-v7+:armv7l:BCM2835";
client-hostname "raspberrypi";
}
But there has been no change to the /etc/unbound/dhcp-leases.conf
file:
[root@ipfire]# ls -al /var/state/dhcp/dhcpd.leases /var/ipfire/dhcp/fixleases /etc/unbound/dhcp-leases.conf /var/ipfire/main/hosts
-rw-r--r-- 1 root root 3880 Oct 16 21:52 /etc/unbound/dhcp-leases.conf
-rw-r--r-- 1 nobody nobody 1019 Oct 16 21:52 /var/ipfire/dhcp/fixleases
-rw-r--r-- 1 nobody nobody 177 Oct 16 21:32 /var/ipfire/main/hosts
-rw-r--r-- 1 root root 12405 Oct 17 14:56 /var/state/dhcp/dhcpd.leases
[root@ipfire]#
EDIT: FYI -
If I add a new host via the hosts.cgi
WebGUI page I see the /etc/unbound/dhcp-leases.conf
file get updated instantly.
If I change a DHCP leased address to a DHCP fixed lease I see the /etc/unbound/dhcp-leases.conf
file get updated instantly.
So it appear to be an issue with a new DHCP leased address only…
EDIT2: small item - arp is a ?
and missing its hostname.
[root@ipfire monit]# arp -a | grep 03:08
? (192.168.60.120) at xx:xx:xx:x8:03:08 [ether] on green0
EDIT3: And if I do a simple /etc/rc.d/init.d/dhcp stop
& start
(as mentioned in earlier posts) then all my missing hostnames re-appear - included the raspberrypi
one added earlier today.
diff --changed-group-format='%>' --unchanged-group-format='' /root/monit/dhcp-leases.conf.last /etc/unbound/dhcp-leases.conf
local-data: "ecobee.localdomain 60 IN A 192.168.65.110"
local-data: "110.65.168.192.in-addr.arpa 60 IN PTR ecobee.localdomain"
<1 REDACTED>
local-data: "iPhone.localdomain 60 IN A 192.168.65.109"
local-data: "109.65.168.192.in-addr.arpa 60 IN PTR iPhone.localdomain"
local-data: "KiPhone.localdomain 60 IN A 192.168.65.117"
local-data: "117.65.168.192.in-addr.arpa 60 IN PTR KiPhone.localdomain"
local-data: "JiPad5.localdomain 60 IN A 192.168.65.113"
local-data: "113.65.168.192.in-addr.arpa 60 IN PTR JiPad5.localdomain"
local-data: "MBP2.localdomain 60 IN A 192.168.65.139"
local-data: "139.65.168.192.in-addr.arpa 60 IN PTR MBP2.localdomain"
local-data: "SiPad.localdomain 60 IN A 192.168.65.108"
local-data: "108.65.168.192.in-addr.arpa 60 IN PTR SiPad.localdomain"
local-data: "raspberrypi.localdomain 60 IN A 192.168.60.120"
local-data: "120.60.168.192.in-addr.arpa 60 IN PTR raspberrypi.localdomain"
I wish I understood python3 way more than I do…
Just to add to the mystery - I was trying to learn a little more about the unbound-dhcp-leases-bridge
python3 file. And I came across these items:
I do not see these messages in the message logs (going back many weeks):
Unbound DHCP Leases Bridge started on %s" % self.leases_file
https://github.com/ipfire/ipfire-2.x/blob/master/config/unbound/unbound-dhcp-leases-bridge#L79
Unbound DHCP Leases Bridge terminated
https://github.com/ipfire/ipfire-2.x/blob/master/config/unbound/unbound-dhcp-leases-bridge#L114
Expired
https://github.com/ipfire/ipfire-2.x/blob/master/config/unbound/unbound-dhcp-leases-bridge#L144
But I DO see every other log.info
or log.debug
message in the message logs.
[ play suspenseful music here ]
Modify the loadproc line 46 in /etc/init.d/dhcp
and add -v next to -d
Now the arguments are >=2 so the loglevel becomes debug (see line 580)
I switched on the e6500 laptop. the laptop got a .27
Here’s the log file (the error may mean something).
Oct 17 07:56:47 ipfire dhcpd: DHCPOFFER on 10.0.0.27 to c4:46:19:50:47:ac (e6500) via green0
Oct 17 07:56:47 ipfire dhcpd: DHCPREQUEST for 10.0.0.27 (10.0.0.1) from c4:46:19:50:47:ac (e6500) via green0
Oct 17 07:56:47 ipfire dhcpd: DHCPACK on 10.0.0.27 to c4:46:19:50:47:ac (e6500) via green0
Oct 17 07:57:27 ipfire unbound: [26317:0] info: 10.0.0.36 e6500.lan. A IN
Oct 17 07:57:27 ipfire unbound: [26317:0] info: 10.0.0.36 e6500.lan. AAAA IN
Oct 17 07:59:24 ipfire dhcp[26769]: Could not run unbound-control local_data e6500.lan 60 IN A 10.0.0.27, error code: 1: b''
Oct 17 08:04:16 ipfire dhcpd: DHCPREQUEST for 10.0.0.27 from c4:46:19:50:47:ac (e6500) via green0
Oct 17 08:04:16 ipfire dhcpd: DHCPACK on 10.0.0.27 to c4:46:19:50:47:ac (e6500) via green0
Adding to the puzzle … the error says local_data (note the underscore) but if you look at the unbound file (/etc/unbound/dhcp-leases.conf) it says, local-data (note the dash)
I think local_data
is a command for unbound-control
. See unbound-control -h
I see a bunch of those types of errors from Mar 2021, but nothing recent. I don’t know what they are…
maybe an error from this line:
In your message log do you see lines with Adding new record xxxx
?? If no, then add another v
to the loadproc
line.
EDIT:
Hey! Blast from the past:
https://community.ipfire.org/t/dhcp-could-not-run-unbound-control-local-data/2379
Added another v as in -vv … now I see
Oct 18 15:28:03 ipfire dhcp[31438]: Adding new record main.lan 60 IN A 10.0.0.47
Oct 18 15:28:03 ipfire dhcp[31438]: Adding new record 47.0.0.10.in-addr.arpa 60 IN PTR main.lan
About line 514 local_data … see line 530 local-data
I’m having this same problem. I created the three line script @anon42188109 created and every time I run it, the output is:
Stopping DHCP Server... [ OK ]
Stopping Unbound DHCP Leases Bridge... [ WARN ]
Starting DHCP Server... [ OK ]
Stopping Unbound DNS Proxy... [ OK ]
Starting Unbound DNS Proxy... [ OK ]
I’m not sure where to look for the Unbound DHCP Leases Bridge output but if I manually run
/usr/sbin/unbound-dhcp-leases-bridge -vv
it does not exit.
I replied to the bug, you need -d to start as a daemon.
/usr/sbin/unbound-dhcp-leases-bridge -d -vv
The output for unbound-dhcp-leases-bridge
is in the messages log file (/var/log/messages
).
You can try this (I hope I typed this right!):
grep 'ipfire dhcp\[' /var/log/messages
I usually use this because it is less restrictive and grabs both dhcp & unbound messages:
grep -e unbound -e dhcp /var/log/messages
EDIT:
See example from @anon42188109 in Post 34. This is the type of info you’ll see.
well, thx to pauls hint with:
/usr/sbin/unbound-dhcp-leases-bridge -d -vv
i was able to get the local dns working again.
this struck my ipfire mini after the last coreupdate…
it seems the unbound-dhcp-leases-bridge
startup on booting
the mini is not reliable…
Have a look at DHCP settings (WUI = dhcp.cgi) for DNS_UPDATE_ENABLED - it has to be turned off in order to launch the unbound-dhcp-leases-bridge…
grep DNS_UPDATE_ENABLED /var/ipfire/dhcp/settings
DNS_UPDATE_ENABLED=off
Explanation:
The init.d script for DCHP uses that setting DNS_UPDATE_ENABLED !=on to determine if unbound-dhcp-leases-bridge is executed (or not):
# Start Unbound DHCP Lease Bridge unless RFC2136 is used
if [ "${DNS_UPDATE_ENABLED}" != on ]; then
boot_mesg "Starting Unbound DHCP Leases Bridge..."
loadproc /usr/sbin/unbound-dhcp-leases-bridge -d
Hope it helps
Mine is already set that way:
# grep DNS_UPDATE_ENABLED /var/ipfire/dhcp/settings
DNS_UPDATE_ENABLED=off
I don’t think this is a configuration issue. The bridge gets started, and works occasionally, but it seems to miss some events that should cause it to update DNS. That sounds more like a real bug (and I suspect it has something to do with how inotify events are being handled and rearmed).
Indeed,
Explanation was posted in the bug 12694 – DHCP hosts not reliably propagated to DNS (ipfire.org)
FYI: for those using my 3 line script to reset dhcp and unbound, add a sleep 3
before unbound. Ipfire needs time to breathe and without the sleep 3, it may throw some errors in /var/log/messages
.
/etc/init.d/dhcp stop
/etc/init.d/dhcp start
sleep 3
/etc/init.d/unbound restart
There is a fix available for testing.
-
unbound-dhcp-leases-bridge
has received improvements to reliably propagate DHCP hosts to the DNS. Thanks go to Anthony Heading for his work on that front.
Please see:
IPFire 2.27 - Core Update 167 is available for testing
testing feedback is always highly appreciated!
cu 167 Testing … feedback
A few tests indicate that the fix is working (thank you Anthony).
- when a new laptop comes in, it can be pinged by name
- when the laptop leaves and dhcp lease expires, the record in DNS is removed.
Paul
Follow up question: I start the dhcp-leases-bridge with -d -vv
/usr/bin/python3 /usr/sbin/unbound-dhcp-leases-bridge -d -vv
The text “Wakeup of main loop” shows in /var/log/messages
at uneven times, sometimes 30s, other times 18s, or 1m 30s. There does not seem to be a pattern. Here’s some log …
Apr 12 05:46:44 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:47:50 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:48:14 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:48:32 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:50:02 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:50:20 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:51:51 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:53:21 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:54:21 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:55:03 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:55:09 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:55:51 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:55:57 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:56:02 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:57:32 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:58:14 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:58:20 zotac dhcp[16447]: Wakeup of main loop
Apr 12 05:58:50 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:00:14 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:00:32 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:00:38 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:00:43 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:01:25 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:01:31 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:01:37 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:03:13 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:03:31 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:03:49 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:05:19 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:06:20 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:06:26 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:06:32 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:06:50 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:06:56 zotac dhcp[16447]: Wakeup of main loop
Apr 12 06:07:02 zotac dhcp[16447]: Wakeup of main loop
Hi Paul,
Could you please add your feedback into the bug report.
it must be 10+ characters … done.