DHCP hosts not reliably propagated to DNS

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

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!

3 Likes

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

2 Likes

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.

Yes, the DHCP → DNS propagation in core 167 update seems to do the right thing now. This is an intermittent problem though, so it probably needs a bit longer before we declare victory, but the early indications are good. Thanks!

1 Like

Jeff, by “this” you mean the “Wakeup of main loop”, right?

Yes, the timing is a bit of concern since the Dev wrote it should happen every 6 seconds.