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

    Unbound frequently restarts on 2.2 - is this normal?

    Scheduled Pinned Locked Moved DHCP and DNS
    43 Posts 17 Posters 10.0k Views
    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.
    • I
      Inq
      last edited by

      I have the same problem with unbound. There seems to be a direct connection between unbound stopping and restarting and DHCP leases. At 8:56:11 the unbound service stopped and then restarted:

      Feb 11 08:56:11	unbound: [16927:0] info: start of service (unbound 1.5.1).
Feb 11 08:56:11	unbound: [16927:0] notice: init module 1: iterator
Feb 11 08:56:11	unbound: [16927:0] notice: init module 0: validator
Feb 11 08:56:11	unbound: [16927:0] notice: Restart of unbound 1.5.1.
Feb 11 08:56:11	unbound: [16927:0] info: 0.262144 0.524288 1
Feb 11 08:56:11	unbound: [16927:0] info: 0.065536 0.131072 1
Feb 11 08:56:11	unbound: [16927:0] info: 0.032768 0.065536 9
Feb 11 08:56:11	unbound: [16927:0] info: 0.016384 0.032768 2
Feb 11 08:56:11	unbound: [16927:0] info: 0.008192 0.016384 1
Feb 11 08:56:11	unbound: [16927:0] info: 0.004096 0.008192 1
Feb 11 08:56:11	unbound: [16927:0] info: 0.002048 0.004096 3
Feb 11 08:56:11	unbound: [16927:0] info: 0.001024 0.002048 1
Feb 11 08:56:11	unbound: [16927:0] info: 0.000000 0.000001 1
Feb 11 08:56:11	unbound: [16927:0] info: lower(secs) upper(secs) recursions
Feb 11 08:56:11	unbound: [16927:0] info: [25%]=0.004096 median[50%]=0.0364089 [75%]=0.0546133
Feb 11 08:56:11	unbound: [16927:0] info: histogram of recursion processing times
Feb 11 08:56:11	unbound: [16927:0] info: average recursion processing time 0.044537 sec
Feb 11 08:56:11	unbound: [16927:0] info: server stats for thread 1: requestlist max 2 avg 0.3 exceeded 0 jostled 0
Feb 11 08:56:11	unbound: [16927:0] info: server stats for thread 1: 111 queries, 91 answers from cache, 20 recursions, 0 prefetch
Feb 11 08:56:11	unbound: [16927:0] info: 0.524288 1.000000 1
Feb 11 08:56:11	unbound: [16927:0] info: 0.262144 0.524288 2
Feb 11 08:56:11	unbound: [16927:0] info: 0.131072 0.262144 1
Feb 11 08:56:11	unbound: [16927:0] info: 0.065536 0.131072 2
Feb 11 08:56:11	unbound: [16927:0] info: 0.032768 0.065536 6
Feb 11 08:56:11	unbound: [16927:0] info: 0.016384 0.032768 6
Feb 11 08:56:11	unbound: [16927:0] info: 0.008192 0.016384 1
Feb 11 08:56:11	unbound: [16927:0] info: 0.004096 0.008192 5
Feb 11 08:56:11	unbound: [16927:0] info: 0.002048 0.004096 4
Feb 11 08:56:11	unbound: [16927:0] info: lower(secs) upper(secs) recursions
Feb 11 08:56:11	unbound: [16927:0] info: [25%]=0.0065536 median[50%]=0.0273067 [75%]=0.0600747
Feb 11 08:56:11	unbound: [16927:0] info: histogram of recursion processing times
Feb 11 08:56:11	unbound: [16927:0] info: average recursion processing time 0.082688 sec
Feb 11 08:56:11	unbound: [16927:0] info: server stats for thread 0: requestlist max 3 avg 0.857143 exceeded 0 jostled 0
Feb 11 08:56:11	unbound: [16927:0] info: server stats for thread 0: 136 queries, 108 answers from cache, 28 recursions, 0 prefetch
Feb 11 08:56:11	unbound: [16927:0] info: service stopped (unbound 1.5.1).

      At that exact time i get this in DHCP logs:

      Feb 11 08:56:11 dhcpd: DHCPACK on 192.168.1.15 to 1c:af:f7:xx:xx:xx (DIR-600) via em0
      Feb 11 08:56:11 dhcpd: DHCPREQUEST for 192.168.1.15 from 1c:af:f7:xx:xx:xx (DIR-600) via em0
      Feb 11 08:56:11 dhcpd: Wrote 9 leases to leases file.
      Feb 11 08:56:11 dhcpd: Wrote 0 new dynamic host decls to leases file.
      Feb 11 08:56:11 dhcpd: Wrote 0 deleted host decls to leases file.

      Again at 09:57:00 unbound service restarts:

      Feb 11 09:57:00	unbound: [16927:0] info: start of service (unbound 1.5.1).
