pfSense

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.