DHCP hosts not reliably propagated to DNS

Ha! this is beyond odd! I just got this error on my Production IPFire box.

iMac $ ping -c1 ipfire
ping: cannot resolve ipfire: Unknown host

iMac $ ping -c1 ipfire.local
PING ipfire.local (192.168.60.1): 56 data bytes
64 bytes from 192.168.60.1: icmp_seq=0 ttl=64 time=0.629 ms
--- ipfire.local ping statistics ---
1 packets transmitted, 1 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 0.629/0.629/0.629/0.000 ms

iMac $ ping -c1 ipfire.localdomain
ping: cannot resolve ipfire.localdomain: Unknown host
iMac3:monit jcmurphy$ 

I can access fine via the IP address.

So I am trying to tell if I broke something. Or this is the same bug as above…

EDIT: resetting the dhcp via /etc/init.d/dhcp restart did not help

I ended up rebooting the IPFire box to get things back up & running. And here is what I saw (but I don’t understand it!):

Before reboot - on the IPFire box things look OK.

[root@ipfire ~]# ping -c1 ipfire
PING ipfire.localdomain (192.168.60.1) 56(84) bytes of data.
64 bytes from ipfire.localdomain (192.168.60.1): icmp_seq=1 ttl=64 time=0.217 ms

--- ipfire.localdomain ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.217/0.217/0.217/0.000 ms

[root@ipfire ~]# ping -c1 ipfire.localdomain
PING ipfire.localdomain (192.168.60.1) 56(84) bytes of data.
64 bytes from ipfire.localdomain (192.168.60.1): icmp_seq=1 ttl=64 time=0.192 ms

--- ipfire.localdomain ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.192/0.192/0.192/0.000 ms

. . .

[root@ipfire ~]# host 192.168.60.1
1.60.168.192.in-addr.arpa domain name pointer ipfire.

[root@ipfire ~]# host 192.168.65.1
1.65.168.192.in-addr.arpa domain name pointer ipfire.


The nslookup command didn’t look right. It was missing the localdomain. And dig +x came back with the same type of results.

And before reboot - more from the Mac side:

iMac:~ $ host 192.168.60.1
1.60.168.192.in-addr.arpa domain name pointer ipfire.

iMac:~ $ host 192.168.60.225
225.60.168.192.in-addr.arpa domain name pointer MM3.localdomain.

the localdomain is only missing from the ipfire device.

All has been working OK since the reboot!

Is there any update on this? it bugs me that I bring systems online on the network, unbound does not ‘see’ them so I have to ssh to my ipfire and run my little rst script. I understand there is a python method inotify() which does not seem to work reliably.

I did some initial testing and didn’t find the effect but @jon gave me additional guidance on the conditions to create it. I then have been tied up with other work on the removal of the EOL python2 and some other bugs.

That is now mostly completed so I will go back to my vm testbed and see where i got to and will look at the source code to see if this is something I have the ability to pick up to fix.

A bug has been created for it so other people are welcome to pick it up if they want to.

1 Like

I appreciate the work you do. Can you share the bug link so I can add myself as int party? thanks.

The bug link is back up in post number 3 in this thread.

thanks, added myself to the cc: list.

@pavlos - Since you are seeing the same issue, can you add comments to the bugzilla? Thank you!

1 Like

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"
1 Like

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

1 Like

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

1 Like

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.

1 Like

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

2 Likes

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).