Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login
    Introducing Netgate Nexus: Multi-Instance Management at Your Fingertips.

    Issue with Netgate - routing issue and device not rebooting

    Scheduled Pinned Locked Moved Routing and Multi WAN
    30 Posts 3 Posters 9.8k Views 4 Watching
    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.
    • G Offline
      GeorgeCZ58 @stephenw10
      last edited by

      @stephenw10 I enable if pppoe this morning. After some hours oruter start to have again problems. In PPP log I see:
      Jun 30 13:21:41 kernel if_pppoe: pppoe0: LCP keepalive timeout
      Jun 30 11:54:54 kernel if_pppoe: pppoe0: LCP keepalive timeout

      I have internet connection, but it looks like DNS resolver doesnt work properly.

      there is plenty info, coppied just initial when it fails:
      Jun 30 11:55:04 unbound 16401 [16401:0] info: [25%]=0.0231366 median[50%]=0.0681366 [75%]=0.114792
      Jun 30 11:55:04 unbound 16401 [16401:0] info: histogram of recursion processing times
      Jun 30 11:55:04 unbound 16401 [16401:0] info: average recursion processing time 0.087892 sec
      Jun 30 11:55:04 unbound 16401 [16401:0] info: server stats for thread 0: requestlist max 16 avg 0.298002 exceeded 0 jostled 0
      Jun 30 11:55:04 unbound 16401 [16401:0] info: server stats for thread 0: 3083 queries, 1281 answers from cache, 1802 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Jun 30 11:55:04 unbound 16401 [16401:0] info: service stopped (unbound 1.25.1).

      1 Reply Last reply Reply Quote 0
      • stephenw10S Offline
        stephenw10 Netgate Administrator
        last edited by

        Ok so using both pppoe drivers the upstream server stops responding to the LCP messages after sometime causing the link to be brought down. That's not normal. A pppoe server should always respond to that. But in the logs you sent this morning the connection reconnects after that.

        There are also reconnections shown like this:

        Jun 29 13:25:46 route ppp[53592]: [wan] IFACE: Add description "WAN"
