Unbound restarting on v6 IA_NA and IA_PD updates when address and prefixes are unchanged
-
Running 26.03.1.
My router gets its GUA and delegated prefixes via DHCPv6 from my ISP (ATT fiber, BGW320). All are stable -- haven't changed in years -- even though they are "dynamic." However, unbound restarts whenever the leases are renewed, even though the addresses/prefixes haven't changed. Note that LAN-side DNS registrations of KEA leases is disabled; this is a WAN-side issue.
There are three delegated prefixes. Because ATT delegates individual /64s, each renewal cycle involves a GUA and three prefixes. ATT sets the T1 and T2 timers to both be 1800 -- don't know why -- which results (?) in each renewal cycle containing a Rebind and a Renew for each object. First snippet below shows a typical cycle for updating all leases, filtered from the dhcpd.log.
Each renew and rebind causes a restart of unbound, even though the addresses/prefixes don't change. Second snippet below is filtered from the resolver.log for the same cycle. Every 30 minutes, unbound is effectively down for 30s, which causes problems elsewhere in the network.
In this example, there are 12 restarts of unbound even though there are only 8 rebinds and renews. Haven't been able to figure out the extra 4 restarts. They don't correlate with v4 DHCP activity on the WAN. In fact, WAN DHCPv4 leases are stably renewed every 5 minutes with no apparent unbound restarts.
The WAN interface has a DHCP6 configuration file override to manage the multiple prefix requests, modeled after this thread. The config file is the final snippet below. I've looked at
/var/etc/dhcp6c_wan_script.shand the scripts that it calls, in particular/etc/rc.newwanipv6which looks like it should (?) detect whether addresses/prefixes have changed.Thanks in advance for suggestions and solutions.
Jun 2 13:24:59 pfSense dhcp6c[75478]: Sending Renew Jun 2 13:24:59 pfSense dhcp6c[75478]: Sending Rebind Jun 2 13:24:59 pfSense dhcp6c[75478]: update an IA: NA-0 Jun 2 13:24:59 pfSense dhcp6c[75478]: executes /var/etc/dhcp6c_wan_script.sh Jun 2 13:25:00 pfSense dhcp6c[75478]: update an IA: NA-0 Jun 2 13:25:00 pfSense dhcp6c[75478]: executes /var/etc/dhcp6c_wan_script.sh Jun 2 13:25:11 pfSense dhcp6c[75478]: Sending Renew Jun 2 13:25:11 pfSense dhcp6c[75478]: Sending Rebind Jun 2 13:25:11 pfSense dhcp6c[75478]: update an IA: PD-2 Jun 2 13:25:11 pfSense dhcp6c[75478]: executes /var/etc/dhcp6c_wan_script.sh Jun 2 13:25:12 pfSense dhcp6c[75478]: update an IA: PD-2 Jun 2 13:25:12 pfSense dhcp6c[75478]: executes /var/etc/dhcp6c_wan_script.sh Jun 2 13:25:19 pfSense dhcp6c[75478]: Sending Renew Jun 2 13:25:19 pfSense dhcp6c[75478]: Sending Rebind Jun 2 13:25:19 pfSense dhcp6c[75478]: update an IA: PD-1 Jun 2 13:25:19 pfSense dhcp6c[75478]: executes /var/etc/dhcp6c_wan_script.sh Jun 2 13:25:20 pfSense dhcp6c[75478]: update an IA: PD-1 Jun 2 13:25:20 pfSense dhcp6c[75478]: executes /var/etc/dhcp6c_wan_script.sh Jun 2 13:25:27 pfSense dhcp6c[75478]: Sending Renew Jun 2 13:25:27 pfSense dhcp6c[75478]: Sending Rebind Jun 2 13:25:27 pfSense dhcp6c[75478]: update an IA: PD-0 Jun 2 13:25:27 pfSense dhcp6c[75478]: executes /var/etc/dhcp6c_wan_script.sh Jun 2 13:25:28 pfSense dhcp6c[75478]: update an IA: PD-0 Jun 2 13:25:28 pfSense dhcp6c[75478]: executes /var/etc/dhcp6c_wan_script.shJun 2 13:25:02 pfSense unbound[20394]: [20394:0] info: start of service (unbound 1.25.1). Jun 2 13:25:04 pfSense unbound[76603]: [76603:0] info: start of service (unbound 1.25.1). Jun 2 13:25:06 pfSense unbound[32360]: [32360:0] info: start of service (unbound 1.25.1). Jun 2 13:25:15 pfSense unbound[27410]: [27410:0] info: start of service (unbound 1.25.1). Jun 2 13:25:16 pfSense unbound[85797]: [85797:0] info: start of service (unbound 1.25.1). Jun 2 13:25:18 pfSense unbound[44322]: [44322:0] info: start of service (unbound 1.25.1). Jun 2 13:25:22 pfSense unbound[33386]: [33386:0] info: start of service (unbound 1.25.1). Jun 2 13:25:24 pfSense unbound[93801]: [93801:0] info: start of service (unbound 1.25.1). Jun 2 13:25:26 pfSense unbound[56072]: [56072:0] info: start of service (unbound 1.25.1). Jun 2 13:25:31 pfSense unbound[44315]: [44315:0] info: start of service (unbound 1.25.1). Jun 2 13:25:32 pfSense unbound[2376]: [2376:0] info: start of service (unbound 1.25.1). Jun 2 13:25:34 pfSense unbound[58694]: [58694:0] info: start of service (unbound 1.25.1).interface igc0 { send ia-na 0; send ia-pd 0; send ia-pd 1; send ia-pd 2; request domain-name-servers; request domain-name; script "/var/etc/dhcp6c_wan_script.sh"; }; id-assoc na 0 { }; id-assoc pd 0 { prefix-interface igc1.15 { sla-id 0; sla-len 0; }; }; id-assoc pd 1 { prefix-interface igc1.20 { sla-id 0; sla-len 0; }; }; id-assoc pd 2 { prefix-interface igc1.40 { sla-id 0; sla-len 0; }; }; -
@marcg said in Unbound restarting on v6 IA_NA and IA_PD updates when address and prefixes are unchanged:
in particular /etc/rc.newwanipv6 which looks like it should (?) detect whether addresses/prefixes have changed
You didn't show the system log at the same moment. Nothing in there ?
If the reason was a DHCPv6 'renew' and 'nothing' changed, then according to here /etc/rc.newwanipv6 simply return, doing nothing.
Add a copy of line 190 (the log line) just before the 'return;' ? so you can check that is is - or is not 'rc.newwanipv6' that restarts unbound (and probably other services).
Modify it somewhat so it shows interesting info in the (system ?) log.@marcg said in Unbound restarting on v6 IA_NA and IA_PD updates when address and prefixes are unchanged:
ATT sets the T1 and T2 timers to both be 1800 -- don't know why --
== a dhcp6c renew every 5 minutes or 300 seconds .
This includes prefix info (I presume).
I get it, that feels strange. But as you said, GUAs, prefix are always dynamic even when the seem to be static. Mine are the same for the last 18+ months now. That makes us the lucky ones. There are pretty sick ISP out there that change them all the time. -
@Gertjan, thanks for the tip to look at system.log.
TL;DR: rc.newwanipv6 doesn't appear to be the issue. Gateway groups may be involved.
I added lines to rc.newwanipv6 to check whether (a) the Reason code was being correctly passed and (b) whether the script was restarting unbound.
55a56,57 > logger(LOG_NOTICE, localize_text("rc.newwanipv6 invoked with reason: %s", $reason)); > 249a252,253 > logger(LOG_NOTICE, localize_text("rc.newwanipv6 restarting services, address_replaced is %s", $address_replaced ? "True" : "False")); >The system.log results below for one of the update cycles show that the Reason code is passed and the script is not restarting unbound (no messages from the second logger addition above).
[26.03.1-RELEASE][admin@pfSense.home.arpa]/etc: grep '10:2.*rc.newwanipv6' /var/log/system.log Jun 3 10:25:46 pfSense php-fpm[15732]: NOTICE rc.newwanipv6 invoked with reason: RENEW Jun 3 10:25:47 pfSense php-fpm[15732]: NOTICE rc.newwanipv6 invoked with reason: REBIND Jun 3 10:25:58 pfSense php-fpm[76079]: NOTICE rc.newwanipv6 invoked with reason: RENEW Jun 3 10:25:59 pfSense php-fpm[76079]: NOTICE rc.newwanipv6 invoked with reason: REBIND Jun 3 10:26:06 pfSense php-fpm[619]: NOTICE rc.newwanipv6 invoked with reason: RENEW Jun 3 10:26:07 pfSense php-fpm[619]: NOTICE rc.newwanipv6 invoked with reason: REBIND Jun 3 10:26:14 pfSense php-fpm[95728]: NOTICE rc.newwanipv6 invoked with reason: RENEW Jun 3 10:26:15 pfSense php-fpm[95728]: NOTICE rc.newwanipv6 invoked with reason: REBINDYou didn't show the system log at the same moment. Nothing in there ?
system.log does show the following at approximately the same time as each update cycle with its unbound restarts: a filter reload and state killing on igc1.95 (a secondary WAN interface different from the primary WAN that we've been discussing) four times, the number of IAs, once for each REBIND presumably. So, rc.newwanipv6 simply returns on RENEW and the log message I added -- maybe in the wrong place -- stating that rc.newwanipv6 is restarting services is not being triggered.
Don't know why Gateway Monitoring kills states on secondary WAN interfaces that aren't in use when the primary's DHCP issues a REBIND (but not a RENEW).
Jun 3 10:25:52 pfSense check_reload_status[670]: Reloading filter Jun 3 10:25:53 pfSense php-fpm[618]: NOTICE [Gateway Monitoring] killed all states for gateways with interface igc1.95 due to gateway recovery for IPv4_GW_GROUP Jun 3 10:26:05 pfSense check_reload_status[670]: Reloading filter Jun 3 10:26:06 pfSense php-fpm[81917]: NOTICE [Gateway Monitoring] killed all states for gateways with interface igc1.95 due to gateway recovery for IPv4_GW_GROUP Jun 3 10:26:13 pfSense check_reload_status[670]: Reloading filter Jun 3 10:26:14 pfSense php-fpm[66525]: NOTICE [Gateway Monitoring] killed all states for gateways with interface igc1.95 due to gateway recovery for IPv4_GW_GROUP Jun 3 10:26:20 pfSense check_reload_status[670]: Reloading filter Jun 3 10:26:21 pfSense php-fpm[15732]: NOTICE [Gateway Monitoring] killed all states for gateways with interface igc1.95 due to gateway recovery for IPv4_GW_GROUP
