Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    unbound service stopping/restaring on 2.5.2

    DHCP and DNS
    2
    5
    273
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • se_marcS
      se_marc
      last edited by

      Hey all,

      I'm still having issues with the unbound service stopping on 2.5.2. I have watchdog set up and when I see alerts, most of the time its around 0:33:00 (but not always).

      has anyone else had this issue? any suggestions?

      i wasn't able to get logs in time for when watchdog actually restarted the service but when I check resolver.log (and the all the .gz2 files) i see unbound restarting quite a bit.

      Sep 10 09:14:54 zuul unbound[68691]: [68691:0] notice: Restart of unbound 1.12.0.
Sep 10 09:14:54 zuul unbound[68691]: [68691:0] notice: init module 0: validator
Sep 10 09:14:54 zuul unbound[68691]: [68691:0] notice: init module 1: iterator
Sep 10 09:14:54 zuul unbound[68691]: [68691:0] info: start of service (unbound 1.12.0).
Sep 10 09:14:57 zuul unbound[68691]: [68691:3] info: generate keytag query _ta-4f66. NULL IN
Sep 10 09:14:57 zuul unbound[68691]: [68691:0] info: generate keytag query _ta-4f66. NULL IN
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: service stopped (unbound 1.12.0).
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: server stats for thread 0: 1186 queries, 1150 answers from cache, 36 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: server stats for thread 0: requestlist max 8 avg 0.555556 exceeded 0 jostled 0
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: average recursion processing time 0.120337 sec
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: histogram of recursion processing times
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: [25%]=0.028672 median[50%]=0.098304 [75%]=0.189326
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: lower(secs) upper(secs) recursions
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.000000    0.000001 6
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.016384    0.032768 4
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.032768    0.065536 3
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.065536    0.131072 10
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.131072    0.262144 9
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.262144    0.524288 3
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.524288    1.000000 1
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: server stats for thread 1: 44 queries, 40 answers from cache, 4 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: average recursion processing time 0.082387 sec
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: histogram of recursion processing times
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: [25%]=0.0436907 median[50%]=0.0546133 [75%]=0.065536
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: lower(secs) upper(secs) recursions
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.032768    0.065536 3
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.131072    0.262144 1
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: server stats for thread 2: 123 queries, 117 answers from cache, 6 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: server stats for thread 2: requestlist max 3 avg 0.5 exceeded 0 jostled 0
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: average recursion processing time 0.352080 sec
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: histogram of recursion processing times
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: [25%]=7.5e-07 median[50%]=0.131072 [75%]=0.393216
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: lower(secs) upper(secs) recursions
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.000000    0.000001 2
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.065536    0.131072 1
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.131072    0.262144 1
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.262144    0.524288 1
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    1.000000    2.000000 1
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: server stats for thread 3: 503 queries, 480 answers from cache, 23 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: server stats for thread 3: requestlist max 2 avg 0.173913 exceeded 0 jostled 0
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: average recursion processing time 0.171179 sec
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: histogram of recursion processing times
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: [25%]=0.0188416 median[50%]=0.045056 [75%]=0.278528
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: lower(secs) upper(secs) recursions
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.000000    0.000001 2
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.008192    0.016384 3
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.016384    0.032768 5
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.032768    0.065536 4
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.131072    0.262144 3
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.262144    0.524288 4
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info:    0.524288    1.000000 2
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] notice: Restart of unbound 1.12.0.
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] notice: init module 0: validator
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] notice: init module 1: iterator
Sep 10 09:19:44 zuul unbound[68691]: [68691:0] info: start of service (unbound 1.12.0).
      GertjanG 1 Reply Last reply Reply Quote 0
      • GertjanG
        Gertjan @se_marc
        last edited by

        @se_marc

        You are using pfBlockerNG-devel ?
        It could restart unbound.

        You have set this option (under Services > DNS Resolver > General Settings ) :

        b705d932-0140-4914-9941-29871b6a239a-image.png

        It will restart unbound on every new (or renew) DHCP lease.
        Btw : If this option is set, The so called Python mode under pfBlockerNG-devel wouldn't work, see Firewall > pfBlockerNG > DNSBL

        Btw : true, a regularly, very frequent unbound restart is not good.
        But, IMHO, using the "Watchdog" package is "not advisable under any circumstances".

        [2.5.2-RELEASE][root@pfsense.my-local-network.net]/root: grep "start" /var/log/resolver.log | wc -l
      46

        And the file ar/log/resolver.log contains logs line since the beginning of august.
        Half the the time, I was changing unbounds settings, thus provoking a restart.

        No "help me" PM's please. Use the forum, the community will thank you.
        Edit : and where are the logs ??

        se_marcS 1 Reply Last reply Reply Quote 1
        • se_marcS
          se_marc @Gertjan
          last edited by

          @gertjan I am not using pfblockerNG-devel, however I did have the Register DHCP leases in the DNS Resolver option turned on.

          I have toggled that off and will see if it makes a difference.

          Thanks for the input.

          GertjanG 1 Reply Last reply Reply Quote 0
          • GertjanG
            Gertjan @se_marc
            last edited by Gertjan

            @se_marc said in unbound service stopping/restaring on 2.5.2:

            and will see if it makes a difference

            If you use just one 'PC' on your only pfSEnse LAN, and this PC renews ones a day, then the effect will be minimal.
            On the other hand, if you have many LAN's and hundreds of devices, the DHCP server's activity grows linearly, as the number of times unbound gets restarted
            And it could be worse : some "door bell type (low bud) devices" could misbehave, and ask a new lease every second or so. This creates a situation wghere people start to claim "Internet doesn't work". "Internet" never breaks of course, it just the local DNS that gets chain gunned.
            ( when you think about it : this makes the DHCP log a super debug tool )

            No "help me" PM's please. Use the forum, the community will thank you.
            Edit : and where are the logs ??

            1 Reply Last reply Reply Quote 1
            • se_marcS
              se_marc
              last edited by

              this seems to have done the trick! I haven't gotten any watchdog alerts since toggling off Register DHCP leases in the DNS Resolver.

              thanks again!

              1 Reply Last reply Reply Quote 0
              • First post
                Last post