Feb 11 09:57:00	unbound: [16927:0] notice: init module 1: iterator
Feb 11 09:57:00	unbound: [16927:0] notice: init module 0: validator
Feb 11 09:57:00	unbound: [16927:0] notice: Restart of unbound 1.5.1.
Feb 11 09:57:00	unbound: [16927:0] info: 0.524288 1.000000 1
Feb 11 09:57:00	unbound: [16927:0] info: 0.262144 0.524288 6

      Corelated with this DHCP log:

      Feb 11 09:57:00 router dhcpd: DHCPOFFER on 192.168.1.17 to 78:dd:08:xx:xx:xx (vaio) via em0
Feb 11 09:57:00 router dhcpd: Wrote 0 deleted host decls to leases file.
Feb 11 09:57:00 router dhcpd: Wrote 0 new dynamic host decls to leases file.
Feb 11 09:57:00 router dhcpd: Wrote 9 leases to leases file.
Feb 11 09:57:00 router dhcpd: DHCPREQUEST for 192.168.1.17 (192.168.1.1) from 78:dd:08:xx:xx:xx (vaio) via em0
Feb 11 09:57:00 router dhcpd: DHCPACK on 192.168.1.17 to 78:dd:08:xx:xx:xx (vaio) via em0
Feb 11 09:57:00 router dhcpd: Request message from fe80::dc38:d6fa:xxx:xxx port 546, transaction ID 0x6B31FC00
Feb 11 09:57:00 router dhcpd: Sending Reply to fe80::dc38:d6fa:xxx:xxx port 546

      And yet again at 10:57:17:

      Feb 11 10:57:17	unbound: [16927:0] info: start of service (unbound 1.5.1).
