Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    unbound crash w/log after WAN IP change

    Scheduled Pinned Locked Moved Development
    2 Posts 1 Posters 373 Views
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • S
      skogs
      last edited by skogs

      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 IN 
      

      Remediation 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.

      1 Reply Last reply Reply Quote 0
      • S
        skogs
        last edited by skogs

        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...

        1 Reply Last reply Reply Quote 0
        • First post
          Last post
        Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.