IPv6 DHCP-PD – radvd dies after interface reset - dhcpv6 does not reaquire addr
-
My box (running the Jul 15 snapshot) also just lost all IPv6 connectivity after 9 days of uptime (Comcast Residential).
Here is the relevant system log output:
Jul 24 17:20:21 router check_reload_status: updating dyndns WAN_DHCP6,WAN_DHCP Jul 24 17:20:21 router check_reload_status: Restarting ipsec tunnels Jul 24 17:20:21 router check_reload_status: Restarting OpenVPN tunnels/interfaces Jul 24 17:20:21 router check_reload_status: Reloading filter Jul 24 17:20:33 router check_reload_status: Linkup starting re0 Jul 24 10:20:33 router kernel: re0: link state changed to DOWN Jul 24 17:20:35 router check_reload_status: Linkup starting re0 Jul 24 10:20:35 router kernel: re0: link state changed to UP Jul 24 10:20:35 router php: rc.linkup: DEVD Ethernet detached event for wan Jul 24 17:20:36 router check_reload_status: Linkup starting re0 Jul 24 10:20:36 router kernel: re0: link state changed to DOWN Jul 24 10:20:37 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:20:37 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:20:37 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:20:37 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:20:37 router php: rc.linkup: DEVD Ethernet attached event for wan Jul 24 10:20:37 router php: rc.linkup: HOTPLUG: Configuring interface wan Jul 24 10:20:38 router php: rc.linkup: DEVD Ethernet detached event for wan Jul 24 10:20:39 router php: rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing. Jul 24 10:20:39 router php: rc.linkup: Clearing states to old gateway 76.102.40.1. Jul 24 10:20:44 router php: rc.newipsecdns: Could not determine VPN endpoint for '' Jul 24 17:20:49 router check_reload_status: Linkup starting re0 Jul 24 10:20:49 router kernel: re0: link state changed to UP Jul 24 10:20:49 router php: rc.newipsecdns: Could not determine VPN endpoint for '' Jul 24 10:20:51 router php: rc.linkup: DEVD Ethernet attached event for wan Jul 24 10:20:51 router php: rc.linkup: HOTPLUG: Configuring interface wan Jul 24 10:20:52 router php: rc.linkup: The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf re0 > /tmp/re0_output 2> /tmp/re0_error_output' returned exit code '1', the output was '' Jul 24 10:20:52 router php: rc.linkup: Accept router advertisements on interface re0 Jul 24 10:20:53 router kernel: re0: link state changed to DOWN Jul 24 17:20:53 router check_reload_status: Linkup starting re0 Jul 24 10:20:53 router dhcpleases: Could not deliver signal HUP to process because its pidfile does not exist, No such process. Jul 24 10:20:55 router php: rc.newipsecdns: Could not determine VPN endpoint for '' Jul 24 10:20:55 router php: rc.linkup: DEVD Ethernet detached event for wan Jul 24 10:20:55 router php: rc.linkup: The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf re0 > /tmp/re0_output 2> /tmp/re0_error_output' returned exit code '15', the output was '' Jul 24 10:20:55 router php: rc.linkup: Accept router advertisements on interface re0 Jul 24 17:20:55 router check_reload_status: Linkup starting re0 Jul 24 10:20:55 router kernel: re0: link state changed to UP Jul 24 10:20:56 router php: rc.linkup: Shutting down Router Advertisment daemon cleanly Jul 24 17:20:56 router check_reload_status: updating dyndns wan Jul 24 10:20:58 router php: rc.linkup: DEVD Ethernet attached event for wan Jul 24 10:20:58 router php: rc.linkup: HOTPLUG: Configuring interface wan Jul 24 10:20:59 router php: rc.dyndns.update: DynDNS ([hostname removed]) There was an error trying to determine the public IP for interface - wan(re0). Probably interface is not a WAN interface. Jul 24 10:21:00 router php: rc.newipsecdns: Could not determine VPN endpoint for '' Jul 24 10:21:00 router php: rc.dyndns.update: DynDNS ([hostname removed]) There was an error trying to determine the public IP for interface - wan(re0). Probably interface is not a WAN interface. Jul 24 17:21:03 router check_reload_status: rc.newwanip starting re0 Jul 24 10:21:03 router php: rc.linkup: Accept router advertisements on interface re0 Jul 24 10:21:03 router php: rc.linkup: ROUTING: setting default route to 192.168.100.1 Jul 24 10:21:04 router dhcpleases: Could not deliver signal HUP to process because its pidfile does not exist, No such process. Jul 24 10:21:05 router php: rc.newipsecdns: Could not determine VPN endpoint for '' Jul 24 10:21:06 router php: rc.newwanip: rc.newwanip: Informational is starting re0. Jul 24 10:21:06 router php: rc.newwanip: rc.newwanip: on (IP address: 192.168.100.10) (interface: wan) (real interface: re0). Jul 24 10:21:06 router php: rc.newwanip: ROUTING: setting default route to 192.168.100.1 Jul 24 17:21:07 router check_reload_status: updating dyndns wan Jul 24 10:21:07 router dhcp6c[25808]: client6_timo: no responses were received Jul 24 10:21:10 router php: rc.newipsecdns: Could not determine VPN endpoint for '' Jul 24 10:21:11 router dhcp6c[25808]: client6_timo: no responses were received Jul 24 10:21:11 router dhcp6c[25808]: check_exit: exiting Jul 24 10:21:16 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:16 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:16 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:17 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:17 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:17 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:18 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:18 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:18 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:19 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:19 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:19 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:20 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:20 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:20 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:21 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:21 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:21 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:23 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:23 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:23 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:27 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:27 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:27 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:35 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:35 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:35 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:51 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:51 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 10:21:51 router kernel: arpresolve: can't allocate llinfo for 76.102.40.1 Jul 24 17:22:07 router check_reload_status: rc.newwanip starting re0 Jul 24 10:22:10 router php: rc.newwanip: rc.newwanip: Informational is starting re0. Jul 24 10:22:10 router php: rc.newwanip: rc.newwanip: on (IP address: 76.102.40.77) (interface: wan) (real interface: re0). Jul 24 10:22:10 router php: rc.newwanip: ROUTING: setting default route to 76.102.40.1 Jul 24 10:22:14 router php: rc.newwanip: Dyndns debug information ([hostname removed]): Could not resolve checkip.dyndns.org to ip using interface ip 192.168.100.10. Jul 24 10:22:14 router php: rc.newwanip: DynDNS ([hostname removed]) There was an error trying to determine the public IP for interface - wan(re0). Probably interface is not a WAN interface. Jul 24 10:22:14 router php: rc.dyndns.update: phpDynDNS ([hostname removed]): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jul 24 10:22:14 router php: rc.newwanip: phpDynDNS ([hostname removed]): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jul 24 10:22:15 router php: rc.newwanip: DynDNS ([hostname removed]) There was an error trying to determine the public IP for interface - wan(re0). Probably interface is not a WAN interface. Jul 24 10:22:15 router php: rc.newwanip: DynDNS ([hostname removed]) There was an error trying to determine the public IP for interface - wan(re0). Probably interface is not a WAN interface. Jul 24 10:22:15 router php: rc.dyndns.update: DynDNS ([hostname removed]) There was an error trying to determine the public IP for interface - wan(re0). Probably interface is not a WAN interface. Jul 24 10:22:21 router php: rc.newwanip: Forcefully reloading IPsec racoon daemon Jul 24 10:22:21 router php: rc.newwanip: Forcefully reloading IPsec racoon daemon Jul 24 10:22:21 router php: rc.newwanip: Resyncing OpenVPN instances for interface WAN. Jul 24 10:22:21 router php: rc.newwanip: Creating rrd update script Jul 24 10:22:21 router php: rc.newwanip: Resyncing OpenVPN instances for interface WAN. Jul 24 10:22:21 router php: rc.newwanip: Creating rrd update script Jul 24 10:22:23 router php: rc.newwanip: pfSense package system has detected an ip change 76.102.40.77 -> 192.168.100.10 ... Restarting packages. Jul 24 17:22:23 router check_reload_status: Starting packages Jul 24 10:22:23 router snmpd[4636]: disk_OS_get_disks: device 'da0' not in device list Jul 24 10:22:23 router snmpd[5638]: bind: 0.0.0.0:161 Address already in use Jul 24 10:22:23 router snmpd[5638]: NgMkSockNode: Address already in use Jul 24 10:22:23 router php: rc.newwanip: pfSense package system has detected an ip change 192.168.100.10 -> 76.102.40.77 ... Restarting packages. Jul 24 10:22:23 router snmpd[5638]: assignment to begemotNgControlNodeName.0 returns 5 Jul 24 17:22:23 router check_reload_status: Reloading filter Jul 24 10:22:23 router snmpd[5638]: in file /var/etc/snmpd.conf line 25 Jul 24 10:22:23 router snmpd[5638]: error in config file Jul 24 10:22:26 router php: rc.start_packages: Restarting/Starting all packages. Jul 24 10:22:27 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:28 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:28 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:28 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:28 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:28 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:28 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:28 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:28 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:28 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:28 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:28 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:28 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:29 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:29 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:29 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:29 router php: rc.filter_configure_sync: Could not find IPv6 gateway for interface(wan). Jul 24 10:22:31 router php: rc.start_packages: XML error: SYSTEM or PUBLIC, the URI is missing at line 1 in /usr/local/pkg/iftop.xml Jul 24 10:22:31 router php: rc.start_packages: XML error: SYSTEM or PUBLIC, the URI is missing at line 1 in /usr/local/pkg/iftop.xml Jul 24 10:22:33 router php: rc.start_packages: XML error: SYSTEM or PUBLIC, the URI is missing at line 1 in /usr/local/pkg/ipmitool.xml Jul 24 10:22:33 router php: rc.start_packages: XML error: SYSTEM or PUBLIC, the URI is missing at line 1 in /usr/local/pkg/ipmitool.xml Jul 24 10:22:35 router upsmon[55314]: Signal 15: exiting
At the beginning, the cable modem appears to lose upstream connectivity. This causes the WAN interface (re0) on the pfSense box to bounce, which in turn prompts pfSense to try to reconfigure it. The problem is that when the interface comes back up, the cable modem hasn't re-established its uplink. As a result, it replies to the DHCPv4 requests from the pfSense box with an ACK for a private IP from the 192.168.100.0/24 range (at 10:21:06); however, it does not respond to DHCPv6 requests at all during this time, which causes dhcp6c on the pfSense box to exit (at 10:21:11). After the cable modem's upstream recovers, pfSense correctly picks up the new public IPv4 address (at 10:22:10); however, dhcp6c is not restarted, and so pfSense never attempt to re-acquire an IPv6 address.
So it looks like the problem is that pfSense does not deal well with IPv6 connectivity going away and then coming back.
(As a side note, what's up with some of the time stamps being time zone adjusted but others not?)
-
Looks like there are relevant entries in dhcpd.log as well:
Jul 22 16:54:58 router dhclient: RENEW Jul 22 16:54:58 router dhclient: Creating resolv.conf Jul 24 10:20:35 router dhclient[11039]: connection closed Jul 24 10:20:35 router dhclient[11039]: exiting. Jul 24 10:20:49 router dhclient: PREINIT Jul 24 10:20:49 router dhclient: Starting delete_old_states() Jul 24 10:20:49 router dhclient: Comparing IPs: Old: New: Jul 24 10:20:49 router dhclient[81638]: DHCPREQUEST on re0 to 255.255.255.255 port 67 Jul 24 10:20:49 router dhclient[81638]: DHCPDISCOVER on re0 to 255.255.255.255 port 67 interval 2 Jul 24 10:20:51 router dhclient[81638]: DHCPDISCOVER on re0 to 255.255.255.255 port 67 interval 2 Jul 24 10:20:52 router dhclient[86320]: dhclient already running, pid: 81638. Jul 24 10:20:52 router dhclient[86320]: exiting. Jul 24 10:20:53 router dhclient[81638]: DHCPDISCOVER on re0 to 255.255.255.255 port 67 interval 4 Jul 24 10:20:55 router dhclient[83516]: connection closed Jul 24 10:20:55 router dhclient[83516]: exiting. Jul 24 10:20:59 router dhclient: PREINIT Jul 24 10:20:59 router dhclient: Starting delete_old_states() Jul 24 10:20:59 router dhclient: Comparing IPs: Old: New: Jul 24 10:20:59 router dhclient[9924]: DHCPREQUEST on re0 to 255.255.255.255 port 67 Jul 24 10:20:59 router dhclient[9924]: DHCPNAK from 192.168.100.1 Jul 24 10:20:59 router dhclient[9924]: DHCPDISCOVER on re0 to 255.255.255.255 port 67 interval 2 Jul 24 10:21:01 router dhclient[9924]: DHCPDISCOVER on re0 to 255.255.255.255 port 67 interval 2 Jul 24 10:21:01 router dhclient[9924]: DHCPOFFER from 192.168.100.1 Jul 24 10:21:01 router dhclient: ARPSEND Jul 24 10:21:01 router dhclient[9924]: DHCPOFFER from 192.168.100.1 Jul 24 10:21:01 router dhclient[9924]: DHCPOFFER already seen. Jul 24 10:21:03 router dhclient: ARPCHECK Jul 24 10:21:03 router dhclient[9924]: DHCPREQUEST on re0 to 255.255.255.255 port 67 Jul 24 10:21:03 router dhclient[9924]: DHCPACK from 192.168.100.1 Jul 24 10:21:03 router dhclient: BOUND Jul 24 10:21:03 router dhclient: Starting delete_old_states() Jul 24 10:21:03 router dhclient: Comparing IPs: Old: New: 192.168.100.10 Jul 24 10:21:03 router dhclient: Starting add_new_address() Jul 24 10:21:03 router dhclient: ifconfig re0 inet 192.168.100.10 netmask 255.255.255.0 broadcast 192.168.100.255 Jul 24 10:21:03 router dhclient: New IP Address (re0): 192.168.100.10 Jul 24 10:21:03 router dhclient: New Subnet Mask (re0): 255.255.255.0 Jul 24 10:21:03 router dhclient: New Broadcast Address (re0): 192.168.100.255 Jul 24 10:21:03 router dhclient: New Routers (re0): 192.168.100.1 Jul 24 10:21:03 router dhclient: Adding new routes to interface: re0 Jul 24 10:21:03 router dhclient: /sbin/route add default 192.168.100.1 Jul 24 10:21:03 router dhclient: Creating resolv.conf Jul 24 10:21:03 router dhclient[9924]: bound to 192.168.100.10 -- renewal in 30 seconds. Jul 24 10:21:33 router dhclient[17330]: DHCPREQUEST on re0 to 192.168.100.1 port 67 Jul 24 10:21:34 router dhclient[17330]: DHCPREQUEST on re0 to 192.168.100.1 port 67 Jul 24 10:21:36 router dhclient[17330]: DHCPREQUEST on re0 to 192.168.100.1 port 67 Jul 24 10:21:41 router dhclient[17330]: DHCPREQUEST on re0 to 192.168.100.1 port 67 Jul 24 10:21:50 router dhclient[17330]: DHCPREQUEST on re0 to 192.168.100.1 port 67 Jul 24 10:22:04 router dhclient: EXPIRE Jul 24 10:22:04 router dhclient: Starting delete_old_states() Jul 24 10:22:04 router dhclient: Comparing IPs: Old: New: Jul 24 10:22:04 router dhclient: Deleting old routes Jul 24 10:22:05 router dhclient: PREINIT Jul 24 10:22:05 router dhclient: Starting delete_old_states() Jul 24 10:22:05 router dhclient[17330]: DHCPDISCOVER on re0 to 255.255.255.255 port 67 interval 2 Jul 24 10:22:05 router dhclient[17330]: DHCPOFFER from 96.156.92.1 Jul 24 10:22:05 router dhclient: ARPSEND Jul 24 10:22:07 router dhclient: ARPCHECK Jul 24 10:22:07 router dhclient[17330]: DHCPREQUEST on re0 to 255.255.255.255 port 67 Jul 24 10:22:07 router dhclient[17330]: DHCPACK from 96.156.92.1 Jul 24 10:22:07 router dhclient: BOUND Jul 24 10:22:07 router dhclient: Starting delete_old_states() Jul 24 10:22:07 router dhclient: Deleting old routes Jul 24 10:22:07 router dhclient: Starting add_new_address() Jul 24 10:22:07 router dhclient: ifconfig re0 inet 76.102.40.77 netmask 255.255.252.0 broadcast 255.255.255.255 Jul 24 10:22:07 router dhclient: New IP Address (re0): 76.102.40.77 Jul 24 10:22:07 router dhclient: New Subnet Mask (re0): 255.255.252.0 Jul 24 10:22:07 router dhclient: New Broadcast Address (re0): 255.255.255.255 Jul 24 10:22:07 router dhclient: New Routers (re0): 76.102.40.1 Jul 24 10:22:07 router dhclient: Adding new routes to interface: re0 Jul 24 10:22:07 router dhclient: /sbin/route add default 76.102.40.1
Why does dhclient log to dhcpd.log, not to system.log (like dhcp6c does)?
-
It should have logged the blocked traffic, did you see anything in the firewall logs at the time?
If we can locate the conflicting addresses we can filter them out during the bogon update routine if we have to.
For reference, see this for the bad bogonsv6 address: http://forum.pfsense.org/index.php/topic,64980.0.html
Thanks, qubit!!!
-
Here's an update I'm running build from 2.1-RC0 (i386) built on Tue Jul 23 21:56:24 EDT 2013 FreeBSD 8.3-RELEASE-p8 and it's not been up for 10 Days 10 Hours 12 Minutes 47 Seconds without lose of IPv6.
Update: 1 1/2 days latter with uptime of 11 Days 20 Hours 51 Minutes 55 Seconds and have lost all IPv6 connectivity.
-
Just lost all v6 connectivity on my box again, after around 4 days of uptime. As before, this appears to happen when the interface bounces and v6 connectivity goes away temporarily; radvd exits and is never restarted.
-
Update 8/21/2013:
I've now had a connection for 16 Days 07 Hours 52 Minutes 17 Seconds using build 2.1-RC1 (i386) built on Thu Aug 1 19:03:40 EDT 2013.
This is the longest I've maintained a connection with no reboots or any other action.