Feb 11 10:57:17	unbound: [16927:0] notice: init module 1: iterator
Feb 11 10:57:17	unbound: [16927:0] notice: init module 0: validator
Feb 11 10:57:17	unbound: [16927:0] notice: Restart of unbound 1.5.1.
Feb 11 10:57:17	unbound: [16927:0] info: 2.000000 4.000000 1
Feb 11 10:57:17	unbound: [16927:0] info: 1.000000 2.000000 1
Feb 11 10:57:17	unbound: [16927:0] info: 0.524288 1.000000 4
Feb 11 10:57:17	unbound: [16927:0] info: 0.262144 0.524288 8
Feb 11 10:57:17	unbound: [16927:0] info: 0.131072 0.262144 9
Feb 11 10:57:17	unbound: [16927:0] info: 0.065536 0.131072 12
Feb 11 10:57:17	unbound: [16927:0] info: 0.032768 0.065536 23
Feb 11 10:57:17	unbound: [16927:0] info: 0.016384 0.032768 43
Feb 11 10:57:17	unbound: [16927:0] info: 0.008192 0.016384 41
Feb 11 10:57:17	unbound: [16927:0] info: 0.004096 0.008192 57
Feb 11 10:57:17	unbound: [16927:0] info: 0.002048 0.004096 43
Feb 11 10:57:17	unbound: [16927:0] info: 0.001024 0.002048 9
Feb 11 10:57:17	unbound: [16927:0] info: 0.000512 0.001024 1
Feb 11 10:57:17	unbound: [16927:0] info: 0.000000 0.000001 19
Feb 11 10:57:17	unbound: [16927:0] info: lower(secs) upper(secs) recursions
Feb 11 10:57:17	unbound: [16927:0] info: [25%]=0.00389358 median[50%]=0.00949073 [75%]=0.029053
Feb 11 10:57:17	unbound: [16927:0] info: histogram of recursion processing times
Feb 11 10:57:17	unbound: [16927:0] info: average recursion processing time 0.054781 sec
Feb 11 10:57:17	unbound: [16927:0] info: server stats for thread 1: requestlist max 4 avg 0.231618 exceeded 0 jostled 0
Feb 11 10:57:17	unbound: [16927:0] info: server stats for thread 1: 329 queries, 57 answers from cache, 272 recursions, 0 prefetch
Feb 11 10:57:17	unbound: [16927:0] info: 1.000000 2.000000 2
Feb 11 10:57:17	unbound: [16927:0] info: 0.524288 1.000000 9
Feb 11 10:57:17	unbound: [16927:0] info: 0.262144 0.524288 19
Feb 11 10:57:17	unbound: [16927:0] info: 0.131072 0.262144 23
Feb 11 10:57:17	unbound: [16927:0] info: 0.065536 0.131072 24
Feb 11 10:57:17	unbound: [16927:0] info: 0.032768 0.065536 44
Feb 11 10:57:17	unbound: [16927:0] info: 0.016384 0.032768 68
Feb 11 10:57:17	unbound: [16927:0] info: 0.008192 0.016384 66
Feb 11 10:57:17	unbound: [16927:0] info: 0.004096 0.008192 95
Feb 11 10:57:17	unbound: [16927:0] info: 0.002048 0.004096 45
Feb 11 10:57:17	unbound: [16927:0] info: 0.001024 0.002048 12
Feb 11 10:57:17	unbound: [16927:0] info: 0.000512 0.001024 1
Feb 11 10:57:17	unbound: [16927:0] info: 0.000000 0.000001 20
Feb 11 10:57:17	unbound: [16927:0] info: lower(secs) upper(secs) recursions
Feb 11 10:57:17	unbound: [16927:0] info: [25%]=0.00534636 median[50%]=0.013281 [75%]=0.0431942
Feb 11 10:57:17	unbound: [16927:0] info: histogram of recursion processing times
Feb 11 10:57:17	unbound: [16927:0] info: average recursion processing time 0.066407 sec
Feb 11 10:57:17	unbound: [16927:0] info: server stats for thread 0: requestlist max 4 avg 0.441589 exceeded 0 jostled 0
Feb 11 10:57:17	unbound: [16927:0] info: server stats for thread 0: 516 queries, 88 answers from cache, 428 recursions, 0 prefetch
Feb 11 10:57:17	unbound: [16927:0] info: service stopped (unbound 1.5.1).

      DHCP logs:

      Feb 11 10:57:17	dhcpd: Sending Reply to fe80::1863:4b13:xxxx:xxxx port 546
