pfSense

I'm observing an issue on my SG-1000 (came preloaded with 2.4b, currently running v. 2.4.0.b.20170430.0444) which causes unbound restarts to fail after the dhcpleases system sends it a SIGHUP due to changes in /etc/hosts.
As you'll see, in those cases unbound usually takes about ~10 seconds to restart (which is not all that surprising given the SG-1000's limited processing power). Also, the system log entry in the first case seems to be logged ~2 seconds before the "old" unbound has properly shut down (according to its logs). That makes me wonder if it's just the limited CPU speed of the SG-1000 that makes this bug observable.
The kqueue error from the first logs puzzles me a bit (since its not properly explained) - I can't tell if it's a symtpom or part of the cause. The error will also appear after a failed restart (when unbound isn't running anymore).

Failing case (changes in /etc/hosts)¶

unbound log:¶

May 21 13:49:10    unbound    22926:0    info: start of service (unbound 1.6.1).
May 21 13:57:36    unbound    22926:0    info: service stopped (unbound 1.6.1).
May 21 13:57:36    unbound    22926:0    info: server stats for thread 0: 6 queries, 4 answers from cache, 2 recursions, 0 prefetch, 0 rejected by ip ratelimiting
May 21 13:57:36    unbound    22926:0    info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
May 21 13:57:36    unbound    22926:0    info: average recursion processing time 0.308737 sec
May 21 13:57:36    unbound    22926:0    info: histogram of recursion processing times
May 21 13:57:36    unbound    22926:0    info: [25%]=0 median[50%]=0 [75%]=0
May 21 13:57:36    unbound    22926:0    info: lower(secs) upper(secs) recursions
May 21 13:57:36    unbound    22926:0    info: 0.065536 0.131072 1
May 21 13:57:36    unbound    22926:0    info: 0.262144 0.524288 1
May 21 13:57:36    unbound    22926:0    notice: Restart of unbound 1.6.1.
May 21 13:57:54    unbound    22926:0    notice: init module 0: validator
May 21 13:57:54    unbound    22926:0    notice: init module 1: iterator
May 21 13:57:55    unbound    22926:0    info: start of service (unbound 1.6.1).
May 21 13:57:55    unbound    22926:0    info: service stopped (unbound 1.6.1).
May 21 13:57:55    unbound    22926:0    info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
May 21 13:57:55    unbound    22926:0    info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0

dhcp log:¶

May 21 13:57:36    dhcpleases        /etc/hosts changed size from original!
May 21 13:57:36    dhcpleases        Sending HUP signal to dns daemon(22926)
May 21 13:57:48    dhcpleases        /etc/hosts changed size from original!
May 21 13:57:49    dhcpleases        Sending HUP signal to dns daemon(22926)
May 21 13:57:53    dhcpleases        kqueue error: unkown
May 21 13:57:53    dhcpleases        Sending HUP signal to dns daemon(22926)
May 21 13:57:55    dhcpd        Internet Systems Consortium DHCP Server 4.3.5
May 21 13:57:55    dhcpd        Copyright 2004-2016 Internet Systems Consortium.
May 21 13:57:55    dhcpd        All rights reserved.
May 21 13:57:55    dhcpd        For info, please visit https://www.isc.org/software/dhcp/
May 21 13:57:55    dhcpd        Config file: /etc/dhcpd.conf
May 21 13:57:55    dhcpd        Database file: /var/db/dhcpd.leases
May 21 13:57:55    dhcpd        PID file: /var/run/dhcpd.pid
May 21 13:57:55    dhcpd        Internet Systems Consortium DHCP Server 4.3.5
May 21 13:57:55    dhcpd        Copyright 2004-2016 Internet Systems Consortium.
May 21 13:57:55    dhcpd        All rights reserved.
May 21 13:57:55    dhcpd        For info, please visit https://www.isc.org/software/dhcp/
May 21 13:57:55    dhcpd        Wrote 0 deleted host decls to leases file.
May 21 13:57:55    dhcpd        Wrote 0 new dynamic host decls to leases file.
May 21 13:57:55    dhcpd        Wrote 14 leases to leases file.
May 21 13:57:55    dhcpd        Listening on BPF/cpsw1/[MAC address]/[IP address]/[subnet mask]
May 21 13:57:55    dhcpd        Sending on BPF/cpsw1/[MAC address]/[IP address]/[subnet mask]
May 21 13:57:55    dhcpd        Sending on Socket/fallback/fallback-net
May 21 13:57:55    dhcpd        Server starting service.
May 21 13:57:55    dhcpleases        Sending HUP signal to dns daemon(22926)
May 21 13:57:55    dhcpleases        Sending HUP signal to dns daemon(22926)

System > General log:¶

May 21 13:57:53    php-fpm    62381    /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1495367873] unbound[85962:0] error: bind: address already in use [1495367873] unbound[85962:0] fatal error: could not open ports'

---

Successfull case (changed DHCP leases)¶

In contrast to the /etc/hosts case, restarts due to changed dhcp leases seem to work fine:

unbound log:¶

May 21 13:38:30    unbound    22926:0    info: start of service (unbound 1.6.1).
May 21 13:48:58    unbound    22926:0    info: service stopped (unbound 1.6.1).
May 21 13:48:58    unbound    22926:0    info: server stats for thread 0: 8 queries, 6 answers from cache, 2 recursions, 0 prefetch, 0 rejected by ip ratelimiting
May 21 13:48:58    unbound    22926:0    info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
May 21 13:48:58    unbound    22926:0    info: average recursion processing time 0.409663 sec
May 21 13:48:58    unbound    22926:0    info: histogram of recursion processing times
May 21 13:48:58    unbound    22926:0    info: [25%]=0 median[50%]=0 [75%]=0
May 21 13:48:58    unbound    22926:0    info: lower(secs) upper(secs) recursions
May 21 13:48:58    unbound    22926:0    info: 0.262144 0.524288 2
May 21 13:48:58    unbound    22926:0    notice: Restart of unbound 1.6.1.
May 21 13:49:09    unbound    22926:0    notice: init module 0: validator
May 21 13:49:09    unbound    22926:0    notice: init module 1: iterator
May 21 13:49:10    unbound    22926:0    info: start of service (unbound 1.6.1).

dhcp log:¶

May 21 13:48:58    dhcpd        DHCPREQUEST for 192.168.1.104 from [MAC address] ([hostname]) via cpsw1
May 21 13:48:58    dhcpd        DHCPACK on 192.168.1.104 to [MAC address] ([hostname]) via cpsw1
May 21 13:48:58    dhcpleases        Sending HUP signal to dns daemon(22926)

---

Changes in /etc/hosts after failed restart¶

dhcp log:¶

May 21 15:30:51    dhcpleases        /etc/hosts changed size from original!
May 21 15:30:51    dhcpleases        Sending HUP signal to dns daemon(22926)
May 21 15:30:51    dhcpleases        Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
May 21 15:30:53    dhcpleases        kqueue error: unkown
May 21 15:30:53    dhcpleases        Sending HUP signal to dns daemon(79438)