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

    Unbound was killed: out of swap space

    Scheduled Pinned Locked Moved Official Netgate® Hardware
    unboundswapsg-1100
    12 Posts 5 Posters 4.9k 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.
    • L
      leonroy
      last edited by

      Saw this error today which brought down internet access.

      pid 18891 (unbound), jid 0, uid 59, was killed: out of swap space

      Running an SG-1100 - any info which can be used to debug the cause or is this a known issue?

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

        It's probably this: https://redmine.pfsense.org/issues/12095

        In 21.09 / 2.6 that will not run by default preventing that issue.

        You can apply patch here using the System Patches package against 21.05.1 to prevent it running there:
        https://redmine.pfsense.org/issues/11933#note-7

        Steve

        T H 2 Replies Last reply Reply Quote 3
        • T
          tman222 @stephenw10
          last edited by

          @stephenw10 said in Unbound was killed: out of swap space:

          It's probably this: https://redmine.pfsense.org/issues/12095

          In 21.09 / 2.6 that will not run by default preventing that issue.

          You can apply patch here using the System Patches package against 21.05.1 to prevent it running there:
          https://redmine.pfsense.org/issues/11933#note-7

          Steve

          Came across this thread and can firm there is definitely a memory leak issue with pcscd. After almost 40 day of uptime, I saw the process consuming ~4.5GB of memory on my system - wow!

          @stephenw10 - What's the recommended way forward? Can I just stop the pcscd service as I'm not using any PC/SC Smartcards? Or can the above linked patch be applied to 2.5.2 as well?

          Thanks in advance!

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

            The patch is better since it prevents it starting at all.
            Yes, it will apply against 2.5.2.

            Steve

            T 1 Reply Last reply Reply Quote 0
            • T
              tman222 @stephenw10
              last edited by

              @stephenw10 said in Unbound was killed: out of swap space:

              The patch is better since it prevents it starting at all.
              Yes, it will apply against 2.5.2.

              Steve

              Thanks @stephenw10 - applied the patch, rebooted and pcscd was no longer enabled / started. Quick question regarding the patch itself: Since the patch looks to be irreversible is it ok to now remove the entry for it from the System Patches package? Thanks again.

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

                You should be able to revert the patch if you really wanted to. I would leave it there until the next release with it included. If you had to reinstall 2.5.2 and restore your config you would want to re-apply it. It does no hard to leave it defined in the patches package.

                Steve

                1 Reply Last reply Reply Quote 0
                • H
                  hwinthe6 @stephenw10
                  last edited by

                  @stephenw10 said in Unbound was killed: out of swap space:

                  It's probably this: https://redmine.pfsense.org/issues/12095

                  In 21.09 / 2.6 that will not run by default preventing that issue.

                  You can apply patch here using the System Patches package against 21.05.1 to prevent it running there:
                  https://redmine.pfsense.org/issues/11933#note-7

                  Steve

                  Post still helping after all these months. Thank you.

                  L 1 Reply Last reply Reply Quote 2
                  • L
                    leonroy @hwinthe6
                    last edited by

                    On our 2.5.2 box it happened again today after 30 days of uptime.

                    840e2b5b-ea48-453b-a43a-20cd3f090e0d-image.png

                    Running the patch:
                    68dff88e-8a85-4381-84e6-ed9591efabd2-image.png

                    Unbound log:

                    Jan 11 13:01:49	unbound	63374	[63374:0] fatal error: Could not read config file: /unbound.conf. Maybe try unbound -dd, it stays on the commandline to see more errors, or unbound-checkconf
