unbound crash w/log after WAN IP change
-
Just had a 15 minute crash of unbound before I restarted it. In the system logs I had the following:
Oct 26 13:15:56 php-fpm 55816 /rc.linkup: Shutting down Router Advertisment daemon cleanly Oct 26 13:15:56 check_reload_status Reloading filter Oct 26 13:15:56 php-fpm 67645 /rc.linkup: DEVD Ethernet attached event for wan Oct 26 13:15:56 php-fpm 67645 /rc.linkup: HOTPLUG: Configuring interface wan Oct 26 13:15:56 kernel arpresolve: can't allocate llinfo for 71.237.8.1 on re1 Oct 26 13:15:56 check_reload_status rc.newwanip starting re1 Oct 26 13:15:56 php-fpm 67645 /rc.linkup: calling interface_dhcpv6_configure. Oct 26 13:15:56 php-fpm 67645 /rc.linkup: Gateway, none 'available' for inet, use the first one configured. 'WAN_DHCP' Oct 26 13:15:56 php-fpm 67645 /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. 'WAN_DHCP6' Oct 26 13:15:56 check_reload_status Restarting ipsec tunnels Oct 26 13:15:57 php-fpm 69626 /rc.newwanip: rc.newwanip: Info: starting on re1. Oct 26 13:15:57 php-fpm 69626 /rc.newwanip: rc.newwanip: on (IP address: 71.237.14.232) (interface: WAN[wan]) (real interface: re1). Oct 26 13:15:57 php-fpm 69626 /rc.newwanip: Accept router advertisements on interface re1 Oct 26 13:15:57 php-fpm 69626 /rc.newwanip: Starting rtsold process Oct 26 13:16:00 php-fpm 69626 /rc.newwanip: Gateway, none 'available' for inet6, use the first one configured. 'WAN_DHCP6' Oct 26 13:16:00 rtsold Received RA specifying route fe80::201:5cff:fe68:e846 for interface wan(re1) Oct 26 13:16:00 rtsold Starting dhcp6 client for interface wan(re1) Oct 26 13:16:01 check_reload_status updating dyndns wan Oct 26 13:16:01 check_reload_status Reloading filter Oct 26 13:16:03 php-fpm 69626 /rc.newwanip: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1603739763] unbound[17429:0] error: can't bind socket: Can't assign requested address for 2601:282:4100:78:201:2eff:fe81:ac0c port 53 [1603739763] unbound[17429:0] fatal error: could not open ports' Oct 26 13:16:05 php-fpm 69626 /rc.newwanip: Resyncing OpenVPN instances for interface WAN. Oct 26 13:16:05 php-fpm 69626 /rc.newwanip: Creating rrd update script Oct 26 13:16:07 php-fpm 69626 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 71.237.14.232 -> 71.237.14.232 - Restarting packages. Oct 26 13:16:07 check_reload_status Starting packages Oct 26 13:16:08 php-fpm 67645 /rc.start_packages: Restarting/Starting all packages. Oct 26 13:23:46 php-fpm 67645 /index.php: Successful login for user 'admin' from: 172.20.20.184 (Local Database)This appears to be the relevant section of unbound, with a fairly fresh reload only 15 minutes prior already:
Oct 26 13:15:58 unbound 53925:0 info: start of service (unbound 1.10.1). Oct 26 13:15:59 unbound 53925:2 error: no TCP outgoing interfaces of family Oct 26 13:15:59 unbound 53925:2 notice: for addr 2001:4860:4860::8888 port 853 Oct 26 13:15:59 unbound 53925:2 info: generate keytag query _ta-4f66. NULL IN Oct 26 13:15:59 unbound 53925:2 error: no TCP outgoing interfaces of family Oct 26 13:15:59 unbound 53925:2 notice: for addr 2001:4860:4860::8888 port 853 Oct 26 13:16:00 unbound 53925:0 info: service stopped (unbound 1.10.1). Oct 26 13:16:00 unbound 53925:0 info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting Oct 26 13:16:00 unbound 53925:0 info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0 Oct 26 13:16:00 unbound 53925:0 info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting Oct 26 13:16:00 unbound 53925:0 info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0 Oct 26 13:16:00 unbound 53925:0 info: server stats for thread 2: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting Oct 26 13:16:00 unbound 53925:0 info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0 Oct 26 13:16:00 unbound 53925:0 info: average recursion processing time 0.358966 sec Oct 26 13:16:00 unbound 53925:0 info: histogram of recursion processing times Oct 26 13:16:00 unbound 53925:0 info: [25%]=0 median[50%]=0 [75%]=0 Oct 26 13:16:00 unbound 53925:0 info: lower(secs) upper(secs) recursions Oct 26 13:16:00 unbound 53925:0 info: 0.262144 0.524288 1 Oct 26 13:16:00 unbound 53925:0 info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting Oct 26 13:16:00 unbound 53925:0 info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0 Oct 26 13:30:41 unbound 24879:0 notice: init module 0: validator Oct 26 13:30:41 unbound 24879:0 notice: init module 1: iterator Oct 26 13:30:41 unbound 24879:0 info: start of service (unbound 1.10.1). Oct 26 13:30:44 unbound 24879:1 info: generate keytag query _ta-4f66. NULL INRemediation simply required clicking the play button on the front page. I'm not quite sure why this is choking so hard on a somewhat pedestrian network change that it should be capable of handling. Existing connections were not interrupted; youtube continued to play dance party and video games had zero lag or disconnect issues. New connections however obviously failed on resolution.
-
Unrelated; service_watchdog seems to have not responded on this one.Perhaps I should be less stupid and make sure service watchdog is actually configured...