Unbound's dhcp-leases.conf disappears

matthaesius · 4 September 2024 09:14

Hello,

first of all, many thanks to the IPfire Team creating and improving such a great product!

Now, I think since Upd. 185 (or 186) I’ve got some strange behaviour related to one file, /etc/unbound/dhcp-leases.conf. After an update the unbound service wouldn’t startup but throw such an error:

Starting Unbound DNS Proxy...
/etc/unbound/unbound.conf:63: error: cannot open include file '/etc/unbound/dhcp-leases.conf': No such file or directory
read /etc/unbound/unbound.conf failed: 1 errors in configuration file
[1724919888] unbound[12445:0] fatal error: Could not read config file: /etc/unbound/unbound.conf. Maybe try unbound -dd, it stays on the commandline to see more errors, or unbound-checkconf    [  OK  ]
/etc/unbound/unbound.conf:63: error: cannot open include file '/etc/unbound/dhcp-leases.conf': No such file or directory
read /etc/unbound/unbound.conf failed: 1 errors in configuration file
[1724919888] unbound-control[12446:0] fatal error: could not read config file
/etc/unbound/unbound.conf:63: error: cannot open include file '/etc/unbound/dhcp-leases.conf': No such file or directory
read /etc/unbound/unbound.conf failed: 1 errors in configuration file
[1724919888] unbound-control[12447:0] fatal error: could not read config file
/etc/unbound/unbound.conf:63: error: cannot open include file '/etc/unbound/dhcp-leases.conf': No such file or directory
read /etc/unbound/unbound.conf failed: 1 errors in configuration file
[1724919888] unbound-control[12448:0] fatal error: could not read config file
/etc/unbound/unbound.conf:63: error: cannot open include file '/etc/unbound/dhcp-leases.conf': No such file or directory
...
(many more lines like this)
...

So I sat at my machine’s console and found this file not existing…
I created an empty /etc/unbound/dhcp-leases.conf file and started up the unbound service using the init script (/etc/init.d/unbound start), which then worked. But when I checked after a short time (a minute?) the /etc/unbound/dhcp-leases.conf file disappeared.

Well, unbound seems to continue it’s service, but after reboot the issue’s is back.

I then did create the file again after the service was running for few minutes, and it remained there, empty, but after machine reboot at latest it’s gone again.

Now I don’t know, what this file really does, I considered removing the include: line in the unbound.conf file, but I thought that might cause some other strange behaviour.

As a workaround I now added a line into the start section if the init script:

[ -f /etc/unbound/dhcp-leases.conf ] || touch /etc/unbound/dhcp-leases.conf

right before the service startup lines

boot_mesg "Starting Unbound DNS Proxy..."
loadproc /usr/sbin/unbound || exit $?

which does the trick for now.

Any idea what could be wrong?
Maybe some other misconfiguration on my side?

Regards
Matthias

nickh · 5 September 2024 18:54

What version of IPF are you running and do you have any DHCP leases or hosts entries?

matthaesius · 6 September 2024 06:40

Hello,
I run version core187 (www.ipfire.org - Profile 022caff402bb19890fbda6ade40c5e1a2d5202ba).

Yes, I have a few hosts entries,

as well as some fixed and some dyn. leases.

matthaesius · 6 September 2024 06:54

I discovered this topic »How do I get debug or info logs from unbound-dhcp-leases-bridge app« the other day.

It seems, that some script unbound-dhcp-leases-bridge manages this dhcp-leases.conf file, which is obviously invoked by the dhcp service,
i. e. it seems, that the dhcp-leases.conf file is removed at dhcp startup.
So I did now additionally add a line to fcrontab:

@reboot [ -f /etc/unbound/dhcp-leases.conf ] || echo -e "# dhcp-leases.conf\012" > /etc/unbound/dhcp-leases.conf

This happens after dhcp startup and the file remained.

nickh · 6 September 2024 10:46

The file should not be being removed unless some recent mods have been pushed through. The bridge must be failing somewhere

Why not touch the file in the unbound init file during start and reload until someone can troubleshoot.

bonnietwin · 6 September 2024 11:05

I would then expect some message for why the dhcp-leases.conf file was deleted by unbound and the only log messages that are being reported are that unbound can’t find dhcp-leases.conf but those will all be after the issue that caused the file to be deleted.

