Unbound did not start upon first boot after update to RC



  • can't remember having this issue, with it  any of the previous snapshots .

    unbound started fine after second boot

    follow timestamps & not top->bottom
    out from status_logs.php?logfile=resolver:

    
    Apr 1 14:27:41 	filterdns 		adding entry 191.232.139.254 to table winspy on host vortex-win.data.microsoft.com
    Apr 1 14:27:41 	filterdns 		adding entry 191.232.139.253 to table winspy on host settings-win.data.microsoft.com
    Apr 1 14:27:33 	unbound 	70364:0 	info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
    Apr 1 14:27:33 	unbound 	70364:0 	info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch
    Apr 1 14:27:33 	unbound 	70364:0 	info: service stopped (unbound 1.5.5).
    Apr 1 14:27:33 	unbound 	70364:0 	info: start of service (unbound 1.5.5).
    Apr 1 14:27:33 	unbound 	70364:0 	notice: init module 1: iterator
    Apr 1 14:27:33 	unbound 	70364:0 	notice: init module 0: validator
    Apr 1 14:27:33 	unbound 	70364:0 	notice: Restart of unbound 1.5.5.
    Apr 1 14:27:33 	unbound 	70364:0 	info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
    Apr 1 14:27:33 	unbound 	70364:0 	info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
    Apr 1 14:27:33 	unbound 	70364:0 	info: service stopped (unbound 1.5.5).
    Apr 1 14:27:32 	unbound 	70364:0 	info: start of service (unbound 1.5.5).
    Apr 1 14:27:32 	unbound 	70364:0 	notice: init module 1: iterator
    Apr 1 14:27:32 	unbound 	70364:0 	notice: init module 0: validator
    Apr 1 14:27:32 	unbound 	31770:0 	info: 0.524288 1.000000 2
    Apr 1 14:27:32 	unbound 	31770:0 	info: 0.262144 0.524288 4
    Apr 1 14:27:32 	unbound 	31770:0 	info: 0.131072 0.262144 6
    Apr 1 14:27:32 	unbound 	31770:0 	info: 0.065536 0.131072 2
    Apr 1 14:27:32 	unbound 	31770:0 	info: 0.032768 0.065536 1
    Apr 1 14:27:32 	unbound 	31770:0 	info: 0.016384 0.032768 1
    Apr 1 14:27:32 	unbound 	31770:0 	info: lower(secs) upper(secs) recursions
    Apr 1 14:27:32 	unbound 	31770:0 	info: [25%]=0.131072 median[50%]=0.218453 [75%]=0.393216
    Apr 1 14:27:32 	unbound 	31770:0 	info: histogram of recursion processing times
    Apr 1 14:27:32 	unbound 	31770:0 	info: average recursion processing time 0.256180 sec
    Apr 1 14:27:32 	unbound 	31770:0 	info: server stats for thread 0: requestlist max 35 avg 17.5625 exceeded 0 jostled 0
    Apr 1 14:27:32 	unbound 	31770:0 	info: server stats for thread 0: 20 queries, 4 answers from cache, 16 recursions, 0 prefetch
    Apr 1 14:27:32 	unbound 	31770:0 	info: service stopped (unbound 1.5.5).
    Apr 1 14:27:29 	unbound 	31770:0 	info: start of service (unbound 1.5.5).
    Apr 1 14:27:29 	unbound 	31770:0 	notice: init module 1: iterator
    Apr 1 14:27:29 	unbound 	31770:0 	notice: init module 0: validator
    Apr 1 14:27:29 	unbound 	31770:0 	notice: Restart of unbound 1.5.5.
    Apr 1 14:27:29 	unbound 	31770:0 	info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
    Apr 1 14:27:29 	unbound 	31770:0 	info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
    Apr 1 14:27:29 	unbound 	31770:0 	info: service stopped (unbound 1.5.5).
    Apr 1 14:27:29 	unbound 	31770:0 	info: start of service (unbound 1.5.5).
    Apr 1 14:27:29 	unbound 	31770:0 	notice: init module 1: iterator
    Apr 1 14:27:29 	unbound 	31770:0 	notice: init module 0: validator
    Apr 1 14:27:23 	kernel 		filterdns: 1.0_8 -> 1.0_9 [pfSense] 
    
    

    MANUAL start of unbound service from GUI:

    
    Apr 1 14:31:12 	unbound 	77650:0 	info: start of service (unbound 1.5.5).
    Apr 1 14:31:12 	unbound 	77650:0 	notice: init module 1: iterator
    Apr 1 14:31:12 	unbound 	77650:0 	notice: init module 0: validator
    Apr 1 14:31:12 	unbound 	77650:0 	notice: Restart of unbound 1.5.5.
    Apr 1 14:31:12 	unbound 	77650:0 	info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
    Apr 1 14:31:12 	unbound 	77650:0 	info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
    Apr 1 14:31:12 	unbound 	77650:0 	info: service stopped (unbound 1.5.5).
    Apr 1 14:31:12 	unbound 	77650:0 	info: start of service (unbound 1.5.5).
    Apr 1 14:31:12 	unbound 	77650:0 	notice: init module 1: iterator
    Apr 1 14:31:12 	unbound 	77650:0 	notice: init module 0: validator
    Apr 1 14:31:12 	unbound 	77650:0 	notice: Restart of unbound 1.5.5.
    Apr 1 14:31:12 	unbound 	77650:0 	info: server stats for thread 0: requestlist max 4 avg 2.25 exceeded 0 jostled 0
    Apr 1 14:31:12 	unbound 	77650:0 	info: server stats for thread 0: 4 queries, 0 answers from cache, 4 recursions, 0 prefetch
    Apr 1 14:31:12 	unbound 	77650:0 	info: service stopped (unbound 1.5.5).
    Apr 1 14:31:12 	unbound 	77650:0 	info: start of service (unbound 1.5.5).
    Apr 1 14:31:11 	unbound 	77650:0 	notice: init module 1: iterator
    Apr 1 14:31:11 	unbound 	77650:0 	notice: init module 0: validator
    Apr 1 14:31:11 	unbound 	77650:0 	notice: Restart of unbound 1.5.5.
    Apr 1 14:31:11 	unbound 	77650:0 	info: 0.262144 0.524288 2
    Apr 1 14:31:11 	unbound 	77650:0 	info: 0.131072 0.262144 2
    Apr 1 14:31:11 	unbound 	77650:0 	info: 0.032768 0.065536 1
    Apr 1 14:31:11 	unbound 	77650:0 	info: lower(secs) upper(secs) recursions
    Apr 1 14:31:11 	unbound 	77650:0 	info: [25%]=0.147456 median[50%]=0.229376 [75%]=0.360448
    Apr 1 14:31:11 	unbound 	77650:0 	info: histogram of recursion processing times
    Apr 1 14:31:11 	unbound 	77650:0 	info: average recursion processing time 0.204544 sec
    Apr 1 14:31:11 	unbound 	77650:0 	info: server stats for thread 0: requestlist max 16 avg 7.2 exceeded 0 jostled 0
    Apr 1 14:31:11 	unbound 	77650:0 	info: server stats for thread 0: 15 queries, 10 answers from cache, 5 recursions, 0 prefetch
    Apr 1 14:31:11 	unbound 	77650:0 	info: service stopped (unbound 1.5.5).
    Apr 1 14:31:10 	unbound 	77650:0 	info: start of service (unbound 1.5.5).
    Apr 1 14:31:10 	unbound 	77650:0 	notice: init module 1: iterator
    Apr 1 14:31:10 	unbound 	77650:0 	notice: init module 0: validator
    Apr 1 14:31:10 	unbound 	77650:0 	notice: Restart of unbound 1.5.5.
    Apr 1 14:31:10 	unbound 	77650:0 	info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
    Apr 1 14:31:10 	unbound 	77650:0 	info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
    Apr 1 14:31:10 	unbound 	77650:0 	info: service stopped (unbound 1.5.5).
    Apr 1 14:31:10 	unbound 	77650:0 	info: start of service (unbound 1.5.5).
    Apr 1 14:31:10 	unbound 	77650:0 	notice: init module 1: iterator
    Apr 1 14:31:10 	unbound 	77650:0 	notice: init module 0: validator
    
    


  • I had this happen in one of the prior builds (unbound that is).  And now I have a situation where instead of something not starting (IPSEC in my case), it's starting twice and causing just as much havoc as not starting.



  • "can't remember having this issue, with it  any of the previous snapshots"
    I started using the Beta March 20th and after any update requiring a reboot also needed a restart of unbound to get the log file showing it was indeed running. After reboot I also had to "Reload" the DNSBL to get it showing in the widget for that database.
    Also I found the running/stopped icon not showing unbound as stopped. It always showed as running.
    Still, thank you for a great firewall. Everything else went very smoothly in the upgrade to RC.


Log in to reply