Jun 29 13:30:26 route ppp[57164]: Multi-link PPP daemon for FreeBSD
Jun 29 13:30:26 route ppp[57164]:  
Jun 29 13:30:26 route ppp[57164]: process 57164 started, version 5.9
Jun 29 13:30:26 route ppp[57164]: web: web is not running
Jun 29 13:30:26 route ppp[57164]: [wan] Bundle: Interface ng0 created
Jun 29 13:30:26 route ppp[57164]: [undefined] GetSystemIfaceMTU: SIOCGIFMTU failed: Device not configured
Jun 29 13:30:26 route ppp[57164]: [wan_link0] Link: OPEN event
Jun 29 13:30:26 route ppp[57164]: [wan_link0] LCP: Open event
Jun 29 13:30:26 route ppp[57164]: [wan_link0] LCP: state change Initial --> Starting
Jun 29 13:30:26 route ppp[57164]: [wan_link0] LCP: LayerStart

        There it looks like mpd5 was restarted for some reason. That might be shown in the main log.

        That output from Unbound is just what it shows when it shuts down or restarts. So, again, something is probably restarting it. A lot of things restart Unbound but if it's happening a lot it's usually because DHCP client registration is enabled.

        There isn't some general issue with PPoE though. At least as far as I know. I have two WAN connections here, they are both PPPoE. I see no significant issues, they usually stay up for months at a time.

        1 Reply Last reply Reply Quote 0
        • G Offline
          GeorgeCZ58
          last edited by

          It happened again, even I disabled pfblocker ng. Unbound is probably not able to start then.

          Jun 30 18:18:50 php-fpm 34595 NOTICE The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1782836330] unbound[82000:0] warning: setsockopt(..., SO_SNDBUF, ...) was not granted: No buffer space available [1782836330] unbound[82000:0] warning: so-sndbuf 4194304 was not granted. Got 57344. To fix: start with root permissions(linux) or sysctl bigger net.core.wmem_max(linux) or kern.ipc.maxsockbuf(bsd) values. or set so-sndbuf: 0 (use system value). [1782836330] unbound[82000:0] error: bind: address already in use [1782836330] unbound[82000:0] fatal error: could not open ports'

          stephenw10S 1 Reply Last reply Reply Quote 0
          • stephenw10S Offline
            stephenw10 Netgate Administrator @GeorgeCZ58
            last edited by

            @GeorgeCZ58 said in Issue with Netgate - routing issue and device not rebooting:

            [1782836330] unbound[82000:0] error: bind: address already in use
            [1782836330] unbound[82000:0] fatal error: could not open ports

            Hmm, do you have something else listening on port 53? Or Unbound listening on some other port?

            Or perhaps there were two instances of Unbound running at that point?

            1 Reply Last reply Reply Quote 0
            • G Offline
              GeorgeCZ58
              last edited by

              I completely uninstalled pfblocker. This is log from time now, when issue osccured in night. Resulting in unbound not runing.

              Jul 1 02:41:11 usbhid-ups 81361 You may want to set 'pollonly' flag on CPS devices
              Jul 1 02:41:11 upsd 81217 Can't connect to UPS [CyberPower] (/var/db/nut/usbhid-ups-CyberPower): Connection refused
              Jul 1 02:41:09 kernel igb2.33: promiscuous mode enabled
              Jul 1 02:41:09 kernel igb2.232: promiscuous mode enabled
              Jul 1 02:41:08 kernel igb2.600: promiscuous mode enabled
              Jul 1 02:41:08 kernel igb2.231: promiscuous mode enabled
              Jul 1 02:41:08 kernel igb2.230: promiscuous mode enabled
              Jul 1 02:41:08 kernel igb2.34: promiscuous mode enabled
              Jul 1 02:41:08 kernel igb3: promiscuous mode enabled
              Jul 1 02:41:08 kernel igb2: promiscuous mode enabled
              Jul 1 02:41:08 usbhid-ups 74299 You may want to set 'pollonly' flag on CPS devices
              Jul 1 02:41:08 upsd 74225 Can't connect to UPS [CyberPower] (/var/db/nut/usbhid-ups-CyberPower): No such file or directory
              Jul 1 02:41:08 upsd 45651 mainloop: Interrupted system call
              Jul 1 02:41:07 radiusd 63742 Ignoring "ldap" (see raddb/mods-available/README.rst)
              Jul 1 02:41:07 radiusd 63742 Ignoring "sql" (see raddb/mods-available/README.rst)
              Jul 1 02:41:07 radiusd 63742 tls: In order to use TLS 1.0 and/or TLS 1.1, you likely need to set: cipher_list = "DEFAULT@SECLEVEL=0"
              Jul 1 02:41:05 kernel igb2.33: promiscuous mode disabled
              Jul 1 02:41:05 kernel igb2: promiscuous mode disabled
              Jul 1 02:41:05 kernel igb3: promiscuous mode disabled
              Jul 1 02:41:05 kernel igb2.34: promiscuous mode disabled
              Jul 1 02:41:05 kernel igb2.600: promiscuous mode disabled
              Jul 1 02:41:05 kernel igb2.232: promiscuous mode disabled
              Jul 1 02:41:05 kernel igb2.231: promiscuous mode disabled
              Jul 1 02:41:05 kernel igb2.230: promiscuous mode disabled
              Jul 1 02:41:04 check_reload_status 662 Reloading filter
              Jul 1 02:41:04 check_reload_status 662 Reloading filter
              Jul 1 02:41:04 check_reload_status 662 Starting packages
              Jul 1 02:41:04 php-fpm 84505 NOTICE Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 172.16.12.1 -> 172.16.12.1 - Restarting packages.
              Jul 1 02:41:01 php-fpm 84505 NOTICE The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1782866461] unbound[82251:0] warning: setsockopt(..., SO_SNDBUF, ...) was not granted: No buffer space available [1782866461] unbound[82251:0] warning: so-sndbuf 4194304 was not granted. Got 57344. To fix: start with root permissions(linux) or sysctl bigger net.core.wmem_max(linux) or kern.ipc.maxsockbuf(bsd) values. or set so-sndbuf: 0 (use system value). [1782866461] unbound[82251:0] error: bind: address already in use [1782866461] unbound[82251:0] fatal error: could not open ports'
              Jul 1 02:40:51 usbhid-ups 45387 You may want to set 'pollonly' flag on CPS devices
              Jul 1 02:40:50 upsd 45158 Can't connect to UPS [CyberPower] (/var/db/nut/usbhid-ups-CyberPower): Connection refused
              Jul 1 02:40:50 php-fpm 69917 NOTICE Skipping STARTing packages process because previous/another instance is already running
              Jul 1 02:40:49 check_reload_status 662 Reloading filter
              Jul 1 02:40:49 check_reload_status 662 Reloading filter
              Jul 1 02:40:49 check_reload_status 662 Starting packages
              Jul 1 02:40:49 php-fpm 621 NOTICE Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 172.16.11.1 -> 172.16.11.1 - Restarting packages.
              Jul 1 02:40:48 usbhid-ups 10462 You may want to set 'pollonly' flag on CPS devices
              Jul 1 02:40:47 kernel igb2.33: promiscuous mode enabled
              Jul 1 02:40:47 upsd 10238 Can't connect to UPS [CyberPower] (/var/db/nut/usbhid-ups-CyberPower): No such file or directory
              Jul 1 02:40:47 kernel igb2.232: promiscuous mode enabled
              Jul 1 02:40:47 upsd 56837 mainloop: Interrupted system call
              Jul 1 02:40:47 kernel igb2.231: promiscuous mode enabled
              Jul 1 02:40:47 kernel igb2.230: promiscuous mode enabled
              Jul 1 02:40:47 kernel igb2.600: promiscuous mode enabled
              Jul 1 02:40:47 kernel igb2.34: promiscuous mode enabled
              Jul 1 02:40:47 kernel igb3: promiscuous mode enabled
              Jul 1 02:40:47 kernel igb2: promiscuous mode enabled
              Jul 1 02:40:45 radiusd 70137 Ignoring "ldap" (see raddb/mods-available/README.rst)
              Jul 1 02:40:45 radiusd 70137 Ignoring "sql" (see raddb/mods-available/README.rst)
              Jul 1 02:40:45 radiusd 70137 tls: In order to use TLS 1.0 and/or TLS 1.1, you likely need to set: cipher_list = "DEFAULT@SECLEVEL=0"
              Jul 1 02:40:44 kernel igb2.231: promiscuous mode disabled
              Jul 1 02:40:44 kernel igb2: promiscuous mode disabled
              Jul 1 02:40:44 kernel igb2.230: promiscuous mode disabled
              Jul 1 02:40:44 kernel igb2.33: promiscuous mode disabled
              Jul 1 02:40:44 kernel igb2.232: promiscuous mode disabled
              Jul 1 02:40:44 kernel igb3: promiscuous mode disabled
              Jul 1 02:40:44 kernel igb2.34: promiscuous mode disabled
              Jul 1 02:40:44 kernel igb2.600: promiscuous mode disabled
              Jul 1 02:40:42 check_reload_status 662 Reloading filter
              Jul 1 02:40:42 check_reload_status 662 Starting packages
              Jul 1 02:40:42 php-fpm 69917 NOTICE Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 18X.17X.1X.1XX -> 18X.17X.1X.1XX - Restarting packages.
              Jul 1 02:40:40 kernel ovpns2: link state changed to UP
              Jul 1 02:40:40 check_reload_status 662 rc.newwanip starting ovpns2
              Jul 1 02:40:40 check_reload_status 662 Reloading filter
              Jul 1 02:40:40 kernel ovpns2: link state changed to DOWN
              Jul 1 02:40:40 check_reload_status 662 Reloading filter
              Jul 1 02:40:38 kernel ovpns1: link state changed to UP
              Jul 1 02:40:38 check_reload_status 662 rc.newwanip starting ovpns1
              Jul 1 02:40:38 check_reload_status 662 Reloading filter
              Jul 1 02:40:37 kernel ovpns1: link state changed to DOWN
              Jul 1 02:40:37 check_reload_status 662 Reloading filter
              Jul 1 02:40:27 check_reload_status 662 rc.newwanip starting pppoe0
              Jul 1 02:40:21 php-fpm 621 NOTICE [OpenVPN] One or more OpenVPN tunnel endpoints may have changed IP addresses. Reloading endpoints that may use WAN_PPPOE.
              Jul 1 02:40:20 kernel pppoe: received PADO but could not find request for it
              Jul 1 02:40:20 kernel pppoe0: host unique tag found, but it belongs to a connection in state 3
              Jul 1 02:40:20 kernel pppoe0: link state changed to UP
              Jul 1 02:40:20 kernel pppoe: received PADO but could not find request for it
              Jul 1 02:40:20 kernel pppoe0: host unique tag found, but it belongs to a connection in state 3
              Jul 1 02:40:20 kernel pppoe0: link state changed to DOWN
              Jul 1 02:40:20 kernel if_pppoe: pppoe0: LCP keepalive timeout
              Jul 1 02:40:19 check_reload_status 662 Reloading filter
              Jul 1 02:40:19 check_reload_status 662 Restarting OpenVPN tunnels/interfaces
              Jul 1 02:40:19 check_reload_status 662 Restarting IPsec tunnels
              Jul 1 02:40:19 check_reload_status 662 updating dyndns WAN_PPPOE

              1 Reply Last reply Reply Quote 0
              • G Offline
                GeorgeCZ58
                last edited by

                In PPP log this occure and then unbound fails and sometimes also other services. But with if pppoe it looks like only unbound is failing. With old driver it was much more.

                Jul 1 02:40:20 kernel if_pppoe: pppoe0: LCP keepalive timeout
                Jun 30 21:36:30 kernel if_pppoe: pppoe0: LCP keepalive timeout
                Jun 30 18:18:23 kernel if_pppoe: pppoe0: LCP keepalive timeout
                Jun 30 13:21:41 kernel if_pppoe: pppoe0: LCP keepalive timeout
                Jun 30 11:54:54 kernel if_pppoe: pppoe0: LCP keepalive timeout

                So on one side there is probably ISP connection flapping, or different issues. On other side, why unbound fail to run? Why it did notresolve itself?

                1 Reply Last reply Reply Quote 0
                • G Offline
                  GeorgeCZ58
                  last edited by

                  I try to set MTU and MSS lower now, as it seems this wireless PPPOE conenction has fragmented packets when using MTU 1500. I set 1420/1380 and will see. But again this is second part of issue, main is, why unbound or other services are failing when connection starts to flap :-/.

                  1 Reply Last reply Reply Quote 0
                  • stephenw10S Offline
                    stephenw10 Netgate Administrator
                    last edited by

                    What are 172.16.12.1 and 172.16.11.1 on that system? pSense is seeing them as WAN connections, so VPN subnets perhaps? They are assigned interfaces?

                    G 1 Reply Last reply Reply Quote 0
                    • G Offline
                      GeorgeCZ58 @stephenw10
                      last edited by

                      @stephenw10 Those are OpenVPN interfaces. How it is possible that it is trying to act as wan?

                      1 Reply Last reply Reply Quote 0
                      • G Offline
                        GeorgeCZ58
                        last edited by

                        Again happened in 11 of our time, log from that time:

                        Jul 6 11:01:01 upsmon 72214 UPS CyberPower has no unclassified status tokens anymore
                        Jul 6 11:00:56 upsmon 72214 UPS CyberPower: has at least one unclassified status token: [WAIT]
                        Jul 6 11:00:55 usbhid-ups 66722 You may want to set 'pollonly' flag on CPS devices
                        Jul 6 11:00:55 upsd 66352 Can't connect to UPS [CyberPower] (/var/db/nut/usbhid-ups-CyberPower): Connection refused
                        Jul 6 11:00:55 upsmon 48337 upsmon parent: exiting (child exited)
                        Jul 6 11:00:55 php-fpm 91742 NOTICE Skipping STARTing packages process because previous/another instance is already running
                        Jul 6 11:00:54 check_reload_status 671 Reloading filter
                        Jul 6 11:00:54 check_reload_status 671 Reloading filter
                        Jul 6 11:00:54 check_reload_status 671 Starting packages
                        Jul 6 11:00:54 php-fpm 75020 NOTICE Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 172.16.12.1 -> 172.16.12.1 - Restarting packages.
                        Jul 6 11:00:53 upsmon 48642 UPS CyberPower: has at least one unclassified status token: [WAIT]
                        Jul 6 11:00:52 usbhid-ups 32948 You may want to set 'pollonly' flag on CPS devices
                        Jul 6 11:00:52 upsd 32701 Can't connect to UPS [CyberPower] (/var/db/nut/usbhid-ups-CyberPower): Connection refused
                        Jul 6 11:00:52 kernel igb2.33: promiscuous mode enabled
                        Jul 6 11:00:52 kernel igb2.232: promiscuous mode enabled
                        Jul 6 11:00:51 kernel igb2.231: promiscuous mode enabled
                        Jul 6 11:00:51 kernel igb2.230: promiscuous mode enabled
                        Jul 6 11:00:51 kernel igb2.600: promiscuous mode enabled
                        Jul 6 11:00:51 kernel igb2.34: promiscuous mode enabled
                        Jul 6 11:00:51 kernel igb3: promiscuous mode enabled
                        Jul 6 11:00:51 kernel igb2: promiscuous mode enabled
                        Jul 6 11:00:51 php-fpm 75020 NOTICE The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1783328451] unbound[11195:0] warning: setsockopt(..., SO_SNDBUF, ...) was not granted: No buffer space available [1783328451] unbound[11195:0] warning: so-sndbuf 4194304 was not granted. Got 57344. To fix: start with root permissions(linux) or sysctl bigger net.core.wmem_max(linux) or kern.ipc.maxsockbuf(bsd) values. or set so-sndbuf: 0 (use system value). [1783328451] unbound[11195:0] error: bind: address already in use [1783328451] unbound[11195:0] fatal error: could not open ports'
                        Jul 6 11:00:51 radiusd 7853 Ignoring "ldap" (see raddb/mods-available/README.rst)
                        Jul 6 11:00:51 radiusd 7853 Ignoring "sql" (see raddb/mods-available/README.rst)
                        Jul 6 11:00:51 radiusd 7853 tls: In order to use TLS 1.0 and/or TLS 1.1, you likely need to set: cipher_list = "DEFAULT@SECLEVEL=0"
                        Jul 6 11:00:49 upsmon 69502 Communications with UPS CyberPower lost
                        Jul 6 11:00:49 upsmon 69502 UPS [CyberPower]: connect failed: Connection failure: Connection refused
                        Jul 6 11:00:48 kernel igb2.600: promiscuous mode disabled
                        Jul 6 11:00:48 kernel igb2: promiscuous mode disabled
                        Jul 6 11:00:48 kernel igb2.232: promiscuous mode disabled
                        Jul 6 11:00:48 kernel igb2.230: promiscuous mode disabled
                        Jul 6 11:00:48 kernel igb2.33: promiscuous mode disabled
                        Jul 6 11:00:48 kernel igb3: promiscuous mode disabled
                        Jul 6 11:00:48 kernel igb2.231: promiscuous mode disabled
                        Jul 6 11:00:48 kernel igb2.34: promiscuous mode disabled
                        Jul 6 11:00:48 upsmon 37370 upsmon parent: exiting (child exited)
                        Jul 6 11:00:47 check_reload_status 671 Reloading filter
                        Jul 6 11:00:47 check_reload_status 671 Reloading filter
                        Jul 6 11:00:47 check_reload_status 671 Starting packages
                        Jul 6 11:00:47 php-fpm 91742 NOTICE Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 172.16.11.1 -> 172.16.11.1 - Restarting packages.
                        Jul 6 11:00:46 upsmon 37706 UPS CyberPower: has at least one unclassified status token: [WAIT]
                        Jul 6 11:00:45 usbhid-ups 17160 You may want to set 'pollonly' flag on CPS devices
                        Jul 6 11:00:45 upsd 16790 Can't connect to UPS [CyberPower] (/var/db/nut/usbhid-ups-CyberPower): No such file or directory
                        Jul 6 11:00:45 upsd 77852 mainloop: Interrupted system call
                        Jul 6 11:00:45 kernel igb2.232: promiscuous mode enabled
                        Jul 6 11:00:45 kernel igb2.33: promiscuous mode enabled
                        Jul 6 11:00:44 kernel igb2.231: promiscuous mode enabled
                        Jul 6 11:00:44 kernel igb2.600: promiscuous mode enabled
                        Jul 6 11:00:44 kernel igb2.230: promiscuous mode enabled
                        Jul 6 11:00:44 kernel igb2.34: promiscuous mode enabled
                        Jul 6 11:00:44 kernel igb3: promiscuous mode enabled
                        Jul 6 11:00:44 kernel igb2: promiscuous mode enabled
                        Jul 6 11:00:43 radiusd 69899 Ignoring "ldap" (see raddb/mods-available/README.rst)
                        Jul 6 11:00:43 radiusd 69899 Ignoring "sql" (see raddb/mods-available/README.rst)
                        Jul 6 11:00:43 radiusd 69899 tls: In order to use TLS 1.0 and/or TLS 1.1, you likely need to set: cipher_list = "DEFAULT@SECLEVEL=0"
                        Jul 6 11:00:41 kernel igb2: promiscuous mode disabled
                        Jul 6 11:00:41 kernel igb2.600: promiscuous mode disabled
                        Jul 6 11:00:41 kernel igb3: promiscuous mode disabled
                        Jul 6 11:00:41 kernel igb2.33: promiscuous mode disabled
                        Jul 6 11:00:41 kernel igb2.232: promiscuous mode disabled
                        Jul 6 11:00:41 kernel igb2.34: promiscuous mode disabled
                        Jul 6 11:00:41 kernel igb2.231: promiscuous mode disabled
                        Jul 6 11:00:41 kernel igb2.230: promiscuous mode disabled
                        Jul 6 11:00:40 check_reload_status 671 Reloading filter
                        Jul 6 11:00:40 check_reload_status 671 Starting packages
                        Jul 6 11:00:40 php-fpm 630 NOTICE Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 185.X.X.X -> 185.X.X.X - Restarting packages.
                        Jul 6 11:00:38 check_reload_status 671 rc.newwanip starting ovpns2
                        Jul 6 11:00:38 kernel ovpns2: link state changed to UP
                        Jul 6 11:00:37 check_reload_status 671 Reloading filter
                        Jul 6 11:00:37 kernel ovpns2: link state changed to DOWN
                        Jul 6 11:00:37 check_reload_status 671 Reloading filter
                        Jul 6 11:00:35 kernel ovpns1: link state changed to UP
                        Jul 6 11:00:35 check_reload_status 671 rc.newwanip starting ovpns1
                        Jul 6 11:00:35 check_reload_status 671 Reloading filter
                        Jul 6 11:00:35 kernel ovpns1: link state changed to DOWN
                        Jul 6 11:00:35 check_reload_status 671 Reloading filter
                        Jul 6 11:00:26 check_reload_status 671 rc.newwanip starting pppoe0
                        Jul 6 11:00:20 kernel pppoe: received PADO but could not find request for it
                        Jul 6 11:00:20 kernel pppoe0: host unique tag found, but it belongs to a connection in state 3
                        Jul 6 11:00:20 kernel pppoe0: link state changed to UP
                        Jul 6 11:00:20 kernel pppoe: received PADO but could not find request for it
                        Jul 6 11:00:20 kernel pppoe0: host unique tag found, but it belongs to a connection in state 3
                        Jul 6 11:00:20 kernel pppoe0: link state changed to DOWN
                        Jul 6 11:00:20 kernel if_pppoe: pppoe0: LCP keepalive timeout

                        1 Reply Last reply Reply Quote 0
                        • First post
                          Last post
                        Copyright 2026 Rubicon Communications LLC (Netgate). All rights reserved.
                        Privacy Policy · Cookie Policy