Jan 11 13:01:48	unbound	63374	[63374:0] notice: Restart of unbound 1.12.0.
Jan 11 13:01:48	unbound	63374	[63374:0] info: 1.000000 2.000000 1
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.262144 0.524288 2
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.131072 0.262144 2
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.065536 0.131072 2
Jan 11 13:01:48	unbound	63374	[63374:0] info: lower(secs) upper(secs) recursions
Jan 11 13:01:48	unbound	63374	[63374:0] info: [25%]=0.12288 median[50%]=0.229376 [75%]=0.425984
Jan 11 13:01:48	unbound	63374	[63374:0] info: histogram of recursion processing times
Jan 11 13:01:48	unbound	63374	[63374:0] info: average recursion processing time 0.433565 sec
Jan 11 13:01:48	unbound	63374	[63374:0] info: server stats for thread 3: requestlist max 1 avg 0.285714 exceeded 0 jostled 0
Jan 11 13:01:48	unbound	63374	[63374:0] info: server stats for thread 3: 7 queries, 0 answers from cache, 7 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.262144 0.524288 1
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.131072 0.262144 2
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.065536 0.131072 2
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.032768 0.065536 5
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.016384 0.032768 1
Jan 11 13:01:48	unbound	63374	[63374:0] info: lower(secs) upper(secs) recursions
Jan 11 13:01:48	unbound	63374	[63374:0] info: [25%]=0.0442368 median[50%]=0.0622592 [75%]=0.147456
Jan 11 13:01:48	unbound	63374	[63374:0] info: histogram of recursion processing times
Jan 11 13:01:48	unbound	63374	[63374:0] info: average recursion processing time 0.099147 sec
Jan 11 13:01:48	unbound	63374	[63374:0] info: server stats for thread 2: requestlist max 4 avg 0.363636 exceeded 0 jostled 0
Jan 11 13:01:48	unbound	63374	[63374:0] info: server stats for thread 2: 11 queries, 0 answers from cache, 11 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.065536 0.131072 1
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.032768 0.065536 1
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.016384 0.032768 3
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.008192 0.016384 1
Jan 11 13:01:48	unbound	63374	[63374:0] info: lower(secs) upper(secs) recursions
Jan 11 13:01:48	unbound	63374	[63374:0] info: [25%]=0.0191147 median[50%]=0.0273067 [75%]=0.049152
Jan 11 13:01:48	unbound	63374	[63374:0] info: histogram of recursion processing times
Jan 11 13:01:48	unbound	63374	[63374:0] info: average recursion processing time 0.042840 sec
Jan 11 13:01:48	unbound	63374	[63374:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Jan 11 13:01:48	unbound	63374	[63374:0] info: server stats for thread 1: 7 queries, 0 answers from cache, 7 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.262144 0.524288 2
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.032768 0.065536 3
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.016384 0.032768 1
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.008192 0.016384 1
Jan 11 13:01:48	unbound	63374	[63374:0] info: 0.000000 0.000001 1
Jan 11 13:01:48	unbound	63374	[63374:0] info: lower(secs) upper(secs) recursions
Jan 11 13:01:48	unbound	63374	[63374:0] info: [25%]=0.016384 median[50%]=0.0436907 [75%]=0.065536
Jan 11 13:01:48	unbound	63374	[63374:0] info: histogram of recursion processing times
Jan 11 13:01:48	unbound	63374	[63374:0] info: average recursion processing time 0.102872 sec
Jan 11 13:01:48	unbound	63374	[63374:0] info: server stats for thread 0: requestlist max 4 avg 0.5 exceeded 0 jostled 0
Jan 11 13:01:48	unbound	63374	[63374:0] info: server stats for thread 0: 8 queries, 0 answers from cache, 8 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Jan 11 13:01:48	unbound	63374	[63374:0] info: service stopped (unbound 1.12.0).
Jan 11 13:01:33	unbound	63374	[63374:3] info: generate keytag query _ta-4f66. NULL IN
Jan 11 13:01:33	unbound	63374	[63374:2] info: generate keytag query _ta-4f66. NULL IN
Jan 11 13:01:33	unbound	63374	[63374:0] info: start of service (unbound 1.12.0).
Jan 11 13:01:33	unbound	63374	[63374:0] notice: init module 1: iterator
Jan 11 13:01:33	unbound	63374	[63374:0] notice: init module 0: validator
Jan 11 13:01:33	unbound	63374	[63374:0] notice: Restart of unbound 1.12.0.
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.262144 0.524288 4
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.131072 0.262144 2
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.065536 0.131072 5
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.032768 0.065536 6
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.016384 0.032768 4
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.008192 0.016384 1
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.000000 0.000001 5
Jan 11 13:01:33	unbound	63374	[63374:0] info: lower(secs) upper(secs) recursions
Jan 11 13:01:33	unbound	63374	[63374:0] info: [25%]=0.019456 median[50%]=0.0518827 [75%]=0.121242
Jan 11 13:01:33	unbound	63374	[63374:0] info: histogram of recursion processing times
Jan 11 13:01:33	unbound	63374	[63374:0] info: average recursion processing time 0.098377 sec
Jan 11 13:01:33	unbound	63374	[63374:0] info: server stats for thread 3: requestlist max 31 avg 2.96296 exceeded 0 jostled 0
Jan 11 13:01:33	unbound	63374	[63374:0] info: server stats for thread 3: 36 queries, 9 answers from cache, 27 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Jan 11 13:01:33	unbound	63374	[63374:0] info: 1.000000 2.000000 1
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.262144 0.524288 1
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.131072 0.262144 1
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.065536 0.131072 2
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.032768 0.065536 2
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.016384 0.032768 2
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.004096 0.008192 1
Jan 11 13:01:33	unbound	63374	[63374:0] info: lower(secs) upper(secs) recursions
Jan 11 13:01:33	unbound	63374	[63374:0] info: [25%]=0.028672 median[50%]=0.065536 [75%]=0.196608
Jan 11 13:01:33	unbound	63374	[63374:0] info: histogram of recursion processing times
Jan 11 13:01:33	unbound	63374	[63374:0] info: average recursion processing time 0.178490 sec
Jan 11 13:01:33	unbound	63374	[63374:0] info: server stats for thread 2: requestlist max 5 avg 1.4 exceeded 0 jostled 0
Jan 11 13:01:33	unbound	63374	[63374:0] info: server stats for thread 2: 10 queries, 0 answers from cache, 10 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Jan 11 13:01:33	unbound	63374	[63374:0] info: 4.000000 8.000000 1
Jan 11 13:01:33	unbound	63374	[63374:0] info: 1.000000 2.000000 2
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.524288 1.000000 2
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.262144 0.524288 2
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.131072 0.262144 8
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.065536 0.131072 4
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.032768 0.065536 13
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.016384 0.032768 8
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.008192 0.016384 2
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.004096 0.008192 1
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.000000 0.000001 7
Jan 11 13:01:33	unbound	63374	[63374:0] info: lower(secs) upper(secs) recursions
Jan 11 13:01:33	unbound	63374	[63374:0] info: [25%]=0.021504 median[50%]=0.0504123 [75%]=0.172032
Jan 11 13:01:33	unbound	63374	[63374:0] info: histogram of recursion processing times
Jan 11 13:01:33	unbound	63374	[63374:0] info: average recursion processing time 0.289025 sec
Jan 11 13:01:33	unbound	63374	[63374:0] info: server stats for thread 1: requestlist max 25 avg 3.5 exceeded 0 jostled 0
Jan 11 13:01:33	unbound	63374	[63374:0] info: server stats for thread 1: 64 queries, 14 answers from cache, 50 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Jan 11 13:01:33	unbound	63374	[63374:0] info: 1.000000 2.000000 1
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.524288 1.000000 1
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.262144 0.524288 1
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.131072 0.262144 4
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.065536 0.131072 2
Jan 11 13:01:33	unbound	63374	[63374:0] info: 0.032768 0.065536 6

                    Any ideas (thanks)?

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

                      Was is out of RAM/SWAP? What do the monitoring graphs show? Anything in the main system log?

                      With that patch in place it wouldn't have been pcscd, unless it hadn't been rebooted since.

                      Steve

                      1 Reply Last reply Reply Quote 0
                      • L
                        leonroy
                        last edited by leonroy

                        @stephenw10

                        Monitoring graph shows 90% memory throughout the past day.

                        Screenshot 2022-01-11 at 23.22.00.png

                        Looking at the logs I realized I added a VLAN (January 10th) - the VLAN ID was 1300. I then renamed the VLAN, then deleted it. Could that have kicked off a memory leak?

                        Jan  9 00:16:05 gateway php-fpm[66698]: /index.php: Successful login for user 'admin' from: 10.1.0.100 (Local Database)
Jan  9 00:17:08 gateway check_reload_status[376]: Syncing firewall
Jan  9 00:17:08 gateway php-fpm[347]: /services_unbound.php: Beginning configuration backup to https://acb.netgate.com/save
Jan  9 00:17:16 gateway php-fpm[347]: /services_unbound.php: End of configuration backup to https://acb.netgate.com/save (success).
Jan  9 00:17:22 gateway dhcpleases[28105]: Could not deliver signal HUP to process 14032: No such process.
Jan  9 00:18:07 gateway check_reload_status[376]: Syncing firewall
Jan  9 00:18:07 gateway php-fpm[66698]: /services_unbound.php: Beginning configuration backup to https://acb.netgate.com/save
Jan  9 00:18:16 gateway php-fpm[66698]: /services_unbound.php: End of configuration backup to https://acb.netgate.com/save (success).
Jan  9 00:21:04 gateway dhcpleases[14803]: Could not deliver signal HUP to process 46897: No such process.
Jan 10 11:54:31 gateway kernel: arp: 10.0.0.196 moved from dc:3a:5e:33:d5:29 to dc:3a:5e:33:c5:29 on igb1
Jan 10 11:54:32 gateway kernel: arp: 10.0.0.196 moved from dc:3a:5e:33:c5:29 to dc:3a:5e:33:d5:29 on igb1
Jan 10 18:38:30 gateway kernel: arp: 10.1.0.136 moved from 00:1c:10:8d:10:57 to 00:04:13:8f:7a:1b on igb1.1100
Jan 10 18:50:33 gateway php-fpm[346]: /index.php: Session timed out for user 'admin' from: 10.1.0.100 (Local Database)
Jan 10 18:50:47 gateway php-fpm[346]: /index.php: Successful login for user 'admin' from: 10.1.0.100 (Local Database)
Jan 10 18:52:03 gateway kernel: vlan4: changing name to 'igb1.1300'
Jan 10 18:52:03 gateway check_reload_status[376]: Linkup starting igb1
Jan 10 18:52:03 gateway kernel: igb1: link state changed to DOWN
Jan 10 18:52:03 gateway kernel: igb1.1300: link state changed to DOWN
Jan 10 18:52:03 gateway kernel: igb1.113: link state changed to DOWN
Jan 10 18:52:03 gateway kernel: igb1.112: link state changed to DOWN
Jan 10 18:52:03 gateway kernel: igb1.110: link state changed to DOWN
Jan 10 18:52:03 gateway kernel: igb1.1100: link state changed to DOWN
Jan 10 18:52:03 gateway check_reload_status[376]: Linkup starting igb1.1300
Jan 10 18:52:03 gateway check_reload_status[376]: Linkup starting igb1.113
Jan 10 18:52:03 gateway check_reload_status[376]: Linkup starting igb1.112
Jan 10 18:52:03 gateway check_reload_status[376]: Linkup starting igb1.110
Jan 10 18:52:03 gateway check_reload_status[376]: Linkup starting igb1.1100
Jan 10 18:52:03 gateway check_reload_status[376]: Syncing firewall
Jan 10 18:52:03 gateway php-fpm[347]: /interfaces_vlan_edit.php: Beginning configuration backup to https://acb.netgate.com/save
Jan 10 18:52:04 gateway php-fpm[346]: /rc.linkup: Hotplug event detected for LAN(lan) static IP (10.0.0.1 )
Jan 10 18:52:04 gateway check_reload_status[376]: Reloading filter
Jan 10 18:52:04 gateway php-fpm[66698]: /rc.linkup: Hotplug event detected for DMZ(opt4) static IP (10.0.8.1 )
Jan 10 18:52:04 gateway check_reload_status[376]: Reloading filter
Jan 10 18:52:04 gateway php-fpm[346]: /rc.linkup: Hotplug event detected for MANAGEMENT(opt1) static IP (10.0.7.1 )
Jan 10 18:52:04 gateway php-fpm[66698]: /rc.linkup: Hotplug event detected for VOICE(opt2) static IP (10.0.5.1 )
Jan 10 18:52:04 gateway php-fpm[346]: /rc.linkup: Hotplug event detected for AIR(opt3) static IP (10.1.0.1 )
Jan 10 18:52:07 gateway check_reload_status[376]: Linkup starting igb1
Jan 10 18:52:07 gateway kernel: igb1: link state changed to UP
Jan 10 18:52:07 gateway kernel: igb1.1300: link state changed to UP
Jan 10 18:52:07 gateway kernel: igb1.113: link state changed to UP
Jan 10 18:52:07 gateway kernel: igb1.112: link state changed to UP
Jan 10 18:52:07 gateway kernel: igb1.110: link state changed to UP
Jan 10 18:52:07 gateway kernel: igb1.1100: link state changed to UP
Jan 10 18:52:07 gateway check_reload_status[376]: Linkup starting igb1.1300
Jan 10 18:52:07 gateway check_reload_status[376]: Linkup starting igb1.113
Jan 10 18:52:07 gateway check_reload_status[376]: Linkup starting igb1.112
Jan 10 18:52:07 gateway check_reload_status[376]: Linkup starting igb1.110
Jan 10 18:52:07 gateway check_reload_status[376]: Linkup starting igb1.1100
Jan 10 18:52:08 gateway check_reload_status[376]: Reloading filter
Jan 10 18:52:08 gateway php-fpm[55973]: /rc.linkup: Hotplug event detected for LAN(lan) static IP (10.0.0.1 )
Jan 10 18:52:08 gateway php-fpm[346]: /rc.linkup: Hotplug event detected for DMZ(opt4) static IP (10.0.8.1 )
Jan 10 18:52:08 gateway check_reload_status[376]: rc.newwanip starting igb1
Jan 10 18:52:08 gateway check_reload_status[376]: rc.newwanip starting igb1.113
Jan 10 18:52:08 gateway php-fpm[55973]: /rc.linkup: Hotplug event detected for MANAGEMENT(opt1) static IP (10.0.7.1 )
Jan 10 18:52:08 gateway php-fpm[346]: /rc.linkup: Hotplug event detected for VOICE(opt2) static IP (10.0.5.1 )
Jan 10 18:52:08 gateway check_reload_status[376]: rc.newwanip starting igb1.112
Jan 10 18:52:08 gateway php-fpm[55973]: /rc.linkup: Hotplug event detected for AIR(opt3) static IP (10.1.0.1 )
Jan 10 18:52:08 gateway check_reload_status[376]: rc.newwanip starting igb1.110
Jan 10 18:52:08 gateway check_reload_status[376]: rc.newwanip starting igb1.1100
Jan 10 18:52:09 gateway php-fpm[66698]: /rc.newwanip: rc.newwanip: Info: starting on igb1.113.
Jan 10 18:52:09 gateway php-fpm[346]: /rc.newwanip: rc.newwanip: Info: starting on igb1.
Jan 10 18:52:09 gateway php-fpm[66698]: /rc.newwanip: rc.newwanip: on (IP address: 10.0.8.1) (interface: DMZ[opt4]) (real interface: igb1.113).
Jan 10 18:52:09 gateway php-fpm[346]: /rc.newwanip: rc.newwanip: on (IP address: 10.0.0.1) (interface: LAN[lan]) (real interface: igb1).
Jan 10 18:52:09 gateway check_reload_status[376]: Reloading filter
Jan 10 18:52:09 gateway php-fpm[66698]: /rc.newwanip: rc.newwanip: Info: starting on igb1.112.
Jan 10 18:52:09 gateway php-fpm[66698]: /rc.newwanip: rc.newwanip: on (IP address: 10.0.7.1) (interface: MANAGEMENT[opt1]) (real interface: igb1.112).
Jan 10 18:52:09 gateway php-fpm[346]: /rc.newwanip: rc.newwanip: Info: starting on igb1.110.
Jan 10 18:52:09 gateway php-fpm[346]: /rc.newwanip: rc.newwanip: on (IP address: 10.0.5.1) (interface: VOICE[opt2]) (real interface: igb1.110).
Jan 10 18:52:09 gateway php-fpm[66698]: /rc.newwanip: rc.newwanip: Info: starting on igb1.1100.
Jan 10 18:52:09 gateway php-fpm[66698]: /rc.newwanip: rc.newwanip: on (IP address: 10.1.0.1) (interface: AIR[opt3]) (real interface: igb1.1100).
Jan 10 18:52:11 gateway php-fpm[347]: /interfaces_vlan_edit.php: End of configuration backup to https://acb.netgate.com/save (success).
Jan 10 18:52:12 gateway php-fpm[66698]: /rc.newwanip: Gateway, none 'available' for inet6, use the first one configured. ''
Jan 10 18:52:12 gateway php-fpm[66698]: /rc.newwanip: IP Address has changed, killing states on former IP Address 10.0.6.1.
Jan 10 18:52:15 gateway dhcpleases[43812]: Could not deliver signal HUP to process 34688: No such process.
Jan 10 18:52:16 gateway php-fpm[66698]: /rc.newwanip: Resyncing OpenVPN instances for interface AIR.
Jan 10 18:52:16 gateway php-fpm[66698]: /rc.newwanip: Creating rrd update script
Jan 10 18:52:18 gateway php-fpm[66698]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 10.0.6.1 ->  10.1.0.1 - Restarting packages.
Jan 10 18:52:18 gateway check_reload_status[376]: Starting packages
Jan 10 18:52:19 gateway php-fpm[347]: /rc.start_packages: Restarting/Starting all packages.
Jan 10 18:52:32 gateway check_reload_status[376]: Linkup starting igb1
Jan 10 18:52:32 gateway kernel: igb1: link state changed to DOWN
Jan 10 18:52:32 gateway kernel: igb1.113: link state changed to DOWN
Jan 10 18:52:32 gateway kernel: igb1.112: link state changed to DOWN
Jan 10 18:52:32 gateway kernel: igb1.110: link state changed to DOWN
Jan 10 18:52:32 gateway kernel: igb1.1100: link state changed to DOWN
Jan 10 18:52:32 gateway check_reload_status[376]: Linkup starting igb1.113
Jan 10 18:52:32 gateway check_reload_status[376]: Linkup starting igb1.112
Jan 10 18:52:32 gateway check_reload_status[376]: Linkup starting igb1.110
Jan 10 18:52:32 gateway check_reload_status[376]: Linkup starting igb1.1100
Jan 10 18:52:32 gateway check_reload_status[376]: Syncing firewall
Jan 10 18:52:32 gateway php-fpm[347]: /interfaces_vlan.php: Beginning configuration backup to https://acb.netgate.com/save
Jan 10 18:52:33 gateway php-fpm[346]: /rc.linkup: Hotplug event detected for LAN(lan) static IP (10.0.0.1 )
Jan 10 18:52:33 gateway php-fpm[55973]: /rc.linkup: Hotplug event detected for DMZ(opt4) static IP (10.0.8.1 )
Jan 10 18:52:33 gateway check_reload_status[376]: Reloading filter
Jan 10 18:52:33 gateway php-fpm[66698]: /rc.linkup: Hotplug event detected for MANAGEMENT(opt1) static IP (10.0.7.1 )
Jan 10 18:52:33 gateway check_reload_status[376]: Reloading filter
Jan 10 18:52:33 gateway php-fpm[346]: /rc.linkup: Hotplug event detected for VOICE(opt2) static IP (10.0.5.1 )
Jan 10 18:52:33 gateway php-fpm[55973]: /rc.linkup: Hotplug event detected for AIR(opt3) static IP (10.1.0.1 )
Jan 10 18:52:35 gateway check_reload_status[376]: Linkup starting igb1
Jan 10 18:52:35 gateway kernel: igb1: link state changed to UP
Jan 10 18:52:35 gateway kernel: igb1.113: link state changed to UP
Jan 10 18:52:35 gateway kernel: igb1.112: link state changed to UP
Jan 10 18:52:35 gateway kernel: igb1.110: link state changed to UP
Jan 10 18:52:35 gateway kernel: igb1.1100: link state changed to UP
Jan 10 18:52:35 gateway check_reload_status[376]: Linkup starting igb1.113
Jan 10 18:52:35 gateway check_reload_status[376]: Linkup starting igb1.112
Jan 10 18:52:35 gateway check_reload_status[376]: Linkup starting igb1.110
Jan 10 18:52:35 gateway check_reload_status[376]: Linkup starting igb1.1100
Jan 10 18:52:36 gateway php-fpm[66698]: /rc.linkup: Hotplug event detected for DMZ(opt4) static IP (10.0.8.1 )
Jan 10 18:52:36 gateway php-fpm[55973]: /rc.linkup: Hotplug event detected for LAN(lan) static IP (10.0.0.1 )
Jan 10 18:52:36 gateway check_reload_status[376]: rc.newwanip starting igb1.113
Jan 10 18:52:36 gateway check_reload_status[376]: Reloading filter
Jan 10 18:52:36 gateway check_reload_status[376]: rc.newwanip starting igb1
Jan 10 18:52:36 gateway php-fpm[66698]: /rc.linkup: Hotplug event detected for MANAGEMENT(opt1) static IP (10.0.7.1 )
Jan 10 18:52:36 gateway php-fpm[55973]: /rc.linkup: Hotplug event detected for VOICE(opt2) static IP (10.0.5.1 )
Jan 10 18:52:36 gateway check_reload_status[376]: rc.newwanip starting igb1.112
Jan 10 18:52:36 gateway check_reload_status[376]: rc.newwanip starting igb1.110
Jan 10 18:52:36 gateway php-fpm[66698]: /rc.linkup: Hotplug event detected for AIR(opt3) static IP (10.1.0.1 )
Jan 10 18:52:36 gateway check_reload_status[376]: rc.newwanip starting igb1.1100
Jan 10 18:52:37 gateway php-fpm[66698]: /rc.newwanip: rc.newwanip: Info: starting on igb1.
Jan 10 18:52:37 gateway php-fpm[55973]: /rc.newwanip: rc.newwanip: Info: starting on igb1.113.
Jan 10 18:52:37 gateway php-fpm[66698]: /rc.newwanip: rc.newwanip: on (IP address: 10.0.0.1) (interface: LAN[lan]) (real interface: igb1).
Jan 10 18:52:37 gateway php-fpm[55973]: /rc.newwanip: rc.newwanip: on (IP address: 10.0.8.1) (interface: DMZ[opt4]) (real interface: igb1.113).
Jan 10 18:52:37 gateway php-fpm[346]: /rc.newwanip: rc.newwanip: Info: starting on igb1.112.
Jan 10 18:52:37 gateway php-fpm[346]: /rc.newwanip: rc.newwanip: on (IP address: 10.0.7.1) (interface: MANAGEMENT[opt1]) (real interface: igb1.112).
Jan 10 18:52:37 gateway check_reload_status[376]: Reloading filter
Jan 10 18:52:37 gateway php-fpm[66698]: /rc.newwanip: rc.newwanip: Info: starting on igb1.110.
Jan 10 18:52:37 gateway php-fpm[66698]: /rc.newwanip: rc.newwanip: on (IP address: 10.0.5.1) (interface: VOICE[opt2]) (real interface: igb1.110).
Jan 10 18:52:37 gateway check_reload_status[376]: Reloading filter
Jan 10 18:52:37 gateway php-fpm[55973]: /rc.newwanip: rc.newwanip: Info: starting on igb1.1100.
Jan 10 18:52:37 gateway php-fpm[55973]: /rc.newwanip: rc.newwanip: on (IP address: 10.1.0.1) (interface: AIR[opt3]) (real interface: igb1.1100).
Jan 10 18:52:40 gateway php-fpm[347]: /interfaces_vlan.php: End of configuration backup to https://acb.netgate.com/save (success).
Jan 10 18:54:48 gateway dhcpleases[65870]: /etc/hosts changed size from original!
Jan 10 18:56:57 gateway kernel: arp: 10.1.0.136 moved from 00:04:13:8f:7a:1b to 00:1c:10:8d:10:57 on igb1.1100
Jan 11 02:48:51 gateway kernel: arp: 10.0.0.196 moved from dc:3a:5e:33:d5:29 to dc:3a:5e:33:c5:29 on igb1
Jan 11 02:48:53 gateway kernel: arp: 10.0.0.196 moved from dc:3a:5e:33:c5:29 to dc:3a:5e:33:d5:29 on igb1
Jan 11 10:35:43 gateway kernel: arp: 10.0.0.196 moved from dc:3a:5e:33:d5:29 to dc:3a:5e:33:c5:29 on igb1
Jan 11 10:35:44 gateway kernel: arp: 10.0.0.196 moved from dc:3a:5e:33:c5:29 to dc:3a:5e:33:d5:29 on igb1
Jan 11 13:02:04 gateway dhcpleases[65870]: Could not deliver signal HUP to process 63374: No such process.
Jan 11 13:02:04 gateway dhcpleases[65578]: Could not deliver signal HUP to process 63374: No such process.
Jan 11 13:02:31 gateway dhcpleases[65870]: Could not deliver signal HUP to process 63374: No such process.
Jan 11 13:02:31 gateway dhcpleases[65578]: Could not deliver signal HUP to process 63374: No such process.
Jan 11 13:04:38 gateway dhcpleases[65578]: Could not deliver signal HUP to process 63374: No such process.
Jan 11 13:04:38 gateway dhcpleases[65870]: Could not deliver signal HUP to process 63374: No such process.
                        1 Reply Last reply Reply Quote 0
                        • stephenw10S
                          stephenw10 Netgate Administrator
                          last edited by

                          That doesn't look like a memory leak at all. The graphs show 90% RAM was free at the time. Unbound stopped for some other reason. What did you do to restart it?

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

                            Log lines indicate the exact moment of the events :

                            @leonroy said in Unbound was killed: out of swap space:

                            Jan 11 13:01:33 unbound 63374 [63374:0] notice: Restart of unbound 1.12.0.

                            and while it's starting - 15 seconds later :

                            @leonroy said in Unbound was killed: out of swap space:

                            Jan 11 13:01:48 unbound 63374 [63374:0] info: service stopped (unbound 1.12.0).

                            and a small instance (< 1 second) :

                            Jan 11 13:01:48 unbound 63374 [63374:0] notice: Restart of unbound 1.12.0.

                            To make a long story, go to the Unbound / Resolver settings page and uncheck this :

                            ffec4b58-bccf-4e36-8b6e-dc41c1cea202-image.png

                            Stick a post-it on the pfSense box that says :
                            "Check the resolver logs again after 48 hours and see how many stops/restarts happened the last 48 hours".
                            If you find "a couple" or even less : issue solved.

                            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
                            • First post
                              Last post
                            Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.