Unbound doesn't know about DHCP lease that expires then appears again

[cpw]

Important notices

Before you add a new report, we ask you kindly to acknowledge the following:

• I have read the contributing guide lines at https://github.com/opnsense/core/blob/master/CONTRIBUTING.md
• I have searched the existing issues and I am convinced that mine is new.

Describe the bug

I have a laptop I shut off nightly. When I power it on again next day, it doesn't appear in DNS. To date, I have restarted unbound after this happens (it happens about 75% of the time), assuming something had crashed (unbound was until recently very crashy), and the laptop immediately resolves again.

I installed a monit monitor on the dhcp watcher, because that seemed to be the most likely culprit, but it hasn't crashed and seems to be working fine. In fact, everything seems to be correct except unbound itself - which knows not about the DHCP lease.

I'm guessing that the dhcp watcher somehow removed the lease from unbound, and unbound refuses to accept the new lease?

To Reproduce

Steps to reproduce the behavior:

1. Not sure. Probably remove a DHCP lease, let it expire (how?) then try and re-acquire the same lease again?

Expected behavior

DHCP and DNS should work reliably together, no matter the status of the in-and-out of the individual DHCP requests.

Describe alternatives you considered

I'm tempted to abandon DHCPD and unbound and go to dnsmasq, but I know that's not the direction of the project, so not sure.

Relevant log files

From /var/unbound/dhcpleases.conf

local-data-ptr: "10.0.0.103 cweeks-lap.*.*"
local-data: "cweeks-lap.*.* IN A 10.0.0.103"

So it looks like the dhcpleases knows about the cweeks-lap entry.

From clog /var/log/dhcpd.log | fgrep cweeks-lap

Feb 16 18:51:29 wall dhcpd[87272]: DHCPREQUEST for 10.0.0.103 from 50:7b:9d:d7:f6:8a (cweeks-lap) via lagg0_vlan20 
Feb 16 18:51:29 wall dhcpd[87272]: DHCPACK on 10.0.0.103 to 50:7b:9d:d7:f6:8a (cweeks-lap) via lagg0_vlan20 
Feb 17 08:58:46 wall dhcpd[87272]: DHCPACK on 10.0.0.103 to 50:7b:9d:d7:f6:8a (cweeks-lap) via lagg0_vlan20 

We can see that the request is made when the laptop starts.

From /var/dhcpd/var/db/dhcpd.leases

lease 10.0.0.103 {
  starts 3 2021/02/17 13:58:46;
  ends 3 2021/02/17 15:58:46;
  cltt 3 2021/02/17 13:58:46;
  binding state active;
  next binding state free;
  rewind binding state free;
  hardware ethernet 50:7b:9d:d7:f6:8a;
  uid "\000cweeks-lap";
  client-hostname "cweeks-lap";
}

There was a second "dormant" entry in here earlier, but it has since been removed by the DHCP process I guess.

lease 10.0.0.103 {
  starts 2 2021/02/16 23:51:29;
  ends 3 2021/02/17 01:51:29;
  tstp 3 2021/02/17 01:51:29;
  cltt 2 2021/02/16 23:51:29;
  binding state free;
  hardware ethernet 50:7b:9d:d7:f6:8a;
  uid "\000cweeks-lap";
}

The second entry above was present in the DHCP leases file above the first entry for sometime.

unbound-control -c /var/unbound/unbound.conf list_local_data | fgrep cweeks-lap. returns nothing (and the DNS fails to resolve)

NOTE:

If I run the command from #4597

unbound-control -c /var/unbound/unbound.conf local_data "cweeks-lap.*.* IN A 10.0.0.103"
and
unbound-control -c /var/unbound/unbound.conf local_data "103.0.0.10.in-addr.arpa. IN PTR cweeks-lap.*.*"

then I can now resolve the machine. Is the watcher somehow ignoring the updated lease because it was present, then it wasn't and now it is again?

Environment

Software version used and hardware type if relevant, e.g.:

OPNsense 21.1.1-amd64
FreeBSD 12.1-RELEASE-p13-HBSD
LibreSSL 3.2.3

Hardware is a little intel box:
Intel(R) Core(TM) i3-4030U CPU @ 1.90GHz (4 cores)

[gwjo]

There is a logic bug in

core/src/opnsense/scripts/dns/unbound_dhcpd.py

Line 104 in 889e24c

def run_watcher(target_filename, domain):

Consider the following scenario:

• When a DHCP client first registers, the watcher does two things:
  1. Updates Unbound dynamically with new DNS entry for this endpoint
  2. Writes this entry to /var/unbound/dhcpleases.conf so it is persistent if Unbound restarts
     RESULT: endpoint has DNS entry
• Now restart Unbound
  1. Unbound reads the cached entries in /var/unbound/dhcpleases.conf
  2. The watcher reads these and stores them in unbound_local_data
     RESULT: endpoint has DNS entry
• Endpoint refreshes it's DHCP lease
  1. watcher adds this entry to cached_leases
  2. Does not update Unbound, because entry is listed in unbound_local_data
     RESULT: endpoint has DNS entry
• If endpoint now doesn't renew it's DHCP and times out
  1. watcher removes entry from cached_leases
  2. It also updates Unbound dynamically
  3. Critically it does not remove the entry from unbound_local_data
     RESULT: No DNS entry for endpoint
• If endpoint later comes back and gets the same IP address from the DHCP server
  1. watcher adds entry into cached_leases
  2. But when it checks unbound_local_data the entry exists, so it does not update Unbound
     RESULT: No DNS entry for endpoint

Not updating unbound_local_data when a DHCP client times out, means that Unbound isn't updated later when the DHCP endpoint comes back later.

[AdSchellevis]

@gwjo I'm not sure I agree, the only delete on cached_leases I could find was this:

core/src/opnsense/scripts/dns/unbound_dhcpd.py

Lines 132 to 134 in 889e24c

	unbound_control(['local_data_remove', cached_leases[address]['client-hostname']])
	del cached_leases[address]
	dhcpd_changed = True

after which dhcpd_changed flushes the running config to /var/unbound/dhcpleases.conf in the next row. If there's an issue we're missing here, please point to the line in question.

[gwjo]

@AdSchellevis, that is the "problematic" delete.

This removes the entry from cached_leases but does not update unbound_local_data, so when the DHCP endpoint comes back, the following check fails and the entry is never dynamically re-added to Unbound.

core/src/opnsense/scripts/dns/unbound_dhcpd.py

Lines 149 to 156 in 88e463c

	if not unbound_local_data.is_equal(address, fqdn):
	for tmp_fqdn in unbound_local_data.all_fqdns(address, fqdn):
	syslog.syslog(syslog.LOG_NOTICE, 'dhcpd entry changed %s @ %s.' % (tmp_fqdn, address))
	unbound_control(['local_data_remove', tmp_fqdn])
	unbound_local_data.cleanup(address, fqdn)
	unbound_control(['local_data', address, 'PTR', fqdn])
	unbound_control(['local_data', fqdn, 'IN A', address])
	unbound_local_data.add_address(address, fqdn)

You are correct that it still gets written to /var/unbound/dhcpleases.conf but this doesn't get read unless Unbound restarts or something triggers a config reload, like the blacklist cronjob running. During normal running the DHCP entries are managed only via unbound-control

[cpw]

Unbound restarts is how I've handled the DHCP not reappearing historically, yes. It seems you might have found the problem 👍

[AdSchellevis]

@gwjo got it, thanks for the PR!