@matthaesius are you certain that there are no other log messages from unbound when the dhcp-leases.conf file is deleted. So anything just before the first message of

fatal error: could not read config file /etc/unbound/unbound.conf:63: error: cannot open include file '/etc/unbound/dhcp-leases.conf': No such file or directory

matthaesius · 8 September 2024 08:23

Looks like the dhcp service causes it.
When I restart the unbound service (/etc/init.d/unbound restart), everything works as expected.

When I restart the dhcp service, the dhcp-leases.conf file is gone afterwards.

# /etc/init.d/dhcp restart
Stopping DHCP Server...                                   [  OK  ]
Stopping Unbound DHCP Leases Bridge...    Not running.    [ WARN ]
Starting DHCP Server...                                   [  OK  ]
Starting Unbound DHCP Leases Bridge...                    [  OK  ]

This is what’s written to the log (/var/log/message):

Sep  8 10:13:56 ipfire dhcpd: Wrote 0 deleted host decls to leases file.
Sep  8 10:13:56 ipfire dhcpd: Wrote 0 new dynamic host decls to leases file.
Sep  8 10:13:56 ipfire dhcpd: Wrote 80 leases to leases file.
Sep  8 10:13:56 ipfire dhcpd: Server starting service.

bbitsch · 8 September 2024 08:36

The warning Stopping Unbound DHCP Leases Bridge... Not running. at dhcp restart points to a problem of the leases bridge program. Do you have any messages in /var/log/messages about this?

matthaesius · 8 September 2024 15:09

No, I greped for “leases” or “brigde” (grep -i …) but nothing except

Sep  8 10:26:22 igel3 dhcp[1121]: Unbound DHCP Leases Bridge started on /var/state/dhcp/dhcpd.leases
Sep  8 10:28:16 igel3 dhcp[1259]: Unbound DHCP Leases Bridge started on /var/state/dhcp/dhcpd.leases
Sep  8 16:43:34 igel3 dhcp[16208]: Unbound DHCP Leases Bridge started on /var/state/dhcp/dhcpd.leases
Sep  8 16:44:58 igel3 dhcp[16324]: Unbound DHCP Leases Bridge started on /var/state/dhcp/dhcpd.leases

…which was when I restarted dhcp.

Following this thread i did add the verbose flag to the Start line of this leases bridge in /etc/init.d/dhcp, i e.

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

This is the log output in messages after dhcp restart:

Sep  8 16:53:06 ipfire dhcp[16754]: Unbound DHCP Leases Bridge started on /var/state/dhcp/dhcpd.leases
Sep  8 16:53:06 ipfire dhcp[16754]: Wakeup of main loop
Sep  8 16:53:07 ipfire dhcp[16754]: Reading static hosts from /var/ipfire/main/hosts
Sep  8 16:53:07 ipfire dhcp[16754]: Static hosts:
Sep  8 16:53:07 ipfire dhcp[16754]:   host1.example.com    : 192.168.0.8
Sep  8 16:53:07 ipfire dhcp[16754]:   host2.example.com     : 192.168.0.7
Sep  8 16:53:07 ipfire dhcp[16754]:   my-printer.example.com : 192.168.0.211
   some more hosts...
Sep  8 16:53:07 ipfire dhcp[16754]: Reading DHCP leases from /var/state/dhcp/dhcpd.leases
Sep  8 16:53:07 ipfire dhcp[16754]: Reading fix leases from /var/ipfire/dhcp/fixleases
Sep  8 16:53:07 ipfire dhcp[16754]: DHCP Leases:
Sep  8 16:53:07 ipfire dhcp[16754]:   host3.example.com:
Sep  8 16:53:07 ipfire dhcp[16754]:     State: active
Sep  8 16:53:07 ipfire dhcp[16754]:     Start: 2024-09-08 14:53:07
Sep  8 16:53:07 ipfire dhcp[16754]:     End  : None
Sep  8 16:53:07 ipfire dhcp[16754]:   host4.example.com:
Sep  8 16:53:07 ipfire dhcp[16754]:     State: active
Sep  8 16:53:07 ipfire dhcp[16754]:     Start: 2024-09-08 14:53:07
Sep  8 16:53:07 ipfire dhcp[16754]:     End  : None
Sep  8 16:53:07 ipfire dhcp[16754]:   None:
Sep  8 16:53:07 ipfire dhcp[16754]:     State: active
Sep  8 16:53:07 ipfire dhcp[16754]:     Start: 2024-09-08 14:53:07
Sep  8 16:53:07 ipfire dhcp[16754]:     End  : None
Sep  8 16:53:07 ipfire dhcp[16754]:   host5.example.com:
Sep  8 16:53:07 ipfire dhcp[16754]:     State: active
Sep  8 16:53:07 ipfire dhcp[16754]:     Start: 2024-09-08 14:53:07
Sep  8 16:53:07 ipfire dhcp[16754]:     End  : None
 some more hosts...
