Unbound does not start after update on a couple boxes (Config Error?)


  • Ive got a handful of firewalls (some of my own and some owned by others) that I watch over.

    This has happened since 2.3 release and now on the snapshots as well..

    2 boxes when I reboot,  Unbound does not start.  The rest all do just fine.  Both boxes are mine so could be something from earlier tinkering and/or snapshot use.

    2.3.1-DEVELOPMENT (i386)
    built on Tue Apr 26 11:02:56 CDT 2016

    DNS Resolver is setup similarly between all with the difference being interfaces of coarse as each box is set up a little different.

    Config looks the same.

    Im lost.

    edit= forgot to mention that I can start the service no problem.


  • What's unbound log during boot? Should have something in the system log and/or resolver log.


  • No logs.

    Then when I start the service-

    Apr 26 16:16:45                 unbound                 10244:0                 notice: init module 0: iterator                   
    Apr 26 16:16:45                 unbound                 10244:0                 info: start of service (unbound 1.5..                   
    Apr 26 16:16:45                 unbound                 10244:0                 info: service stopped (unbound 1.5..                   
    Apr 26 16:16:45                 unbound                 10244:0                 info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch                   
    Apr 26 16:16:45                 unbound                 10244:0                 info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0                   
    Apr 26 16:16:45                 unbound                 10244:0                 info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch                   
    Apr 26 16:16:45                 unbound                 10244:0                 info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0                   
    Apr 26 16:16:45                 unbound                 10244:0                 info: server stats for thread 2: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch                   
    Apr 26 16:16:45                 unbound                 10244:0                 info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0                   
    Apr 26 16:16:45                 unbound                 10244:0                 info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch                   
    Apr 26 16:16:45                 unbound                 10244:0                 info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0                   
    Apr 26 16:16:45                 unbound                 10244:0                 notice: Restart of unbound 1.5.8.                   
    Apr 26 16:16:45                 unbound                 10244:0                 notice: init module 0: iterator                  
    Apr 26 16:16:45                 unbound                 10244:0                info: start of service (unbound 1.5..                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: service stopped (unbound 1.5..                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 2: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0                   
    Apr 26 16:16:46                 unbound                 10244:0                 notice: Restart of unbound 1.5.8.                   
    Apr 26 16:16:46                 unbound                 10244:0                 notice: init module 0: iterator                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: start of service (unbound 1.5..                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: service stopped (unbound 1.5..                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 2: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0                   
    Apr 26 16:16:46                 unbound                 10244:0                 notice: Restart of unbound 1.5.8.                   
    Apr 26 16:16:46                 unbound                 10244:0                 notice: init module 0: iterator                   
    Apr 26 16:16:46                 unbound                 10244:0                 info: start of service (unbound 1.5..                   
    
    

  • Hm, the "Can't assign requested address for" link local seems suspect, but that's from the time when it starts up successfully, right? I'd expect that to have logged when it failed if that were related.

    Would you mind getting me into one of the systems in question so I can add some debug logging to find out where things are going wrong?


  • Yep-  get you in my spur office.  Its one of the boxes doing it.

    This from console here when I rebooted.  Seems like it starts there.

    Configuring firewall…...done.
    Starting PFLOG...done.
    Setting up gateway monitors...done.
    Synchronizing user settings...done.
    Starting webConfigurator...done.
    Configuring CRON...done.
    Starting DNS Resolver...done.


  • from dmesg

    Apr 26 16:37:39 php-cgi

    rc.bootup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1461713859] unbound[29181:0] error: can't bind socket: Can't assign requested address for 2002:1871:33a4:1::1 [1461713859] unbound[29181:0] fatal error: could not open ports' [/t][/t]
    Once I took all the IPv6 link interfaces out of the loop this box restarted with Unbound starting fine.  But wouldn't selecting "All" do the same thing?


  • As soon as I take the ip6 link-locals out of the equation unbound starts on its own.

    Those roll off down when selecting interfaces so I forgot I had em set.

    The other boxes- binding to ip6 link-locals don't cause issues with Unbound starting just for info. Seems hit or miss depending on the device.


  • If you have "all" selected, it binds to *:53, so any IP that comes and goes is no big deal. If you choose the options individually, then it specifies those IPs in the config file individually, and it has to be able to bind to all those specific IPs or it fails.

    One other person reported that with link local IPs selected, though it wasn't something I could replicate.

    If you can get me an account on one of those, open it up WAN-side from 208.123.73.0/24, I'd like to check it out. Can PM me the password here and email me the username and IP (cmb at pfsense dot org).


  • @cmb:

    If you can get me an account on one of those, open it up WAN-side from 208.123.73.0/24, I'd like to check it out. Can PM me the password here and email me the username and IP (cmb at pfsense dot org).

    Sent-

    Let me know if you want into the primary here as well.

    I just looked and had ip6 link-local selected on several other sites as well with no problems.  Just these two with the issues.

    :)


  • Interesting coincidence.

    my box with the DNS resolver problem-    (has IPv address obviously)
    PING6(56=40+8+8 bytes) 200x:1xx1:3xx4::1 –> ::1                (changed to obfuscate)
    --- ::1 ping6 statistics ---
    3 packets transmitted, 0 packets received, 100.0% packet loss

    My customer box which works fine.  (does not have IPv6 set up)
    PING6(56=40+8+8 bytes) ::1 --> ::1
    16 bytes from ::1, icmp_seq=0 hlim=64 time=0.521 ms
    16 bytes from ::1, icmp_seq=1 hlim=64 time=0.353 ms
    16 bytes from ::1, icmp_seq=2 hlim=64 time=0.459 ms