Actions
Bug #7918
closed
Nightly error reloading rules
Status:
Not a Bug
Priority:
Normal
Assignee:
-
Category:
Traffic Shaper (ALTQ)
Target version:
-
Start date:
10/09/2017
Due date:
% Done:
0%
Estimated time:
Plus Target Version:
Release Notes:
Affected Version:
2.3.4_1
Affected Architecture:
Description
A while ago, I started getting the same notice in my logs every night at the same time. Most of my external servers report losing their vpn connection about two minutes later. When I log into the web UI, I get this helpful greeting:
pf_busy
PF was wedged/busy and has been reset. @ 2017-10-08 04:32:17
Filter Reload
There were error(s) loading the rules: pfctl: DIOCADDALTQ: Device busy - The line in question reads [0]: @ 2017-10-08 04:32:24
From my syslog host, I found these lines:
2017-09-14.log:Sep 14 04:32:01 10.41.50.1 php-fpm[88706]: /rc.filter_configure_sync: New alert found: There were error(s) loading the rules: pfctl: DIOCADDALTQ: Device busy - The line in question reads [0]: 2017-09-18.log:Sep 18 04:32:07 10.41.50.1 php-fpm[13626]: /rc.filter_configure_sync: New alert found: There were error(s) loading the rules: pfctl: DIOCADDALTQ: Device busy - The line in question reads [0]: 2017-09-19.log:Sep 19 04:32:12 10.41.50.1 php-fpm[16118]: /rc.filter_configure_sync: New alert found: There were error(s) loading the rules: pfctl: DIOCADDALTQ: Device busy - The line in question reads [0]: 2017-09-21.log:Sep 21 04:32:09 10.41.50.1 php-fpm[75829]: /rc.filter_configure_sync: New alert found: There were error(s) loading the rules: pfctl: DIOCADDALTQ: Device busy - The line in question reads [0]: 2017-09-22.log:Sep 22 04:31:57 10.41.50.1 php-fpm[72919]: /rc.filter_configure_sync: New alert found: There were error(s) loading the rules: pfctl: DIOCADDALTQ: Device busy - The line in question reads [0]: 2017-09-25.log:Sep 25 04:32:00 10.41.50.1 php-fpm[92114]: /rc.filter_configure_sync: New alert found: There were error(s) loading the rules: pfctl: DIOCADDALTQ: Device busy - The line in question reads [0]: 2017-09-26.log:Sep 26 04:32:12 10.41.50.1 php-fpm[76299]: /rc.filter_configure_sync: New alert found: There were error(s) loading the rules: pfctl: DIOCADDALTQ: Device busy - The line in question reads [0]: 2017-09-28.log:Sep 28 04:32:13 10.41.50.1 php-fpm[36325]: /rc.filter_configure_sync: New alert found: There were error(s) loading the rules: pfctl: DIOCADDALTQ: Device busy - The line in question reads [0]: 2017-09-29.log:Sep 29 04:32:28 10.41.50.1 php-fpm[91783]: /rc.filter_configure_sync: New alert found: There were error(s) loading the rules: pfctl: DIOCADDALTQ: Device busy - The line in question reads [0]: 2017-10-01.log:Oct 1 04:32:19 10.41.50.1 php-fpm[5097]: /rc.filter_configure_sync: New alert found: There were error(s) loading the rules: pfctl: DIOCADDALTQ: Device busy - The line in question reads [0]: 2017-10-08.log:Oct 8 04:32:24 10.41.50.1 php-fpm[96129]: /rc.filter_configure_sync: New alert found: There were error(s) loading the rules: pfctl: DIOCADDALTQ: Device busy - The line in question reads [0]:
If I look at one of the log files, I see this:
Oct 8 04:31:00 10.141.5.1 /usr/sbin/cron[91656]: (root) CMD (/usr/bin/nice -n20 adjkerntz -a) Oct 8 04:31:03 10.141.5.1 dhclient[26768]: igb0 link state up -> down Oct 8 04:31:03 10.141.5.1 kernel: igb0: link state changed to DOWN Oct 8 04:31:03 10.141.5.1 check_reload_status: Linkup starting igb0 Oct 8 04:31:04 10.141.5.1 php-fpm[30617]: /rc.linkup: DEVD Ethernet detached event for wan Oct 8 04:31:04 10.141.5.1 dhclient[21428]: connection closed Oct 8 04:31:04 10.141.5.1 dhclient[21428]: exiting. Oct 8 04:31:05 10.141.5.1 suricata[55845]: [100174] <Info> -- alert-pf -> Received notification of IP address change on interface igb0. Oct 8 04:31:05 10.141.5.1 suricata[55845]: [100174] <Info> -- alert-pf -> deleted address 172.23.89.203 from automatic interface IP Pass List. Oct 8 04:31:05 10.141.5.1 check_reload_status: Reloading filter Oct 8 04:31:05 10.141.5.1 kernel: arpresolve: can't allocate llinfo for 172.23.89.1 on igb0 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:31:05 10.141.5.1 unbound: [47828:0] error: can't bind socket: Can't assign requested address for 172.23.89.203 # .. Skipping ~108,000 repeated lines (11 MB worth) Oct 8 04:32:15 10.141.50.1 unbound: [77244:1] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:32:15 10.141.50.1 unbound: [77244:1] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:32:15 10.141.50.1 unbound: [77244:1] error: can't bind socket: Can't assign requested address for 172.23.89.203 Oct 8 04:32:15 10.141.50.1 suricata[55845]: [100174] <Info> -- alert-pf -> Received notification of IP address change on interface igb0. Oct 8 04:32:15 10.141.50.1 suricata[55845]: [100174] <Info> -- alert-pf -> added address 172.23.89.203 to automatic interface IP Pass List. Oct 8 04:32:15 10.141.50.1 dhclient: New IP Address (igb0): 172.23.89.203 Oct 8 04:32:15 10.141.50.1 dhclient: New Subnet Mask (igb0): 255.255.254.0 Oct 8 04:32:15 10.141.50.1 dhclient: New Broadcast Address (igb0): 172.23.89.255 Oct 8 04:32:15 10.141.50.1 dhclient: New Routers (igb0): 172.23.89.1 Oct 8 04:32:15 10.141.50.1 dhclient: Adding new routes to interface: igb0 Oct 8 04:32:15 10.141.50.1 dhclient: /sbin/route add default 172.23.89.1 Oct 8 04:32:15 10.141.50.1 dhclient: Creating resolv.conf Oct 8 04:32:15 10.141.50.1 php-fpm[93144]: /rc.dyndns.update: phpDynDNS (319826): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
I can't tell if this is a bug or something else. My ISP provides a single DHCP address, but the address does not change; it was not changing here. This is on an SG-2440.
Updated by Michael Lustfield about 7 years ago
Still present on 2.4.0.
edit: and 2.4.1
edit: and 2.4.2
Updated by Chris Collins over 5 years ago
confirmed same problem here, never seen it before then out of nowhere suddenly no type of rule update can be carried out.
I see many hits on google on the pfsense forums so isnt an isolated issue.
Failing to update rules is clearly a serious problem so I feel this should be high priority.
Updated by Chris Collins over 5 years ago
Ok in my case the error was caused by me accidentally setting two queues to the same priority on FAIRQ.
So to avoid the problem I reported I suggest the dev's add a sanity check so when FAIRQ is used no 2 queues can have the same priority.
Updated by Jim Pingle over 5 years ago
- Category set to Traffic Shaper (ALTQ)
- Status changed from New to Not a Bug
This appears to be a configuration issue, but if you can figure out exactly what the issue is in your case(s), then input validation can be crafted to help avoid the situation.
For help tracking down your configuration issues, please create a new topic on the Netgate Forum and include your entire ruleset and traffic shaping configuration.
Once you figure out which combination of configuration parameters produces this error, create a new issue with the details.
Actions