Feb 11 10:57:17	dhcpd: Confirm message from fe80::1863:4b13:xxxx:xxxx port 546, transaction ID 0x51830100
Feb 11 10:57:17	dhcpd: DHCPACK on 192.168.1.12 to 78:7e:61:xx:xx:xx (Anamas-iPhone) via em0
Feb 11 10:57:17	dhcpd: DHCPREQUEST for 192.168.1.12 from 78:7e:61:xx:xx:xx (Anamas-iPhone) via em0
Feb 11 10:57:17	dhcpd: Wrote 9 leases to leases file.
Feb 11 10:57:17	dhcpd: Wrote 0 new dynamic host decls to leases file.
Feb 11 10:57:17	dhcpd: Wrote 0 deleted host decls to leases file.

      The problem with making something idiot proof is that the world keeps making better idiots.

      1 Reply Last reply Reply Quote 0
      • P
        phil.davis
        last edited by

        Do you have a cron job rc.backup_dhcpleases.sh that is running every hour?

        It must be over-enthusiastic and restart unbound when the lease file is written. Perhaps it can just send unbound a message? Or perhaps it does not need to tell unbound anything - unbound should already be getting DHCP lease data on-the-fly as it happens?

        As the Greek philosopher Isosceles used to say, "There are 3 sides to every triangle."
        If I helped you, then help someone else - buy someone a gift from the INF catalog http://secure.inf.org/gifts/usd/

        1 Reply Last reply Reply Quote 0
        • I
          Inq
          last edited by

          Nope…

          $ crontab -l
          crontab: no crontab for root

          The problem with making something idiot proof is that the world keeps making better idiots.

          1 Reply Last reply Reply Quote 0
          • P
            phil.davis
            last edited by 

            crontab -l

            That does not work for me either.

            cat /etc/crontab

            and see what is there.
            Or instal the Cron package and you an see the cron jobs in the webGUI.

            As the Greek philosopher Isosceles used to say, "There are 3 sides to every triangle."
            If I helped you, then help someone else - buy someone a gift from the INF catalog http://secure.inf.org/gifts/usd/

            1 Reply Last reply Reply Quote 0
            • I
              Inq
              last edited by

              $ cat /etc/crontab
              SHELL=/bin/sh
              PATH=/etc:/bin:/sbin:/usr/bin:/usr/sbin
              HOME=/var/log
              #minute hour    mday    month  wday    who      command

              pfSense specific crontab entries

              Created: February 8, 2015, 6:13 pm

              1,31 0-5 * * * root /usr/bin/nice -n20 adjkerntz -a
              1 3 1 * * root /usr/bin/nice -n20 /etc/rc.update_bogons.sh
              */60 * * * * root /usr/bin/nice -n20 /usr/local/sbin/expiretable -v -t 3600 sshlockout
              1 1 * * * root /usr/bin/nice -n20 /etc/rc.dyndns.update
              */60 * * * * root /usr/bin/nice -n20 /usr/local/sbin/expiretable -v -t 3600 virusprot
              30 12 * * * root /usr/bin/nice -n20 /etc/rc.update_urltables
              */60 * * * * root /usr/bin/nice -n20 /usr/local/sbin/expiretable -v -t 3600 webConfiguratorlockout

              If possible do not add items to this file manually.

              If you do so, this file must be terminated with a blank line (e.g. new line)

              The problem with making something idiot proof is that the world keeps making better idiots.

              1 Reply Last reply Reply Quote 0
              • M
                macboy6
                last edited by

                I am going to have to assume this is the intended behaviour at this point.  It doesn't cause any adverse effects for me.

                I do have the OpenVPN client configured (in case this is somehow interacting with unbound) but it is constantly connected and not restarting.

                Would be nice to get confirmation from one of the developers though…

                1 Reply Last reply Reply Quote 0
                • K
                  kejianshi
                  last edited by

                  No - Its not intentional (Unless mine is broken.  Unbound has been running without service restart for a week)

                  1 Reply Last reply Reply Quote 0
                  • H
                    hda
                    last edited by

                    @macboy6:

                    While troubleshooting another issue, I discovered frequent restarts (every hour) in the unbound log.  Is this normal or is something wrong?

                    Related to your ISP lease renewal ? Status: System logs: General:
                    …
                    () check_reload_status: Starting packages
                    () php-fpm[34310]: /rc.start_packages: Restarting/Starting all packages.
                    …

                    1 Reply Last reply Reply Quote 0
                    • M
                      macboy6
                      last edited by

                      Nope, nothing correlates in system logs.  I do have Dynamic DNS setup though but that only updates once per day, so doubt it's related.

                      Cron jobs output:

                      SHELL=/bin/sh
                      PATH=/etc:/bin:/sbin:/usr/bin:/usr/sbin
                      HOME=/var/log
                      #minute hour    mday    month  wday    who      command

                      pfSense specific crontab entries

                      Created: February 7, 2015, 8:05 pm

                      1,31 0-5 * * * root /usr/bin/nice -n20 adjkerntz -a
                      1 3 1 * * root /usr/bin/nice -n20 /etc/rc.update_bogons.sh
                      */60 * * * * root /usr/bin/nice -n20 /usr/local/sbin/expiretable -v -t 3600 sshlockout
                      */60 * * * * root /usr/bin/nice -n20 /usr/local/sbin/expiretable -v -t 3600 webConfiguratorlockout
                      1 1 * * * root /usr/bin/nice -n20 /etc/rc.dyndns.update
                      */60 * * * * root /usr/bin/nice -n20 /usr/local/sbin/expiretable -v -t 3600 virusprot
                      30 12 * * * root /usr/bin/nice -n20 /etc/rc.update_urltables

                      If possible do not add items to this file manually.

                      If you do so, this file must be terminated with a blank line (e.g. new line)

                      1 Reply Last reply Reply Quote 0
                      • I
                        Inq
                        last edited by

                        One thing is clear in my case : Every time the dhcp service writes leases to leases file the unbound service restarts…every single time.

                        The problem with making something idiot proof is that the world keeps making better idiots.

                        1 Reply Last reply Reply Quote 0
                        • M
                          macboy6
                          last edited by

                          Inq - I just noticed that one of my network devices (Apple TV) was going crazy asking for dhcp every few seconds.  I did a clean install of 2.2 and didnt reboot some of my devices, which probably caused this issue.

                          I am now thinking that this issue could have been causing the frequent unbound resets.  I will monitor and update this thread.

                          Thanks,
                          Marco

                          1 Reply Last reply Reply Quote 0
                          • K
                            kejianshi
                            last edited by

                            It would be interesting and probably helpful to see your DHCP server setting and your unbound settings.

                            1 Reply Last reply Reply Quote 0
                            • M
                              macboy6
                              last edited by

                              Ok, this issue was definitely caused by a misconfiguration on my Apple TV (connected to both wired and wireless simultaneously).  This was causing the Apple TV to get stuck in a DHCP request loop (verified by DHCP logs).

                              In addition, I have the following setting in Unbound: Register DHCP leases in the DNS Resolver

                              Since I corrected the Apple TV issue, the hourly unbound restarts have stopped.

                              Thanks,
                              Marco

                              1 Reply Last reply Reply Quote 0
                              • K
                                kejianshi
                                last edited by

                                Sounds like something I see lots of people doing with laptops.  Plugging in wired while wireless is still on.  Same with IP Cams.

                                1 Reply Last reply Reply Quote 0
                                • W
                                  wbond
                                  last edited by

                                  @Inq:

                                  One thing is clear in my case : Every time the dhcp service writes leases to leases file the unbound service restarts…every single time.

                                  I noticed the same thing the other day, unbound restarting every time the dhcp service wrote the leases file, about once an hour.  It hadn't been doing this until I changed the setting for "unwanted reply threshold" in the dns resolver advanced settings from disabled to 10 million.  I changed it back to disabled yesterday and unbound has not restarted since.  No idea what the relationship is, but there seems to be one.

                                  edit: nevermind, changed another setting in dns resolver and now unbound is restarting at the same time the dhcp service writes the leases file again…

                                  1 Reply Last reply Reply Quote 0
                                  • K
                                    kevindd992002
                                    last edited by

                                    I'm experiencing the same problem with Unbound. Does this mean that it's normal for it to restart if the option to "Register DHCP leases in the DNS Resolver" is enabled?

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

                                      @wbond:

                                      edit: nevermind, changed another setting in dns resolver and now unbound is restarting at the same time the dhcp service writes the leases file again…

                                      I see the same thing: Unbound is restarting on every DHCPREQUEST - DHCPACK  sequence:
                                      Status: System logs: DHCP log:

                                      04-06-2015	09:49:36	Local7.Info	192.168.1.1	Apr  6 09:49:37 dhcpd: DHCPREQUEST for 192.168.2.235 from 78:3a:84:xx:34:1f (Philippes-Air) via sis0
