unboud stops multiple times per day, due to part of Router Advertisement expired

Unbound
1

Unbound 1.13.1, with ./configure --prefix=/usr --sysconfdir=/etc --disable-static --enable-tfo-client --enable-tfo-server --with-libevent --with-libhiredis --enable-cachedb --with-pidfile=/run/unbound.pid

The log shows, multiple times per day:

May 14 06:15:26 unbound[790:0] info: service stopped (unbound 1.13.1).

info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting

info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0

info: mesh has 1 recursion states (0 with reply, 1 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out

info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting

info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0

info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out

info: server stats for thread 2: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting

info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0

info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out

info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting

info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0

info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out

notice: Restart of unbound 1.13.1.

unbound than almost always immediately stops a second time:

May 14 06:15:27 unbound[790:0] info: service stopped (unbound 1.13.1).

verbosity 1, which, according to the manual, should display all errors.

I’ve narrowed it down to a specific matching syslog entry:

The syslog entries:

May 14 06:15:26 raspberrypi dhcpcd[562]: eth0: part of Router Advertisement expired

May 14 07:09:04 raspberrypi dhcpcd[562]: eth0: Router Advertisement from fe80::20e:c4ff:fecf:f3cf

May 14 07:09:04 raspberrypi dhcpcd[562]: eth0: Router Advertisement from fe80::20e:c4ff:fecf:f3cf

May 14 14:53:25 raspberrypi dhcpcd[562]: eth0: part of Router Advertisement expired

The unbound entries:

May 14 06:15:26 unbound[790:0] info: service stopped (unbound 1.13.1).

May 14 06:15:27 unbound[790:0] info: service stopped (unbound 1.13.1).

May 14 14:53:25 unbound[790:0] info: service stopped (unbound 1.13.1).

May 14 14:53:29 unbound[790:0] info: service stopped (unbound 1.13.1).

Notice the time match, part of Router Advertisement expired apparently triggers an unbound restart

the IPv4 address is served by a static (MAC based) entry, thus never changes.

the IPv6 address is served by a pfsense firewall (configured with ‘track interface’), never changes, unless ISP resets… (didn’t happen today).

There is really nothing I can do about the IP address assignment…

Not sure how to proceed from here, I don’t understand why an expired route causes unbound to restart

2

Hi Peter,

Unbound does not restart on its own.
I suspect that the DCHP daemon (or something else on your system) instructs unbound to reload (either with SIGHUP or via unbound-control reload) when there is a DHCP update.

I would advise to look at the DHCP configuration for further troubleshooting.

Best regards,
-- George

3

Thank you for your reply

I agree that it's probably the DHCP daemon that triggers unbound to restart,
not directly, but because unbound detects a routing change.
Since there is a syslog message from the daemon (dhcpcd[562]: eth0: part of
Router Advertisement Expired), it is the probable cause for unbound to
restart.

However (1) the message says part of the routing expired, shouldn't unbound
ignore expired routes?

However (2) , as I mentioned before, unbound restarts twice, every time this
happens.
There is nothing I can find that would explain the second restart.
So this looks like something unbound is doing, without any external event or
command.

I very much doubt it is an unbound-control command, these are logged in the
unbound log.
Not sure if SIGHUB signals are logged...

Behalf Of George Thessalonikefs via Unbound-users

4

Hi Peter,

Since you mentioned something about pfsense, this could also be a culprit for sending unbound a HUP signal (the second one).

Unbound does not explicitly log that it receives a HUP signal. Instead you will see unbound reloading without previously receiving an unbound-control command.

I am afraid I cannot help you further because as I said unbound does not reload on its own. Maybe someone else that uses a similar setup could provide more information.

-- George

5

Hi

Last month, I asked a question, regarding unexpected unbound stops.

SOLVED: the culprit appears to be the resolvconf script (which resolvconf)


sha1sum /usr/sbin/resolvconf

4bfee7ac4e855ae48e35ab9ac37ebb8c2d37d210 /usr/sbin/resolvconf

I haven’t had an unbound stop message since I commented out


#unbound_conf=/var/cache/unbound/resolvconf_resolvers.conf

in /etc/resolvconf.conf, this on raspberry pi 3b, Raspberry Pi OS Lite, Release date: May 7th 2021.

You can read the full story here (Unbound frequent restarts - General - Pi-hole Userspace)

summary of the events I noticed:

  • stop message in unbound: May 14 06:15:26 unbound[790:0] info: service stopped (unbound 1.13.1)

  • matching syslog error : May 14 06:15:26 raspberrypi dhcpcd[562]: eth0: part of Router Advertisement expired

  • setup monitoring in screen: sudo strace -tt -ffo /tmp/trace-unbound -e trace=%signal -p “pidof unbound”

  • logging script in screen (the topic also describes a method using audit):


#!/bin/bash

file="/home/pi/ps-test.txt"

while :

do

while IFS=" " read -r USER PID CPU MEM VSZ RSS TTY STAT START TIME COMMAND; do

if ! grep -q "${PID}" "${file}"; then

if [[ ( "${COMMAND}" != 'ps aux' ) && ( "${COMMAND}" != *"ps-test"* )]]; then

echo "$(date),${PID},${COMMAND}" | sudo tee -a "${file}"

fi

fi

done < <(ps aux)

done

result in log:


Sun 30 May 18:48:15 CEST 2021,32610,/bin/sh /usr/sbin/resolvconf -a eth0.ra

commenting out the unbound entry in /etc/resolvconf.conf eliminates the unbound stops.

For the first time, since I started monitoring errors and warnings in my logs, the unbound log doesn’t contain any errors / warnings.