V2.3 unbound fails to start on reboot



  • Fantastic upgrade. Thank you developers!

    Since upgrading, I have to manually start unbound. Not sure what logs to look at in order to provide helpful debugging feedback. A manual restart and everything is fine.


  • Rebel Alliance Developer Netgate

    Anything in the Resolver log when it happens?

    Status > System Logs, Resolver tab.



  • @jimp:

    Anything in the Resolver log when it happens?

    Status > System Logs, Resolver tab.

    Same problem as yea mentions above but mine has been doing since beta March 20th. Some have said in different posts a clean install helped clear it up but mine was upgrade from 2.2.6 not a clean redo. Will try clean install when I am in tinkering mood.
    The logs at verbosity of 2 still never showed anything out of place. The icon even showed it as running but the logs showed it was not.
    Simple restart after any reboot and all good for long periods. The logs just stop during reboot and then nothing until a restart.
    Figured I would just redo the install and it was just my machine until yea had posted. Running behind bridged Actiontec with public IP. Unbound works very well, no issue otherwise. Connection is rock solid.


  • Rebel Alliance Developer Netgate

    Next time it happens, get the full ps output ("ps uxawww") and the contents of /var/run/unbound.pid ("cat /var/run/unbound.pid")



  • @jimp:

    Next time it happens, get the full ps output ("ps uxawww") and the contents of /var/run/unbound.pid ("cat /var/run/unbound.pid")

    After reboot and Unbound not restarted.
    ps and your options:

    USER      PID  %CPU %MEM     VSZ    RSS TT  STAT STARTED    TIME COMMAND
    root    38714 100.0 22.7 1336488 918636  -  R     4:27PM 1:08.39 /usr/local/bin/snort -R 32858 -D -q --suppress-config-log -l /var/log/snort/snort_re132858 --pid-path /var/run --nolock-pidfile -G 32858 -c /usr/local/etc/snort/snort_32858_re1/snort.conf -i re1
    root       11  85.2  0.0       0     32  -  RL    4:26PM 2:00.57 [idle]
    root    84789  57.0 18.9 1213424 763652  -  Ss    4:27PM 0:41.13 /usr/local/bin/suricata --netmap -D -c /usr/local/etc/suricata/suricata_11170_re0/suricata.yaml --pidfile /var/run/suricata_re011170.pid
    root    95319   0.5  0.9  268196  35932  -  S     4:28PM 0:00.06 php-fpm: pool nginx (php-fpm)
    root        0   0.0  0.0       0    160  -  DLs   4:26PM 0:00.02 [kernel]
    root        1   0.0  0.0    9136    788  -  SLs   4:26PM 0:00.01 /sbin/init --
    root        2   0.0  0.0       0     16  -  DL    4:26PM 0:00.00 [crypto]
    root        3   0.0  0.0       0     16  -  DL    4:26PM 0:00.00 [crypto returns]
    root        4   0.0  0.0       0     32  -  DL    4:26PM 0:00.10 [cam]
    root        5   0.0  0.0       0     16  -  DL    4:26PM 0:00.24 [pf purge]
    root        6   0.0  0.0       0     16  -  DL    4:26PM 0:00.00 [sctp_iterator]
    root        7   0.0  0.0       0     32  -  DL    4:26PM 0:00.01 [pagedaemon]
    root        8   0.0  0.0       0     16  -  DL    4:26PM 0:00.00 [vmdaemon]
    root        9   0.0  0.0       0     16  -  DL    4:26PM 0:00.00 [pagezero]
    root       10   0.0  0.0       0     16  -  DL    4:26PM 0:00.00 [audit]
    root       12   0.0  0.0       0    288  -  WL    4:26PM 0:00.47 [intr]
    root       13   0.0  0.0       0     32  -  DL    4:26PM 0:00.00 [ng_queue]
    root       14   0.0  0.0       0     48  -  DL    4:26PM 0:00.01 [geom]
    root       15   0.0  0.0       0     16  -  DL    4:26PM 0:00.02 [rand_harvestq]
    root       16   0.0  0.0       0    160  -  DL    4:26PM 0:00.01 [usb]
    root       17   0.0  0.0       0     16  -  DL    4:26PM 0:00.00 [acpi_thermal]
    root       18   0.0  0.0       0     16  -  DL    4:26PM 0:00.00 [acpi_cooling1]
    root       19   0.0  0.0       0     16  -  DL    4:26PM 0:00.00 [idlepoll]
    root       20   0.0  0.0       0     32  -  DL    4:26PM 0:00.01 [bufdaemon]
    root       21   0.0  0.0       0     16  -  DL    4:26PM 0:00.01 [syncer]
    root       22   0.0  0.0       0     16  -  DL    4:26PM 0:00.00 [vnlru]
    root       56   0.0  0.0       0     16  -  DL    4:26PM 0:00.03 [md0]
    root      262   0.0  0.6  268192  24520  -  Ss    4:26PM 0:00.01 php-fpm: master process (/usr/local/lib/php-fpm.conf) (php-fpm)
    root      300   0.0  0.1   18888   2404  -  SNs   4:26PM 0:00.01 /usr/local/sbin/check_reload_status
    root      302   0.0  0.1   18888   2272  -  IN    4:26PM 0:00.00 check_reload_status: Monitoring daemon of check_reload_status
    root      312   0.0  0.1   13624   4812  -  Ss    4:26PM 0:00.01 /sbin/devd -q
    root     6880   0.0  0.1   14564   2180  -  Is    4:26PM 0:00.00 dhclient: re1 [priv] (dhclient)
    _dhcp   12687   0.0  0.1   14564   2304  -  Ss    4:27PM 0:00.00 dhclient: re1 (dhclient)
    root    18851   0.0  0.0    8168   1824  -  SN    4:28PM 0:00.00 sleep 60
    root    19069   0.0  0.1   18676   2252  -  R     4:28PM 0:00.00 ps uxawww
    root    20117   0.0  0.1   16676   2064  -  Ss    4:27PM 0:00.00 /usr/local/sbin/filterlog -i pflog0 -p /var/run/filterlog.pid
    root    20329   0.0  0.1   21616   5064  -  Ss    4:27PM 0:00.00 /usr/local/sbin/openvpn --config /var/etc/openvpn/server1.conf
    root    21324   0.0  0.1   18896   2376  -  Ss    4:27PM 0:00.00 /usr/local/sbin/xinetd -syslog daemon -f /var/etc/xinetd.conf -pidfile /var/run/xinetd.pid
    root    30594   0.0  0.1   14508   2312  -  Ss    4:27PM 0:00.01 /usr/sbin/syslogd -s -c -c -l /var/dhcpd/var/run/log -P /var/run/syslog.pid -f /var/etc/syslog.conf
    root    34956   0.0  0.1   15012   2196  -  Ss    4:27PM 0:00.01 /usr/local/bin/dpinger -S -r 0 -i WAN_DHCP -B xx.xx.82.112 -p /var/run/dpinger_WAN_DHCP_xx.xx.82.112_xx.xx.80.1.pid -u /var/run/dpinger_WAN_DHCP_xx.xx.82.112_xx.xx.80.1.sock -C /etc/rc.gateway_alarm -d 0 -s 500 -l 2000 -t 60000 -A 1000 -D 500 -L 20 xx.xx.80.1
    root    36171   0.0  0.2   46196   6888  -  Is    4:27PM 0:00.00 nginx: master process /usr/local/sbin/nginx -c /var/etc/nginx-webConfigurator.conf (nginx)
    root    36459   0.0  0.2   46196   7332  -  S     4:27PM 0:00.00 nginx: worker process (nginx)
    root    36668   0.0  0.2   46196   7968  -  S     4:27PM 0:00.06 nginx: worker process (nginx)
    root    37335   0.0  0.1   16532   2208  -  Is    4:27PM 0:00.01 /usr/sbin/cron -s
    root    38174   0.0  0.1   17000   2336  -  I     4:27PM 0:00.00 /bin/sh /usr/local/etc/rc.d/snort.sh start
    root    38859   0.0  0.0   12268   1872  -  Is    4:27PM 0:00.00 /usr/local/bin/minicron 240 /var/run/ping_hosts.pid /usr/local/bin/ping_hosts.sh
    root    39243   0.0  0.0   12268   1884  -  I     4:27PM 0:00.00 minicron: helper /usr/local/bin/ping_hosts.sh  (minicron)
    root    39296   0.0  0.0   12268   1872  -  Is    4:27PM 0:00.00 /usr/local/bin/minicron 3600 /var/run/expire_accounts.pid /usr/local/sbin/fcgicli -f /etc/rc.expireaccounts
    root    39591   0.0  0.0   12268   1872  -  Is    4:27PM 0:00.00 /usr/local/bin/minicron 86400 /var/run/update_alias_url_data.pid /usr/local/sbin/fcgicli -f /etc/rc.update_alias_url_data
    root    39948   0.0  0.0   12268   1884  -  I     4:27PM 0:00.00 minicron: helper /usr/local/sbin/fcgicli -f /etc/rc.update_alias_url_data  (minicron)
    root    40342   0.0  0.0   12268   1884  -  I     4:27PM 0:00.00 minicron: helper /usr/local/sbin/fcgicli -f /etc/rc.expireaccounts  (minicron)
    unbound 40591   0.0  4.0  190280 163592  -  Is    4:27PM 0:07.24 /usr/local/sbin/unbound -c /var/unbound/unbound.conf
    root    41643   0.0  0.4   30144  17988  -  Is    4:27PM 0:00.06 /usr/local/sbin/ntpd -g -c /var/etc/ntpd.conf -p /var/run/ntpd.pid
    root    48462   0.0  0.1   40244   5608  -  S     4:27PM 0:00.00 /usr/local/sbin/lighttpd_pfb -f /var/unbound/pfb_dnsbl_lighty.conf
    dhcpd   49880   0.0  0.3   24800  13444  -  Ss    4:27PM 0:00.01 /usr/local/sbin/dhcpd -user dhcpd -group _dhcp -chroot /var/dhcpd -cf /etc/dhcpd.conf -pf /var/run/dhcpd.pid re0 sk0
    root    51658   0.0  0.1   14612   2180  -  Is    4:27PM 0:00.00 /usr/local/sbin/sshlockout_pf 15
    root    85407   0.0  0.8  229204  33348  -  S     4:27PM 0:00.22 /usr/local/bin/php -f /usr/local/pkg/pfblockerng/pfblockerng.inc dnsbl
    root    98098   0.0  0.4  729884  14564  -  Is    4:27PM 0:00.00 /usr/local/sbin/radiusd
    root    51391   0.0  0.1   43440   2672 v0  Is    4:27PM 0:00.01 login [pam] (login)
    root    51787   0.0  0.1   17000   2636 v0  I     4:27PM 0:00.00 -sh (sh)
    root    52461   0.0  0.1   17000   2524 v0  I+    4:27PM 0:00.00 /bin/sh /etc/rc.initial
    root    85836   0.0  0.1   17000   2360 v0- SN    4:27PM 0:00.02 /bin/sh /var/db/rrd/updaterrd.sh
    
    

    Unbound process id: 40591
    Again tested with a refresh of my debian update package manager and no new logs . Then did a restart and again did a refresh of package manager and logs showed proper queries to debian.



  • @webtyro:

    After reboot and Unbound not restarted.

    did you manually start it then? That shows it's running normally.



  • @cmb:

    @webtyro:

    After reboot and Unbound not restarted.

    did you manually start it then? That shows it's running normally.

    Sequence as follows: Reboot - check unbound not running(no new logs) - run ps uxawww and cat /var/run/unbound.pid - test with package manager to make sure not running(no new logs) - Restart Unbound - test again with package manager and logs now correctly showing. It seems maybe a file or something may be left behind in my setup that is why I mentioned it was not a clean install. It looked ok to my tyro eyes. :o



  • If you have not a live WAN yet (PPPoE, DHCP), Unbound will quit.



  • I have seen that on 2.2.6-RELEASE (i386) with pfblockerNG, on reboot, unbound would die and I had to start it manually, as I don't reboot often, it didn't bother me.

    At some point, that problem disappeared.

    What I recollect doing in the weeks before was :

    • change some DNSBL table,
    • clean up Services DNS / Host Overrides
    • modification to Services DNS / Network Interfaces
    • modification to pfBlockerNG: DNSBL: Settings DNSBL Listening Interface
    • update to pfBlockerNG

    But I was not rebooting, so I don't have a clue on what "fixed" the issue.



  • @hda:

    If you have not a live WAN yet (PPPoE, DHCP), Unbound will quit.

    Understood. Not sure if yea is having that as an issue but my ps output shows it got the public IP ok.

    as I don't reboot often, it didn't bother me.

    @RonpfS, That is how I am about it. I am not overly concerned right now. Like I said I will eventually get to a clean install first before messing with a working setup. Yard work outside with my name on it.
    Not one to complain just thought I would mention it since yea piped up.



  • Are all of you seeing it using pfblocker's DNSBL? That's the issue here.
    https://redmine.pfsense.org/issues/6116



  • @cmb:

    Are all of you seeing it using pfblocker's DNSBL? That's the issue here.
    https://redmine.pfsense.org/issues/6116

    Not for mine.
    Read that over and it seems unrelated. No firmware upgrade or update.
    Just a reboot will stop the logging. The icon shows as running and the ps output confirms that too. Another thing is when I mentioned earlier that I tested if logging was working before I Restarted Unbound the package manager did in fact refresh and checked for updates. It seems to me the logging is just not kicking in.
    The more I look into Unbound the less I think it is with it "NOT" running, but just an issue with the logs.
    If the package manager had not been able to show progress in the refresh I might have thought it was a problem with Unbound not running. I am using DNSBL but never saw any issue in the upgrade logs during beta to release 2.3. Nothing in the pfblockerng logs going  back a month also. I may only need to do a clean install.  If yea does not chime in here, we may be kicking a dead horse. I will redo to a clean install in the next day or so and update back here.
    FYI. Full install with HDD, not nano or SSD.


Log in to reply