04-06-2015	09:49:36	Local7.Info	192.168.1.1	Apr  6 09:49:37 dhcpd: DHCPACK on 192.168.2.235 to 78:3a:84:xx:34:1f (Philippes-Air) via sis0
04-06-2015	09:49:36	User.Info	192.168.1.1	Apr  6 09:49:37 dhcpleases: Sending HUP signal to dns daemon(53865)

                                      I guess, when "Sending HUP signal to dns daemon" is fired, Unbound restarts.
                                      At that moment, on the "Status: System logs: Resolver", I see (reversed time order):

                                      04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: start of service (unbound 1.5.3).
04-06-2015	09:52:08	Daemon.Notice	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] notice: init module 0: iterator
04-06-2015	09:52:08	Daemon.Notice	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] notice: Restart of unbound 1.5.3.
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.524288    1.000000 1
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.262144    0.524288 2
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.131072    0.262144 1
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: lower(secs) upper(secs) recursions
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: [25%]=0.262144 median[50%]=0.393216 [75%]=0.524288
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: histogram of recursion processing times
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: average recursion processing time 0.414164 sec
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: server stats for thread 1: requestlist max 4 avg 1 exceeded 0 jostled 0
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: server stats for thread 1: 4 queries, 0 answers from cache, 4 recursions, 0 prefetch
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.524288    1.000000 4
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.262144    0.524288 5
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.131072    0.262144 3
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.065536    0.131072 3
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.032768    0.065536 3
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info:    0.016384    0.032768 1
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: lower(secs) upper(secs) recursions
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: [25%]=0.08192 median[50%]=0.240299 [75%]=0.484966
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: histogram of recursion processing times
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: average recursion processing time 0.331678 sec
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: server stats for thread 0: requestlist max 28 avg 3.36842 exceeded 0 jostled 0
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: server stats for thread 0: 25 queries, 6 answers from cache, 19 recursions, 0 prefetch
04-06-2015	09:52:08	Daemon.Info	192.168.1.1	Apr  6 09:52:09 unbound: [53865:0] info: service stopped (unbound 1.5.3).

                                      This means that unbound restart several times per minute … is this normal ???
                                      Or is this what it is all about, the setting "DHCP Registration" on the "Services: DNS Resolver" page ?

                                      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 0
                                      • D
                                        doktornotor Banned
                                        last edited by

                                        @Gertjan:

                                        Or is this what it is all about, the setting "DHCP Registration" on the "Services: DNS Resolver" page ?
                                        This means that unbound restart several times per minute … is this normal ???

                                        No, it's not normal. And in general, the "wheeeeeeeee something might have changed (99% of cases absolutely nothing at all changed and apinger just went haywire as usual) so lets restart all services and packages" mentality that pfSense has grown is an absolute disaster. (Recently, someone finally nuked this nonsense on routing packages like OpenBGPD/Quagga where it was making them just completely no-op.)

                                        Example of this madness: https://redmine.pfsense.org/issues/4474

                                        1 Reply Last reply Reply Quote 0
                                        • C
                                          CiscoKid85
                                          last edited by

                                          I upgraded to 2.2.1 and this is still occurring very frequently for me.

                                          
