DHCP hosts not reliably propagated to DNS

jon · 18 October 2021 21:51

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:

ipfire/ipfire-2.x/blob/master/config/unbound/unbound-dhcp-leases-bridge#L514


      
          			# Forward record
          			(self.fqdn, "%s" % LOCAL_TTL, "IN A", self.ipaddr),
          
          			# Reverse record
          			(ip_address_to_reverse_pointer(self.ipaddr), "%s" % LOCAL_TTL,
          				"IN PTR", self.fqdn),
          		]
          
          
          class UnboundConfigWriter(object):
          	def __init__(self, path):
          		self.path = path
          
          	def update_dhcp_leases(self, leases):
          		# Write out all leases
          		self.write_dhcp_leases(leases)
          
          		log.debug("Reloading Unbound...")
          
          		# Reload the configuration without dropping the cache
          		self._control("reload_keep_cache")

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

anon42188109 · 18 October 2021 22:29

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

bsmorgan · 19 October 2021 14:49

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.

anon42188109 · 19 October 2021 14:53

I replied to the bug, you need -d to start as a daemon.

/usr/sbin/unbound-dhcp-leases-bridge -d -vv

jon · 19 October 2021 18:39

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.

current_user · 10 January 2022 22:37

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…

hjkl · 27 February 2022 10:26

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

jlayton · 27 February 2022 12:08

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

hjkl · 27 February 2022 12:18

Indeed,
Explanation was posted in the bug 12694 – DHCP hosts not reliably propagated to DNS (ipfire.org)

anon42188109 · 27 February 2022 15:49

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

jon · 11 April 2022 19:50

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!

anon42188109 · 11 April 2022 21:37

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

anon42188109 · 12 April 2022 13:57

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

bonnietwin · 12 April 2022 14:11

Hi Paul,
Could you please add your feedback into the bug report.

anon42188109 · 12 April 2022 14:19

it must be 10+ characters … done.

jlayton · 18 April 2022 11:34

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!

anon42188109 · 18 April 2022 11:46

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.

jlayton · 18 April 2022 12:10

No, I meant that the original reported problem, where the daemon would sometimes fail to propagate new DHCP clients to DNS, seems to be fixed.

I haven’t run the daemon with debug logging so I’m not clear on your follow-up question. Given that it’s using inotify to look for changes though, I’d be surprised if the wakeups were at regular intervals.

hellfire · 18 April 2022 19:09

I’m currently running IPFire a few versions below the most current release.

Does the above mentioned fix mean that I do not have to add a Host entry for each of the DHCP leases anymore?

Can those DNS entries be used in SARG reports, too, instead of IP addresses? Currently I’ve changed a param in SARG config to get resolved IP addresses.

Which DNS name will be used if each DHCP now gets properly propagated?

anon42188109 · 18 April 2022 19:19

When a new laptop joins the network, DHCP assigns (10.0.0.36, e6500) and sends that pair to unbound. That means, immediately, you can ping e6500 Up to cu166 this functionality was not working.

When the laptop leaves the network && its lease expires, the pair (10.0.0.36, e6500) is removed from unbound. Up to cu166, unbound kept that pair forever.