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-7Steve
-
@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-7Steve
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!
-
The patch is better since it prevents it starting at all.
Yes, it will apply against 2.5.2.Steve
-
@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.
-
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
-
@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-7Steve
Post still helping after all these months. Thank you.
-
On our 2.5.2 box it happened again today after 30 days of uptime.
Running the patch:
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 6Any ideas (thanks)?
-
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
-
Monitoring graph shows 90% memory throughout the past day.
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. -
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?
-
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 :
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.