Apr 7 18:46:45	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:46:45	unbound: [53511:0] info: service stopped (unbound 1.5.3).
Apr 7 18:36:50	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:36:50	unbound: [53511:0] info: service stopped (unbound 1.5.3).
Apr 7 18:31:39	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:31:39	unbound: [53511:0] info: service stopped (unbound 1.5.3).
Apr 7 18:26:56	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:26:56	unbound: [53511:0] info: service stopped (unbound 1.5.3).
Apr 7 18:21:31	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:21:31	unbound: [53511:0] info: service stopped (unbound 1.5.3).
Apr 7 18:17:00	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:17:00	unbound: [53511:0] info: service stopped (unbound 1.5.3).
Apr 7 18:10:10	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:10:09	unbound: [53511:0] info: service stopped (unbound 1.5.3).
Apr 7 18:09:23	unbound: [53511:0] info: start of service (unbound 1.5.3).
Apr 7 18:09:23	unbound: [53511:0] info: service stopped (unbound 1.5.3).
                                          1 Reply Last reply Reply Quote 0
                                          • B
                                            Barnabas
                                            last edited by

                                            I have been having this problem also.
                                            I first thought it was BandwidthD, but I removed and did not help.

                                            Apr 11 18:03:42 	unbound: [76411:0] info: service stopped (unbound 1.5.3).