Sep  8 16:53:07 ipfire dhcp[16754]: Writing DHCP leases...

What does None mean in the list of fixed leases?

bbitsch · 8 September 2024 17:24

‘None’ just means, that the lease ( the relation MAC <—> IP ) has an endless vaiidity. This property is expected

matthaesius · 9 September 2024 07:24

Matthias Menzel:

Sep  8 16:53:07 ipfire dhcp[16754]:   None:
Sep  8 16:53:07 ipfire dhcp[16754]:     State: active
Sep  8 16:53:07 ipfire dhcp[16754]:     Start: 2024-09-08 14:53:07
Sep  8 16:53:07 ipfire dhcp[16754]:     End  : None

Thank you, I guessed that one

But I rather meant that block above

matthaesius · 9 September 2024 18:11

It’s for sure the unbound-dhcp-leases-bridge program, that’s removing the /etc/unbound/dhcp-leases.conf file.

I invoked the program from the cmd line

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

and the file was gone after that. It’s reproducible.

The output is the same as in the post above with the log, and additionally appending this:

    ...
  host9.example.com:
    State: active
    Start: 2024-09-09 17:57:28
    End  : None
Writing DHCP leases...
Traceback (most recent call last):
  File "/usr/sbin/unbound-dhcp-leases-bridge", line 617, in <module>
    bridge.run()
  File "/usr/sbin/unbound-dhcp-leases-bridge", line 142, in run
    self.update_dhcp_leases()
  File "/usr/sbin/unbound-dhcp-leases-bridge", line 182, in update_dhcp_leases
    self.unbound.update_dhcp_leases(leases)
  File "/usr/sbin/unbound-dhcp-leases-bridge", line 520, in update_dhcp_leases
    if self.write_dhcp_leases(leases):
  File "/usr/sbin/unbound-dhcp-leases-bridge", line 555, in write_dhcp_leases
    os.link(f.name, self.path)
OSError: [Errno 18] Invalid cross-device link: '/tmp/tmp982m0z72' -> '/etc/unbound/dhcp-leases.conf'

(this is not to be found in the messages file)

bbitsch · 9 September 2024 18:37

I supposed that.
unbound-dhcp-leases-bridge assumes that the transfer from the new ( temporary ) file to the standard file ( /etc/unbound/dhcp-leases.conf ) works without error. The exact process is

delete old config file
move temp file to config file

The move is done by link command ( os.link in the error message ). The message seems to reflect the situation that /tmp and /etc are located on different devices. Is that true?

bbitsch · 9 September 2024 18:39

Matthias Menzel:

Sep  8 16:53:07 ipfire dhcp[16754]:   None:
Sep  8 16:53:07 ipfire dhcp[16754]:     State: active
Sep  8 16:53:07 ipfire dhcp[16754]:     Start: 2024-09-08 14:53:07
Sep  8 16:53:07 ipfire dhcp[16754]:     End  : None

Thank you, I guessed that one

But I rather meant that block above

This means there is no host-name or FQDN defined for one lease ( dynamic or fixed, the list is generated from both ).

matthaesius · 9 September 2024 19:36

That’s actually true. The /tmp dev. is a tmpfs.

# grep "/tmp" /etc/fstab
tmpfs  /tmp  tmpfs  size=10%  0 0

I can’t remember, but obviously I did that. Maybe I thought I could speed up the system? …don’t know.

Well, I did remove that very line, rebooted,
and everything’s good again…
Thank you @bbitch