Apr 11 18:03:42 	unbound: [76411:0] info: server stats for thread 0: 228 queries, 48 answers from cache, 180 recursions, 0 prefetch
Apr 11 18:03:42 	unbound: [76411:0] info: server stats for thread 0: requestlist max 20 avg 2.90556 exceeded 0 jostled 0
Apr 11 18:03:42 	unbound: [76411:0] info: average recursion processing time 0.291716 sec
Apr 11 18:03:42 	unbound: [76411:0] info: histogram of recursion processing times
Apr 11 18:03:42 	unbound: [76411:0] info: [25%]=0.107241 median[50%]=0.236444 [75%]=0.40778
Apr 11 18:03:42 	unbound: [76411:0] info: lower(secs) upper(secs) recursions
Apr 11 18:03:42 	unbound: [76411:0] info: 0.000000 0.000001 2
Apr 11 18:03:42 	unbound: [76411:0] info: 0.008192 0.016384 10
Apr 11 18:03:42 	unbound: [76411:0] info: 0.016384 0.032768 13
Apr 11 18:03:42 	unbound: [76411:0] info: 0.032768 0.065536 13
Apr 11 18:03:42 	unbound: [76411:0] info: 0.065536 0.131072 11
Apr 11 18:03:42 	unbound: [76411:0] info: 0.131072 0.262144 51
Apr 11 18:03:42 	unbound: [76411:0] info: 0.262144 0.524288 63
Apr 11 18:03:42 	unbound: [76411:0] info: 0.524288 1.000000 10
Apr 11 18:03:42 	unbound: [76411:0] info: 1.000000 2.000000 6
Apr 11 18:03:42 	unbound: [76411:0] info: 2.000000 4.000000 1
Apr 11 18:03:42 	unbound: [76411:0] notice: Restart of unbound 1.5.3.
Apr 11 18:03:42 	unbound: [76411:0] notice: init module 0: validator
Apr 11 18:03:42 	unbound: [76411:0] notice: init module 1: iterator
Apr 11 18:03:42 	unbound: [76411:0] info: start of service (unbound 1.5.3).
Apr 11 18:07:39 	unbound: [76411:0] info: service stopped (unbound 1.5.3).
Apr 11 18:07:39 	unbound: [76411:0] info: server stats for thread 0: 36 queries, 4 answers from cache, 32 recursions, 0 prefetch
Apr 11 18:07:39 	unbound: [76411:0] info: server stats for thread 0: requestlist max 14 avg 3.96875 exceeded 0 jostled 0
Apr 11 18:07:39 	unbound: [76411:0] info: average recursion processing time 0.224321 sec
Apr 11 18:07:39 	unbound: [76411:0] info: histogram of recursion processing times
Apr 11 18:07:39 	unbound: [76411:0] info: [25%]=0.104858 median[50%]=0.191567 [75%]=0.299593
Apr 11 18:07:39 	unbound: [76411:0] info: lower(secs) upper(secs) recursions
Apr 11 18:07:39 	unbound: [76411:0] info: 0.008192 0.016384 1
Apr 11 18:07:39 	unbound: [76411:0] info: 0.016384 0.032768 2
Apr 11 18:07:39 	unbound: [76411:0] info: 0.032768 0.065536 2
Apr 11 18:07:39 	unbound: [76411:0] info: 0.065536 0.131072 5
Apr 11 18:07:39 	unbound: [76411:0] info: 0.131072 0.262144 13
Apr 11 18:07:39 	unbound: [76411:0] info: 0.262144 0.524288 7
Apr 11 18:07:39 	unbound: [76411:0] info: 0.524288 1.000000 1
Apr 11 18:07:39 	unbound: [76411:0] info: 1.000000 2.000000 1
Apr 11 18:07:39 	unbound: [76411:0] notice: Restart of unbound 1.5.3.
Apr 11 18:07:39 	unbound: [76411:0] notice: init module 0: validator
Apr 11 18:07:39 	unbound: [76411:0] notice: init module 1: iterator
Apr 11 18:07:39 	unbound: [76411:0] info: start of service (unbound 1.5.3).

                                            Any clues?

                                            1 Reply Last reply Reply Quote 0
                                            • First post
                                              Last post
                                            Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.