Local ISP weird behaviour w/ IPv6 via DHCP6
-
This is a standard set of System logs for just after I issue the reconnect WAN via the WebUI:
Jul 16 17:26:16 ppp 77449 caught fatal signal TERM Jul 16 17:26:16 ppp 77449 [wan] IFACE: Close event Jul 16 17:26:16 ppp 77449 [wan] IPCP: Close event Jul 16 17:26:16 ppp 77449 [wan] IPCP: state change Opened --> Closing Jul 16 17:26:16 ppp 77449 [wan] IPCP: SendTerminateReq #4 Jul 16 17:26:16 ppp 77449 [wan] IPCP: LayerDown Jul 16 17:26:16 check_reload_status 439 Rewriting resolv.conf Jul 16 17:26:16 ppp 77449 [wan] IFACE: Removing IPv4 address from pppoe0 failed(IGNORING for now. This should be only for PPPoE friendly!): Can't assign requested address Jul 16 17:26:16 ppp 77449 [wan] IPV6CP: Close event Jul 16 17:26:16 ppp 77449 [wan] IPV6CP: state change Opened --> Closing Jul 16 17:26:16 ppp 77449 [wan] IPV6CP: SendTerminateReq #2 Jul 16 17:26:16 ppp 77449 [wan] IPV6CP: LayerDown Jul 16 17:26:18 check_reload_status 439 Rewriting resolv.conf Jul 16 17:26:18 ppp 77449 [wan] IFACE: Down event Jul 16 17:26:18 ppp 77449 [wan] IFACE: Rename interface pppoe0 to pppoe0 Jul 16 17:26:18 ppp 77449 [wan] IFACE: Set description "WAN" Jul 16 17:26:18 ppp 77449 [wan] IPCP: rec'd Terminate Ack #4 (Closing) Jul 16 17:26:18 ppp 77449 [wan] IPCP: state change Closing --> Closed Jul 16 17:26:18 ppp 77449 [wan] IPCP: LayerFinish Jul 16 17:26:18 ppp 77449 [wan_link0] LCP: rec'd Terminate Request #179 (Opened) Jul 16 17:26:18 ppp 77449 [wan_link0] LCP: state change Opened --> Stopping Jul 16 17:26:18 ppp 77449 [wan_link0] Link: Leave bundle "wan" Jul 16 17:26:18 ppp 77449 [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Jul 16 17:26:18 ppp 77449 [wan] IPCP: Close event Jul 16 17:26:18 ppp 77449 [wan] IPV6CP: Close event Jul 16 17:26:18 ppp 77449 [wan] IPCP: Down event Jul 16 17:26:18 ppp 77449 [wan] IPCP: state change Closed --> Initial Jul 16 17:26:18 ppp 77449 [wan] IPV6CP: Down event Jul 16 17:26:18 ppp 77449 [wan] IPV6CP: LayerFinish Jul 16 17:26:18 ppp 77449 [wan] Bundle: No NCPs left. Closing links... Jul 16 17:26:18 ppp 77449 [wan] IPV6CP: state change Closing --> Initial Jul 16 17:26:18 ppp 77449 [wan_link0] LCP: SendTerminateAck #3 Jul 16 17:26:18 ppp 77449 [wan_link0] LCP: LayerDown Jul 16 17:26:18 ppp 77449 [wan] rec'd unexpected protocol IP Jul 16 17:26:18 ppp 77449 [wan_link0] PPPoE: connection closed Jul 16 17:26:18 ppp 77449 [wan_link0] Link: DOWN event Jul 16 17:26:18 ppp 77449 [wan_link0] Link: giving up after 0 reconnection attempts Jul 16 17:26:18 ppp 77449 [wan_link0] LCP: Close event Jul 16 17:26:18 ppp 77449 [wan_link0] LCP: state change Stopping --> Closing Jul 16 17:26:18 ppp 77449 [wan_link0] LCP: Down event Jul 16 17:26:18 ppp 77449 [wan_link0] LCP: LayerFinish Jul 16 17:26:18 ppp 77449 [wan_link0] LCP: state change Closing --> Initial Jul 16 17:26:20 ppp 77449 [wan] Bundle: Shutdown Jul 16 17:26:20 ppp 77449 [wan_link0] Link: Shutdown Jul 16 17:26:20 ppp 77449 process 77449 terminated Jul 16 17:26:20 php-fpm 399 /status_interfaces.php: Resyncing OpenVPN instances for interface WAN. Jul 16 17:26:20 check_reload_status 439 Reloading filter Jul 16 17:26:20 check_reload_status 439 Starting packages Jul 16 17:26:21 php-fpm 398 /rc.start_packages: Restarting/Starting all packages. Jul 16 17:26:21 SnortStartup 53003 Snort START for WAN(pppoe0)... Jul 16 17:26:21 php-fpm 398 /rc.start_packages: Configuration Change: (system): pfBlockerNG: saving DNSBL changes Jul 16 17:26:21 check_reload_status 439 Syncing firewall Jul 16 17:26:21 snort 58237 FATAL ERROR: Can't start DAQ (-1) - No such device exists! Jul 16 17:26:22 php-fpm 398 /rc.start_packages: Configuration Change: (system): pfBlockerNG: saving Firewall rules Jul 16 17:26:22 check_reload_status 439 Syncing firewall Jul 16 17:26:22 ppp 76000 Multi-link PPP daemon for FreeBSD Jul 16 17:26:22 ppp 76000 process 76000 started, version 5.9 Jul 16 17:26:22 ppp 76000 web: web is not running Jul 16 17:26:22 ppp 76000 [wan] Bundle: Interface ng0 created Jul 16 17:26:22 ppp 76000 [wan_link0] Link: OPEN event Jul 16 17:26:22 kernel ng0: changing name to 'pppoe0' Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: Open event Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: state change Initial --> Starting Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: LayerStart Jul 16 17:26:22 ppp 76000 [wan_link0] PPPoE: Connecting to '' Jul 16 17:26:22 ppp 76000 PPPoE: rec'd ACNAME "wnjv-bng1" Jul 16 17:26:22 ppp 76000 [wan_link0] PPPoE: connection successful Jul 16 17:26:22 ppp 76000 [wan_link0] Link: UP event Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: Up event Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: state change Starting --> Req-Sent Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: SendConfigReq #1 Jul 16 17:26:22 ppp 76000 [wan_link0] PROTOCOMP Jul 16 17:26:22 ppp 76000 [wan_link0] MRU 1492 Jul 16 17:26:22 ppp 76000 [wan_link0] MAGICNUM 0x03916120 Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: rec'd Configure Request #156 (Req-Sent) Jul 16 17:26:22 ppp 76000 [wan_link0] MRU 1500 Jul 16 17:26:22 ppp 76000 [wan_link0] AUTHPROTO PAP Jul 16 17:26:22 ppp 76000 [wan_link0] MAGICNUM 0x5b234ccd Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: SendConfigAck #156 Jul 16 17:26:22 ppp 76000 [wan_link0] MRU 1500 Jul 16 17:26:22 ppp 76000 [wan_link0] AUTHPROTO PAP Jul 16 17:26:22 ppp 76000 [wan_link0] MAGICNUM 0x5b234ccd Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: state change Req-Sent --> Ack-Sent Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: rec'd Configure Reject #1 (Ack-Sent) Jul 16 17:26:22 ppp 76000 [wan_link0] PROTOCOMP Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: SendConfigReq #2 Jul 16 17:26:22 ppp 76000 [wan_link0] MRU 1492 Jul 16 17:26:22 ppp 76000 [wan_link0] MAGICNUM 0x03916120 Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: rec'd Configure Ack #2 (Ack-Sent) Jul 16 17:26:22 ppp 76000 [wan_link0] MRU 1492 Jul 16 17:26:22 ppp 76000 [wan_link0] MAGICNUM 0x03916120 Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: state change Ack-Sent --> Opened Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: auth: peer wants PAP, I want nothing Jul 16 17:26:22 ppp 76000 [wan_link0] PAP: using authname "paulwedde@snap.net.nz" Jul 16 17:26:22 ppp 76000 [wan_link0] PAP: sending REQUEST #1 len: 39 Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: LayerUp Jul 16 17:26:22 ppp 76000 [wan_link0] PAP: rec'd ACK #1 len: 13 Jul 16 17:26:22 ppp 76000 [wan_link0] MESG: Login ok Jul 16 17:26:22 ppp 76000 [wan_link0] LCP: authorization successful Jul 16 17:26:22 ppp 76000 [wan_link0] Link: Matched action 'bundle "wan" ""' Jul 16 17:26:22 ppp 76000 [wan_link0] Link: Join bundle "wan" Jul 16 17:26:22 ppp 76000 [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps Jul 16 17:26:22 ppp 76000 [wan] IPCP: Open event Jul 16 17:26:22 ppp 76000 [wan] IPCP: state change Initial --> Starting Jul 16 17:26:22 ppp 76000 [wan] IPCP: LayerStart Jul 16 17:26:22 ppp 76000 [wan] IPV6CP: Open event Jul 16 17:26:22 ppp 76000 [wan] IPV6CP: state change Initial --> Starting Jul 16 17:26:22 ppp 76000 [wan] IPV6CP: LayerStart Jul 16 17:26:22 ppp 76000 [wan] IPCP: Up event Jul 16 17:26:22 ppp 76000 [wan] IPCP: state change Starting --> Req-Sent Jul 16 17:26:22 ppp 76000 [wan] IPCP: SendConfigReq #1 Jul 16 17:26:22 ppp 76000 [wan] IPADDR 0.0.0.0 Jul 16 17:26:22 ppp 76000 [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Jul 16 17:26:22 ppp 76000 [wan] IPV6CP: Up event Jul 16 17:26:22 ppp 76000 [wan] IPV6CP: state change Starting --> Req-Sent Jul 16 17:26:22 ppp 76000 [wan] IPV6CP: SendConfigReq #1 Jul 16 17:26:22 ppp 76000 [wan] IPV6CP: rec'd Configure Request #130 (Req-Sent) Jul 16 17:26:22 ppp 76000 [wan] IPV6CP: SendConfigAck #130 Jul 16 17:26:22 ppp 76000 [wan] IPV6CP: state change Req-Sent --> Ack-Sent Jul 16 17:26:22 ppp 76000 [wan] IPCP: rec'd Configure Request #96 (Req-Sent) Jul 16 17:26:22 ppp 76000 [wan] IPADDR [x.x.x.x] Jul 16 17:26:22 ppp 76000 [wan] [x.x.x.x] is OK Jul 16 17:26:22 ppp 76000 [wan] IPCP: SendConfigAck #96 Jul 16 17:26:22 ppp 76000 [wan] IPADDR [x.x.x.x] Jul 16 17:26:22 ppp 76000 [wan] IPCP: state change Req-Sent --> Ack-Sent Jul 16 17:26:22 ppp 76000 [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent) Jul 16 17:26:22 ppp 76000 [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Jul 16 17:26:22 ppp 76000 [wan] IPCP: SendConfigReq #2 Jul 16 17:26:22 ppp 76000 [wan] IPADDR 0.0.0.0 Jul 16 17:26:22 ppp 76000 [wan] IPV6CP: rec'd Configure Ack #1 (Ack-Sent) Jul 16 17:26:22 ppp 76000 [wan] IPV6CP: state change Ack-Sent --> Opened Jul 16 17:26:22 ppp 76000 [wan] IPV6CP: LayerUp Jul 16 17:26:22 ppp 76000 [wan] [xxxx:xxxx:xxxx:xxxx:] -> [xxxx:xxxx:xxxx:xxxx:] Jul 16 17:26:22 check_reload_status 439 Reloading filter Jul 16 17:26:22 tail_pfb 78837 [pfBlockerNG] Firewall Filter Service stopped Jul 16 17:26:22 php_pfb 79609 [pfBlockerNG] filterlog daemon stopped Jul 16 17:26:22 php-fpm 398 [pfBlockerNG] Restarting firewall filter daemon Jul 16 17:26:22 tail_pfb 84193 [pfBlockerNG] Firewall Filter Service stopped Jul 16 17:26:22 tail_pfb 84879 [pfBlockerNG] Firewall Filter Service stopped Jul 16 17:26:22 php_pfb 85640 [pfBlockerNG] filterlog daemon stopped Jul 16 17:26:22 php_pfb 86159 [pfBlockerNG] filterlog daemon stopped Jul 16 17:26:22 tail_pfb 90527 [pfBlockerNG] Firewall Filter Service started Jul 16 17:26:22 tail_pfb 91925 [pfBlockerNG] Firewall Filter Service started Jul 16 17:26:22 php 77929 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0 Jul 16 17:26:22 php 77929 /usr/local/sbin/ppp-ipv6: Starting DHCP6 client for interfaces pppoe0 in DHCP6 without RA mode Jul 16 17:26:22 php 77929 /usr/local/sbin/ppp-ipv6: Starting rtsold process on wan(pppoe0) Jul 16 17:26:22 php_pfb 91638 [pfBlockerNG] filterlog daemon started Jul 16 17:26:22 php_pfb 92180 [pfBlockerNG] filterlog daemon started Jul 16 17:26:24 check_reload_status 439 rc.newwanipv6 starting pppoe0 Jul 16 17:26:24 ppp 76000 [wan] IFACE: Up event Jul 16 17:26:24 ppp 76000 [wan] IFACE: Rename interface ng0 to pppoe0 Jul 16 17:26:24 ppp 76000 [wan] IFACE: Add description "WAN" Jul 16 17:26:24 ppp 76000 [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent) Jul 16 17:26:24 ppp 76000 [wan] IPADDR [x.x.x.x] Jul 16 17:26:24 ppp 76000 [wan] [x.x.x.x] is OK Jul 16 17:26:24 ppp 76000 [wan] IPCP: SendConfigReq #3 Jul 16 17:26:24 ppp 76000 [wan] IPADDR [x.x.x.x] Jul 16 17:26:24 ppp 76000 [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent) Jul 16 17:26:24 ppp 76000 [wan] IPADDR [x.x.x.x] Jul 16 17:26:24 ppp 76000 [wan] IPCP: state change Ack-Sent --> Opened Jul 16 17:26:24 ppp 76000 [wan] IPCP: LayerUp Jul 16 17:26:24 ppp 76000 [wan] [x.x.x.x] -> [x.x.x.x] Jul 16 17:26:24 check_reload_status 439 rc.newwanip starting pppoe0 Jul 16 17:26:25 php-fpm 38529 /status_interfaces.php: calling interface_dhcpv6_configure. Jul 16 17:26:25 php-fpm 399 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. Jul 16 17:26:25 php-fpm 399 /rc.newwanipv6: rc.newwanipv6: on (IP address: [xxxx:xxxx:xxxx:xxxx::xxxx]) (interface: wan) (real interface: pppoe0). Jul 16 17:26:25 rtsold 27073 Received RA specifying route [fe80::xxxx:xxxx:xxxx] for interface wan(pppoe0) Jul 16 17:26:25 php-fpm 45454 /rc.newwanip: rc.newwanip: Info: starting on pppoe0. Jul 16 17:26:25 php-fpm 45454 /rc.newwanip: rc.newwanip: on (IP address: [x.x.x.x]) (interface: WAN[wan]) (real interface: pppoe0). Jul 16 17:26:26 php-fpm 38529 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. Jul 16 17:26:26 php-fpm 38529 /rc.newwanipv6: rc.newwanipv6: on (IP address: [xxxx:xxxx:xxxx:xxxx::xxxx]) (interface: wan) (real interface: pppoe0). Jul 16 17:26:27 php-fpm 45454 /rc.newwanip: The command '/usr/local/bin/dpinger -S -r 0 -i WAN_DHCP6 -B [fe80::xxxx:xxxx:xxxx]%pppoe0 -p /var/run/dpinger_WAN_DHCP6~[fe80::xxxx:xxxx:xxxx%pppoe0~fe80::xxxx:xxxx:xxxx]%pppoe0.pid -u /var/run/dpinger_WAN_DHCP6~[fe80::xxxx:xxxx:xxxx%pppoe0~fe80::xxxx:xxxx:xxxx]%pppoe0.sock -C "/etc/rc.gateway_alarm" -d 1 -s 500 -l 2000 -t 60000 -A 1000 -D 500 -L 20 [fe80::xxxx:xxxx:xxxx]%pppoe0 >/dev/null' returned exit code '1', the output was '' Jul 16 17:26:27 php-fpm 45454 /rc.newwanip: Error starting gateway monitor for WAN_DHCP6 Jul 16 17:26:27 php-fpm 399 /rc.newwanipv6: Default gateway setting Interface WAN_PPPOE Gateway as default. Jul 16 17:26:27 php-fpm 38529 /rc.newwanipv6: Default gateway setting Interface WAN_PPPOE Gateway as default. Jul 16 17:26:27 check_reload_status 439 Reloading filter Jul 16 17:26:27 check_reload_status 439 Reloading filter Jul 16 17:26:27 php-fpm 399 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. Jul 16 17:26:27 php-fpm 38529 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. Jul 16 17:26:27 php-fpm 399 /rc.newwanipv6: Creating rrd update script Jul 16 17:26:27 php-fpm 38529 /rc.newwanipv6: Creating rrd update script Jul 16 17:26:27 php-fpm 399 /rc.newwanipv6: pfSense package system has detected an IP change or dynamic WAN reconnection - -> [xxxx:xxxx:xxxx:xxxx::xxxx] - Restarting packages. Jul 16 17:26:27 check_reload_status 439 Starting packages Jul 16 17:26:27 php-fpm 38529 /rc.newwanipv6: pfSense package system has detected an IP change or dynamic WAN reconnection - -> [xxxx:xxxx:xxxx:xxxx::xxxx] - Restarting packages. Jul 16 17:26:27 check_reload_status 439 Starting packages Jul 16 17:26:27 php-fpm 45454 /rc.newwanip: Resyncing OpenVPN instances for interface WAN. Jul 16 17:26:27 php-fpm 45454 /rc.newwanip: Creating rrd update script Jul 16 17:26:28 php-fpm 399 /rc.start_packages: Restarting/Starting all packages. Jul 16 17:26:28 php-fpm 13863 /rc.start_packages: Restarting/Starting all packages. Jul 16 17:26:28 php-fpm 399 /rc.start_packages: Configuration Change: (system): pfBlockerNG: saving DNSBL changes Jul 16 17:26:28 check_reload_status 439 Syncing firewall Jul 16 17:26:28 php-fpm 13863 /rc.start_packages: Configuration Change: (system): pfBlockerNG: saving DNSBL changes Jul 16 17:26:28 check_reload_status 439 Syncing firewall Jul 16 17:26:29 php-fpm 399 /rc.start_packages: Configuration Change: (system): pfBlockerNG: saving Firewall rules Jul 16 17:26:29 php-fpm 13863 /rc.start_packages: Configuration Change: (system): pfBlockerNG: saving Firewall rules Jul 16 17:26:29 check_reload_status 439 Syncing firewall Jul 16 17:26:29 check_reload_status 439 Reloading filter Jul 16 17:26:29 check_reload_status 439 Reloading filter Jul 16 17:26:29 tail_pfb 51455 [pfBlockerNG] Firewall Filter Service stopped Jul 16 17:26:29 tail_pfb 51676 [pfBlockerNG] Firewall Filter Service stopped Jul 16 17:26:29 php_pfb 52689 [pfBlockerNG] filterlog daemon stopped Jul 16 17:26:29 php_pfb 52937 [pfBlockerNG] filterlog daemon stopped Jul 16 17:26:29 php-fpm 399 [pfBlockerNG] Restarting firewall filter daemon Jul 16 17:26:29 php-fpm 13863 [pfBlockerNG] Restarting firewall filter daemon Jul 16 17:26:29 tail_pfb 62040 [pfBlockerNG] Firewall Filter Service stopped Jul 16 17:26:29 tail_pfb 62171 [pfBlockerNG] Firewall Filter Service stopped Jul 16 17:26:29 tail_pfb 63585 [pfBlockerNG] Firewall Filter Service stopped Jul 16 17:26:29 tail_pfb 64016 [pfBlockerNG] Firewall Filter Service stopped Jul 16 17:26:29 php_pfb 65124 [pfBlockerNG] filterlog daemon stopped Jul 16 17:26:29 php_pfb 65497 [pfBlockerNG] filterlog daemon stopped Jul 16 17:26:29 php_pfb 65517 [pfBlockerNG] filterlog daemon stopped Jul 16 17:26:29 php_pfb 66642 [pfBlockerNG] filterlog daemon stopped Jul 16 17:26:29 tail_pfb 73685 [pfBlockerNG] Firewall Filter Service started Jul 16 17:26:29 tail_pfb 74107 [pfBlockerNG] Firewall Filter Service started Jul 16 17:26:29 tail_pfb 74628 [pfBlockerNG] Firewall Filter Service started Jul 16 17:26:29 tail_pfb 75647 [pfBlockerNG] Firewall Filter Service started Jul 16 17:26:30 php-fpm 45454 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - [x.x.x.x] -> [x.x.x.x] 0 - Restarting packages. Jul 16 17:26:30 check_reload_status 439 Starting packages Jul 16 17:26:30 php_pfb 75413 [pfBlockerNG] filterlog daemon started Jul 16 17:26:30 php_pfb 76255 [pfBlockerNG] filterlog daemon started Jul 16 17:26:30 php_pfb 78811 [pfBlockerNG] filterlog daemon started Jul 16 17:26:30 php_pfb 76540 [pfBlockerNG] filterlog daemon started Jul 16 17:26:31 php-fpm 13863 /rc.start_packages: Restarting/Starting all packages. Jul 16 17:26:31 SnortStartup 12698 Snort START for WAN(pppoe0)... Jul 16 17:26:31 php-fpm 13863 /rc.start_packages: Configuration Change: (system): pfBlockerNG: saving DNSBL changes Jul 16 17:26:31 check_reload_status 439 Syncing firewall Jul 16 17:26:31 kernel pppoe0: promiscuous mode enabled Jul 16 17:26:31 tail_pfb 59967 [pfBlockerNG] Firewall Filter Service stopped Jul 16 17:26:31 php_pfb 60873 [pfBlockerNG] filterlog daemon stopped Jul 16 17:26:31 tail_pfb 64326 [pfBlockerNG] Firewall Filter Service started Jul 16 17:26:31 php_pfb 64519 [pfBlockerNG] filterlog daemon startedAnd the equivalent DHCPv6 Logs:
Jul 16 17:26:17 dhcp6c 79236 exit without release Jul 16 17:26:17 dhcp6c 79236 removing an event on pppoe0, state=SOLICIT Jul 16 17:26:17 dhcp6c 79236 removing an event on pppoe0, state=SOLICIT Jul 16 17:26:17 dhcp6c 79236 executes /var/etc/dhcp6c_wan_dhcp6withoutra_script.sh Jul 16 17:26:17 dhcp6c 73451 lstat failed: No such file or directory Jul 16 17:26:17 dhcp6c 73451 script "/var/etc/dhcp6c_wan_dhcp6withoutra_script.sh" cannot be executed safely Jul 16 17:26:17 dhcp6c 79236 script "/var/etc/dhcp6c_wan_dhcp6withoutra_script.sh" terminated Jul 16 17:26:17 dhcp6c 79236 exiting Jul 16 17:26:22 dhcp6c 93223 extracted an existing DUID from /var/db/dhcp6c_duid: xxxx Jul 16 17:26:22 dhcp6c 93223 failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory Jul 16 17:26:22 dhcp6c 93223 failed initialize control message authentication Jul 16 17:26:22 dhcp6c 93223 skip opening control port Jul 16 17:26:22 dhcp6c 93223 <3>[interface] (9) Jul 16 17:26:22 dhcp6c 93223 <5>[pppoe0] (6) Jul 16 17:26:22 dhcp6c 93223 <3>begin of closure [{] (1) Jul 16 17:26:22 dhcp6c 93223 <3>[send] (4) Jul 16 17:26:22 dhcp6c 93223 <3>[ia-na] (5) Jul 16 17:26:22 dhcp6c 93223 <3>[0] (1) Jul 16 17:26:22 dhcp6c 93223 <3>end of sentence [;] (1) Jul 16 17:26:22 dhcp6c 93223 <3>comment [# request stateful address] (26) Jul 16 17:26:22 dhcp6c 93223 <3>[send] (4) Jul 16 17:26:22 dhcp6c 93223 <3>[ia-pd] (5) Jul 16 17:26:22 dhcp6c 93223 <3>[0] (1) Jul 16 17:26:22 dhcp6c 93223 <3>end of sentence [;] (1) Jul 16 17:26:22 dhcp6c 93223 <3>comment [# request prefix delegation] (27) Jul 16 17:26:22 dhcp6c 93223 <3>[request] (7) Jul 16 17:26:22 dhcp6c 93223 <3>[domain-name-servers] (19) Jul 16 17:26:22 dhcp6c 93223 <3>end of sentence [;] (1) Jul 16 17:26:22 dhcp6c 93223 <3>[request] (7) Jul 16 17:26:22 dhcp6c 93223 <3>[domain-name] (11) Jul 16 17:26:22 dhcp6c 93223 <3>end of sentence [;] (1) Jul 16 17:26:22 dhcp6c 93223 <3>[script] (6) Jul 16 17:26:22 dhcp6c 93223 <3>["/var/etc/dhcp6c_wan_dhcp6withoutra_script.sh"] (46) Jul 16 17:26:22 dhcp6c 93223 <3>end of sentence [;] (1) Jul 16 17:26:22 dhcp6c 93223 <3>comment [# we'd like nameservers and RTSOLD to do all the work] (53) Jul 16 17:26:22 dhcp6c 93223 <3>end of closure [}] (1) Jul 16 17:26:22 dhcp6c 93223 <3>end of sentence [;] (1) Jul 16 17:26:22 dhcp6c 93223 <3>[id-assoc] (8) Jul 16 17:26:22 dhcp6c 93223 <13>[na] (2) Jul 16 17:26:22 dhcp6c 93223 <13>[0] (1) Jul 16 17:26:22 dhcp6c 93223 <13>begin of closure [{] (1) Jul 16 17:26:22 dhcp6c 93223 <3>end of closure [}] (1) Jul 16 17:26:22 dhcp6c 93223 <3>end of sentence [;] (1) Jul 16 17:26:22 dhcp6c 93223 <3>[id-assoc] (8) Jul 16 17:26:22 dhcp6c 93223 <13>[pd] (2) Jul 16 17:26:22 dhcp6c 93223 <13>[0] (1) Jul 16 17:26:22 dhcp6c 93223 <13>begin of closure [{] (1) Jul 16 17:26:22 dhcp6c 93223 <3>[prefix] (6) Jul 16 17:26:22 dhcp6c 93223 <3>[::] (2) Jul 16 17:26:22 dhcp6c 93223 <3>[/] (1) Jul 16 17:26:22 dhcp6c 93223 <3>[64] (2) Jul 16 17:26:22 dhcp6c 93223 <3>[infinity] (8) Jul 16 17:26:22 dhcp6c 93223 <3>end of sentence [;] (1) Jul 16 17:26:22 dhcp6c 93223 <3>end of closure [}] (1) Jul 16 17:26:22 dhcp6c 93223 <3>end of sentence [;] (1) Jul 16 17:26:22 dhcp6c 93223 called Jul 16 17:26:22 dhcp6c 93223 called Jul 16 17:26:22 dhcp6c 93453 reset a timer on pppoe0, state=INIT, timeo=0, retrans=891 Jul 16 17:26:23 dhcp6c 93453 Sending Solicit Jul 16 17:26:23 dhcp6c 93453 a new XID (a581a) is generated Jul 16 17:26:23 dhcp6c 93453 set client ID (len 14) Jul 16 17:26:23 dhcp6c 93453 set identity association Jul 16 17:26:23 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:26:23 dhcp6c 93453 set option request (len 4) Jul 16 17:26:23 dhcp6c 93453 set IA_PD prefix Jul 16 17:26:23 dhcp6c 93453 set IA_PD Jul 16 17:26:23 dhcp6c 93453 send solicit to ff02::1:2%pppoe0 Jul 16 17:26:23 dhcp6c 93453 reset a timer on pppoe0, state=SOLICIT, timeo=0, retrans=1091 Jul 16 17:26:24 dhcp6c 93453 Sending Solicit Jul 16 17:26:24 dhcp6c 93453 set client ID (len 14) Jul 16 17:26:24 dhcp6c 93453 set identity association Jul 16 17:26:24 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:26:24 dhcp6c 93453 set option request (len 4) Jul 16 17:26:24 dhcp6c 93453 set IA_PD prefix Jul 16 17:26:24 dhcp6c 93453 set IA_PD Jul 16 17:26:24 dhcp6c 93453 send solicit to ff02::1:2%pppoe0 Jul 16 17:26:24 dhcp6c 93453 reset a timer on pppoe0, state=SOLICIT, timeo=1, retrans=2083 Jul 16 17:26:24 dhcp6c 93453 receive advertise from [fe80::xxxx:xxxx:xxxx]%pppoe0 on pppoe0 Jul 16 17:26:24 dhcp6c 93453 get DHCP option server ID, len 10 Jul 16 17:26:24 dhcp6c 93453 DUID: xxx Jul 16 17:26:24 dhcp6c 93453 get DHCP option client ID, len 14 Jul 16 17:26:24 dhcp6c 93453 DUID: xxx Jul 16 17:26:24 dhcp6c 93453 get DHCP option identity association, len 40 Jul 16 17:26:24 dhcp6c 93453 IA_NA: ID=0, T1=300, T2=480 Jul 16 17:26:24 dhcp6c 93453 get DHCP option IA address, len 24 Jul 16 17:26:24 dhcp6c 93453 IA_NA address: [xxxx:xxxx:xxxx:xxxx::xxxx] pltime=600 vltime=600 Jul 16 17:26:24 dhcp6c 93453 get DHCP option IA_PD, len 41 Jul 16 17:26:24 dhcp6c 93453 IA_PD: ID=0, T1=300, T2=480 Jul 16 17:26:24 dhcp6c 93453 get DHCP option IA_PD prefix, len 25 Jul 16 17:26:24 dhcp6c 93453 IA_PD prefix: [xxxx:xxxx:xxxx:xxxx::]/64 pltime=600 vltime=17984653545969812056 Jul 16 17:26:24 dhcp6c 93453 server ID: xxx, pref=-1 Jul 16 17:26:24 dhcp6c 93453 reset timer for pppoe0 to 0.997789 Jul 16 17:26:25 dhcp6c 93453 picked a server (ID: xxx) Jul 16 17:26:25 dhcp6c 93453 Sending Request Jul 16 17:26:25 dhcp6c 93453 a new XID (872565) is generated Jul 16 17:26:25 dhcp6c 93453 set client ID (len 14) Jul 16 17:26:25 dhcp6c 93453 set server ID (len 10) Jul 16 17:26:25 dhcp6c 93453 set IA address Jul 16 17:26:25 dhcp6c 93453 set identity association Jul 16 17:26:25 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:26:25 dhcp6c 93453 set option request (len 4) Jul 16 17:26:25 dhcp6c 93453 set IA_PD prefix Jul 16 17:26:25 dhcp6c 93453 set IA_PD Jul 16 17:26:25 dhcp6c 93453 send request to ff02::1:2%pppoe0 Jul 16 17:26:25 dhcp6c 93453 reset a timer on pppoe0, state=REQUEST, timeo=0, retrans=911 Jul 16 17:26:25 dhcp6c 93453 receive reply from [fe80::xxxx:xxxx:xxxx]%pppoe0 on pppoe0 Jul 16 17:26:25 dhcp6c 93453 get DHCP option server ID, len 10 Jul 16 17:26:25 dhcp6c 93453 DUID: xxx Jul 16 17:26:25 dhcp6c 93453 get DHCP option client ID, len 14 Jul 16 17:26:25 dhcp6c 93453 DUID: xxx Jul 16 17:26:25 dhcp6c 93453 get DHCP option identity association, len 40 Jul 16 17:26:25 dhcp6c 93453 IA_NA: ID=0, T1=300, T2=480 Jul 16 17:26:25 dhcp6c 93453 get DHCP option IA address, len 24 Jul 16 17:26:25 dhcp6c 93453 IA_NA address: [xxxx:xxxx:xxxx:xxxx::xxxx] pltime=600 vltime=600 Jul 16 17:26:25 dhcp6c 93453 get DHCP option IA_PD, len 41 Jul 16 17:26:25 dhcp6c 93453 IA_PD: ID=0, T1=300, T2=480 Jul 16 17:26:25 dhcp6c 93453 get DHCP option IA_PD prefix, len 25 Jul 16 17:26:25 dhcp6c 93453 IA_PD prefix: [xxxx:xxxx:xxxx:xxxx::]/64 pltime=600 vltime=17984653545969812056 Jul 16 17:26:25 dhcp6c 93453 dhcp6c Received REQUEST Jul 16 17:26:25 dhcp6c 93453 make an IA: PD-0 Jul 16 17:26:25 dhcp6c 93453 create a prefix [xxxx:xxxx:xxxx:xxxx::]/64 pltime=600, vltime=600 Jul 16 17:26:25 dhcp6c 93453 make an IA: NA-0 Jul 16 17:26:25 dhcp6c 93453 create an address [xxxx:xxxx:xxxx:xxxx::xxxx] pltime=600, vltime=34359738968 Jul 16 17:26:25 dhcp6c 93453 add an address [xxxx:xxxx:xxxx:xxxx::xxxx]/128 on pppoe0 Jul 16 17:26:25 dhcp6c 93453 executes /var/etc/dhcp6c_wan_dhcp6withoutra_script.sh Jul 16 17:26:25 dhcp6c 24167 dhcp6c REQUEST on pppoe0 - running rtsold Jul 16 17:26:25 dhcp6c 93453 script "/var/etc/dhcp6c_wan_dhcp6withoutra_script.sh" terminated Jul 16 17:26:25 dhcp6c 93453 removing an event on pppoe0, state=REQUEST Jul 16 17:26:25 dhcp6c 93453 removing server (ID: xxx) Jul 16 17:26:25 dhcp6c 93453 got an expected reply, sleeping. -
And here are the logs for 10 minutes later when the IPv6 is dropped and the Interface never recovers -
System Logs
Jul 16 17:36:41 rc.gateway_alarm 99403 >>> Gateway alarm: WAN_DHCP6 (Addr:[fe80::xxx:xxxx:xxxx:xxxx]%pppoe0 Alarm:1 RTT:1.447ms RTTsd:.421ms Loss:21%) Jul 16 17:36:41 check_reload_status 439 updating dyndns WAN_DHCP6 Jul 16 17:36:41 check_reload_status 439 Restarting IPsec tunnels Jul 16 17:36:41 check_reload_status 439 Restarting OpenVPN tunnels/interfaces Jul 16 17:36:41 check_reload_status 439 Reloading filter Jul 16 17:38:33 rtsold 98738 Received RA specifying route [fe80::xxx:xxxx:xxxx:xxxx] for interface wan(pppoe0) Jul 16 17:38:34 php-fpm 45454 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. Jul 16 17:38:34 php-fpm 45454 /rc.newwanipv6: rc.newwanipv6: on (IP address: [NEW IPv6 Address]) (interface: wan) (real interface: pppoe0). Jul 16 17:38:35 check_reload_status 439 Reloading filter Jul 16 17:38:35 php-fpm 45454 /rc.newwanipv6: The command '/sbin/ifconfig pppoe0 inet6 [OLD IPv6 Address] delete' returned exit code '1', the output was 'ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address' Jul 16 17:38:35 php-fpm 45454 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. Jul 16 17:38:35 php-fpm 45454 /rc.newwanipv6: Creating rrd update script Jul 16 17:38:35 php-fpm 45454 /rc.newwanipv6: pfSense package system has detected an IP change or dynamic WAN reconnection - [OLD IPv6 Address] -> [NEW IPv6 Address] - Restarting packages. Jul 16 17:38:35 check_reload_status 439 Starting packages Jul 16 17:38:35 check_reload_status 439 Reloading filter Jul 16 17:38:36 php-fpm 399 /rc.start_packages: Restarting/Starting all packages. Jul 16 17:38:36 php-fpm 399 /rc.start_packages: Configuration Change: (system): pfBlockerNG: saving DNSBL changes Jul 16 17:38:36 check_reload_status 439 Syncing firewall Jul 16 17:38:37 tail_pfb 73078 [pfBlockerNG] Firewall Filter Service stopped Jul 16 17:38:37 php_pfb 74496 [pfBlockerNG] filterlog daemon stopped Jul 16 17:38:37 tail_pfb 82097 [pfBlockerNG] Firewall Filter Service started Jul 16 17:38:37 php_pfb 82636 [pfBlockerNG] filterlog daemon started Jul 16 17:38:46 rtsold 54756 Received RA specifying route [fe80::xxx:xxxx:xxxx:xxxx] for interface wan(pppoe0) Jul 16 17:38:47 php-fpm 38529 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. Jul 16 17:38:47 php-fpm 38529 /rc.newwanipv6: rc.newwanipv6: on (IP address: [NEW IPv6 Address]) (interface: wan) (real interface: pppoe0). Jul 16 17:38:48 check_reload_status 439 Reloading filter Jul 16 17:38:48 php-fpm 38529 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. Jul 16 17:38:48 check_reload_status 439 Reloading filterDHCP6c Debug Logs:
Jul 16 17:31:25 dhcp6c 93453 IA timeout for NA-0, state=ACTIVE Jul 16 17:31:25 dhcp6c 93453 reset a timer on pppoe0, state=RENEW, timeo=0, retrans=10256 Jul 16 17:31:25 dhcp6c 93453 Sending Renew Jul 16 17:31:25 dhcp6c 93453 a new XID (9e65a3) is generated Jul 16 17:31:25 dhcp6c 93453 set client ID (len 14) Jul 16 17:31:25 dhcp6c 93453 set server ID (len 10) Jul 16 17:31:25 dhcp6c 93453 set IA address Jul 16 17:31:25 dhcp6c 93453 set identity association Jul 16 17:31:25 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:31:25 dhcp6c 93453 set option request (len 4) Jul 16 17:31:25 dhcp6c 93453 send renew to ff02::1:2%pppoe0 Jul 16 17:31:25 dhcp6c 93453 IA timeout for PD-0, state=ACTIVE Jul 16 17:31:25 dhcp6c 93453 reset a timer on pppoe0, state=RENEW, timeo=0, retrans=10244 Jul 16 17:31:25 dhcp6c 93453 Sending Renew Jul 16 17:31:25 dhcp6c 93453 a new XID (4cb9b4) is generated Jul 16 17:31:25 dhcp6c 93453 set client ID (len 14) Jul 16 17:31:25 dhcp6c 93453 set server ID (len 10) Jul 16 17:31:25 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:31:25 dhcp6c 93453 set option request (len 4) Jul 16 17:31:25 dhcp6c 93453 set IA_PD prefix Jul 16 17:31:25 dhcp6c 93453 set IA_PD Jul 16 17:31:25 dhcp6c 93453 send renew to ff02::1:2%pppoe0 Jul 16 17:31:35 dhcp6c 93453 Sending Renew Jul 16 17:31:35 dhcp6c 93453 set client ID (len 14) Jul 16 17:31:35 dhcp6c 93453 set server ID (len 10) Jul 16 17:31:35 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:31:35 dhcp6c 93453 set option request (len 4) Jul 16 17:31:35 dhcp6c 93453 set IA_PD prefix Jul 16 17:31:35 dhcp6c 93453 set IA_PD Jul 16 17:31:35 dhcp6c 93453 send renew to ff02::1:2%pppoe0 Jul 16 17:31:35 dhcp6c 93453 reset a timer on pppoe0, state=RENEW, timeo=1, retrans=20034 Jul 16 17:31:35 dhcp6c 93453 Sending Renew Jul 16 17:31:35 dhcp6c 93453 set client ID (len 14) Jul 16 17:31:35 dhcp6c 93453 set server ID (len 10) Jul 16 17:31:35 dhcp6c 93453 set IA address Jul 16 17:31:35 dhcp6c 93453 set identity association Jul 16 17:31:35 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:31:35 dhcp6c 93453 set option request (len 4) Jul 16 17:31:35 dhcp6c 93453 send renew to ff02::1:2%pppoe0 Jul 16 17:31:35 dhcp6c 93453 reset a timer on pppoe0, state=RENEW, timeo=1, retrans=20708 Jul 16 17:31:56 dhcp6c 93453 Sending Renew Jul 16 17:31:56 dhcp6c 93453 set client ID (len 14) Jul 16 17:31:56 dhcp6c 93453 set server ID (len 10) Jul 16 17:31:56 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:31:56 dhcp6c 93453 set option request (len 4) Jul 16 17:31:56 dhcp6c 93453 set IA_PD prefix Jul 16 17:31:56 dhcp6c 93453 set IA_PD Jul 16 17:31:56 dhcp6c 93453 send renew to ff02::1:2%pppoe0 Jul 16 17:31:56 dhcp6c 93453 reset a timer on pppoe0, state=RENEW, timeo=2, retrans=39893 Jul 16 17:31:56 dhcp6c 93453 Sending Renew Jul 16 17:31:56 dhcp6c 93453 set client ID (len 14) Jul 16 17:31:56 dhcp6c 93453 set server ID (len 10) Jul 16 17:31:56 dhcp6c 93453 set IA address Jul 16 17:31:56 dhcp6c 93453 set identity association Jul 16 17:31:56 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:31:56 dhcp6c 93453 set option request (len 4) Jul 16 17:31:56 dhcp6c 93453 send renew to ff02::1:2%pppoe0 Jul 16 17:31:56 dhcp6c 93453 reset a timer on pppoe0, state=RENEW, timeo=2, retrans=40140 Jul 16 17:32:35 dhcp6c 93453 Sending Renew Jul 16 17:32:35 dhcp6c 93453 set client ID (len 14) Jul 16 17:32:35 dhcp6c 93453 set server ID (len 10) Jul 16 17:32:35 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:32:35 dhcp6c 93453 set option request (len 4) Jul 16 17:32:35 dhcp6c 93453 set IA_PD prefix Jul 16 17:32:35 dhcp6c 93453 set IA_PD Jul 16 17:32:35 dhcp6c 93453 send renew to ff02::1:2%pppoe0 Jul 16 17:32:35 dhcp6c 93453 reset a timer on pppoe0, state=RENEW, timeo=3, retrans=80895 Jul 16 17:32:36 dhcp6c 93453 Sending Renew Jul 16 17:32:36 dhcp6c 93453 set client ID (len 14) Jul 16 17:32:36 dhcp6c 93453 set server ID (len 10) Jul 16 17:32:36 dhcp6c 93453 set IA address Jul 16 17:32:36 dhcp6c 93453 set identity association Jul 16 17:32:36 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:32:36 dhcp6c 93453 set option request (len 4) Jul 16 17:32:36 dhcp6c 93453 send renew to ff02::1:2%pppoe0 Jul 16 17:32:36 dhcp6c 93453 reset a timer on pppoe0, state=RENEW, timeo=3, retrans=77269 Jul 16 17:33:54 dhcp6c 93453 Sending Renew Jul 16 17:33:54 dhcp6c 93453 set client ID (len 14) Jul 16 17:33:54 dhcp6c 93453 set server ID (len 10) Jul 16 17:33:54 dhcp6c 93453 set IA address Jul 16 17:33:54 dhcp6c 93453 set identity association Jul 16 17:33:54 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:33:54 dhcp6c 93453 set option request (len 4) Jul 16 17:33:54 dhcp6c 93453 send renew to ff02::1:2%pppoe0 Jul 16 17:33:54 dhcp6c 93453 reset a timer on pppoe0, state=RENEW, timeo=4, retrans=155001 Jul 16 17:33:56 dhcp6c 93453 Sending Renew Jul 16 17:33:56 dhcp6c 93453 set client ID (len 14) Jul 16 17:33:56 dhcp6c 93453 set server ID (len 10) Jul 16 17:33:56 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:33:56 dhcp6c 93453 set option request (len 4) Jul 16 17:33:56 dhcp6c 93453 set IA_PD prefix Jul 16 17:33:56 dhcp6c 93453 set IA_PD Jul 16 17:33:56 dhcp6c 93453 send renew to ff02::1:2%pppoe0 Jul 16 17:33:56 dhcp6c 93453 reset a timer on pppoe0, state=RENEW, timeo=4, retrans=154040 Jul 16 17:34:25 dhcp6c 93453 IA timeout for NA-0, state=RENEW Jul 16 17:34:25 dhcp6c 93453 reset a timer on pppoe0, state=REBIND, timeo=0, retrans=9245 Jul 16 17:34:25 dhcp6c 93453 Sending Rebind Jul 16 17:34:25 dhcp6c 93453 a new XID (4e5a83) is generated Jul 16 17:34:25 dhcp6c 93453 set client ID (len 14) Jul 16 17:34:25 dhcp6c 93453 set IA address Jul 16 17:34:25 dhcp6c 93453 set identity association Jul 16 17:34:25 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:34:25 dhcp6c 93453 set option request (len 4) Jul 16 17:34:25 dhcp6c 93453 send rebind to ff02::1:2%pppoe0 Jul 16 17:34:25 dhcp6c 93453 IA timeout for PD-0, state=RENEW Jul 16 17:34:25 dhcp6c 93453 reset a timer on pppoe0, state=REBIND, timeo=0, retrans=9832 Jul 16 17:34:25 dhcp6c 93453 Sending Rebind Jul 16 17:34:25 dhcp6c 93453 a new XID (b44aee) is generated Jul 16 17:34:25 dhcp6c 93453 set client ID (len 14) Jul 16 17:34:25 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:34:25 dhcp6c 93453 set option request (len 4) Jul 16 17:34:25 dhcp6c 93453 set IA_PD prefix Jul 16 17:34:25 dhcp6c 93453 set IA_PD Jul 16 17:34:25 dhcp6c 93453 send rebind to ff02::1:2%pppoe0 Jul 16 17:34:34 dhcp6c 93453 Sending Rebind Jul 16 17:34:34 dhcp6c 93453 set client ID (len 14) Jul 16 17:34:34 dhcp6c 93453 set IA address Jul 16 17:34:34 dhcp6c 93453 set identity association Jul 16 17:34:34 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:34:34 dhcp6c 93453 set option request (len 4) Jul 16 17:34:34 dhcp6c 93453 send rebind to ff02::1:2%pppoe0 Jul 16 17:34:34 dhcp6c 93453 reset a timer on pppoe0, state=REBIND, timeo=1, retrans=18333 Jul 16 17:34:35 dhcp6c 93453 Sending Rebind Jul 16 17:34:35 dhcp6c 93453 set client ID (len 14) Jul 16 17:34:35 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:34:35 dhcp6c 93453 set option request (len 4) Jul 16 17:34:35 dhcp6c 93453 set IA_PD prefix Jul 16 17:34:35 dhcp6c 93453 set IA_PD Jul 16 17:34:35 dhcp6c 93453 send rebind to ff02::1:2%pppoe0 Jul 16 17:34:35 dhcp6c 93453 reset a timer on pppoe0, state=REBIND, timeo=1, retrans=18742 Jul 16 17:34:53 dhcp6c 93453 Sending Rebind Jul 16 17:34:53 dhcp6c 93453 set client ID (len 14) Jul 16 17:34:53 dhcp6c 93453 set IA address Jul 16 17:34:53 dhcp6c 93453 set identity association Jul 16 17:34:53 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:34:53 dhcp6c 93453 set option request (len 4) Jul 16 17:34:53 dhcp6c 93453 send rebind to ff02::1:2%pppoe0 Jul 16 17:34:53 dhcp6c 93453 reset a timer on pppoe0, state=REBIND, timeo=2, retrans=36526 Jul 16 17:34:54 dhcp6c 93453 Sending Rebind Jul 16 17:34:54 dhcp6c 93453 set client ID (len 14) Jul 16 17:34:54 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:34:54 dhcp6c 93453 set option request (len 4) Jul 16 17:34:54 dhcp6c 93453 set IA_PD prefix Jul 16 17:34:54 dhcp6c 93453 set IA_PD Jul 16 17:34:54 dhcp6c 93453 send rebind to ff02::1:2%pppoe0 Jul 16 17:34:54 dhcp6c 93453 reset a timer on pppoe0, state=REBIND, timeo=2, retrans=37305 Jul 16 17:35:29 dhcp6c 93453 Sending Rebind Jul 16 17:35:29 dhcp6c 93453 set client ID (len 14) Jul 16 17:35:29 dhcp6c 93453 set IA address Jul 16 17:35:29 dhcp6c 93453 set identity association Jul 16 17:35:29 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:35:29 dhcp6c 93453 set option request (len 4) Jul 16 17:35:29 dhcp6c 93453 send rebind to ff02::1:2%pppoe0 Jul 16 17:35:29 dhcp6c 93453 reset a timer on pppoe0, state=REBIND, timeo=3, retrans=69545 Jul 16 17:35:31 dhcp6c 93453 Sending Rebind Jul 16 17:35:31 dhcp6c 93453 set client ID (len 14) Jul 16 17:35:31 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:35:31 dhcp6c 93453 set option request (len 4) Jul 16 17:35:31 dhcp6c 93453 set IA_PD prefix Jul 16 17:35:31 dhcp6c 93453 set IA_PD Jul 16 17:35:31 dhcp6c 93453 send rebind to ff02::1:2%pppoe0 Jul 16 17:35:31 dhcp6c 93453 reset a timer on pppoe0, state=REBIND, timeo=3, retrans=77631 [From here is almost 10 minutes (9 minutes and 54s) from when the previous lease was acquired] Jul 16 17:36:25 dhcp6c 93453 address timeout for [OLD IPv6 Address] Jul 16 17:36:25 dhcp6c 93453 remove an address [OLD IPv6 Address] Jul 16 17:36:25 dhcp6c 93453 remove an address [OLD IPv6 Address]/128 on pppoe0 Jul 16 17:36:25 dhcp6c 93453 IA NA-0 is invalidated Jul 16 17:36:25 dhcp6c 93453 remove an IA: NA-0 Jul 16 17:36:25 dhcp6c 93453 reset a timer on pppoe0, state=INIT, timeo=0, retrans=288 Jul 16 17:36:25 dhcp6c 93453 prefix timeout for [IPv6 Delegated Prefix]::/64 Jul 16 17:36:25 dhcp6c 93453 remove a site prefix [IPv6 Delegated Prefix]::/64 Jul 16 17:36:25 dhcp6c 93453 IA PD-0 is invalidated Jul 16 17:36:25 dhcp6c 93453 remove an IA: PD-0 Jul 16 17:36:25 dhcp6c 93453 reset a timer on pppoe0, state=INIT, timeo=0, retrans=843 Jul 16 17:36:26 dhcp6c 93453 Sending Solicit Jul 16 17:36:26 dhcp6c 93453 a new XID (c66ca2) is generated Jul 16 17:36:26 dhcp6c 93453 set client ID (len 14) Jul 16 17:36:26 dhcp6c 93453 set identity association Jul 16 17:36:26 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:36:26 dhcp6c 93453 set option request (len 4) Jul 16 17:36:26 dhcp6c 93453 set IA_PD prefix Jul 16 17:36:26 dhcp6c 93453 set IA_PD Jul 16 17:36:26 dhcp6c 93453 send solicit to ff02::1:2%pppoe0 Jul 16 17:36:26 dhcp6c 93453 reset a timer on pppoe0, state=SOLICIT, timeo=0, retrans=1071 Jul 16 17:36:26 dhcp6c 93453 Sending Solicit Jul 16 17:36:26 dhcp6c 93453 a new XID (318b1c) is generated Jul 16 17:36:26 dhcp6c 93453 set client ID (len 14) Jul 16 17:36:26 dhcp6c 93453 set identity association Jul 16 17:36:26 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:36:26 dhcp6c 93453 set option request (len 4) Jul 16 17:36:26 dhcp6c 93453 set IA_PD prefix Jul 16 17:36:26 dhcp6c 93453 set IA_PD Jul 16 17:36:26 dhcp6c 93453 send solicit to ff02::1:2%pppoe0 Jul 16 17:36:26 dhcp6c 93453 reset a timer on pppoe0, state=SOLICIT, timeo=0, retrans=1024 Jul 16 17:36:27 dhcp6c 93453 Sending Solicit Jul 16 17:36:27 dhcp6c 93453 set client ID (len 14) Jul 16 17:36:27 dhcp6c 93453 set identity association Jul 16 17:36:27 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:36:27 dhcp6c 93453 set option request (len 4) Jul 16 17:36:27 dhcp6c 93453 set IA_PD prefix Jul 16 17:36:27 dhcp6c 93453 set IA_PD Jul 16 17:36:27 dhcp6c 93453 send solicit to ff02::1:2%pppoe0 Jul 16 17:36:27 dhcp6c 93453 reset a timer on pppoe0, state=SOLICIT, timeo=1, retrans=2222 Jul 16 17:36:27 dhcp6c 93453 Sending Solicit Jul 16 17:36:27 dhcp6c 93453 set client ID (len 14) Jul 16 17:36:27 dhcp6c 93453 set identity association Jul 16 17:36:27 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:36:27 dhcp6c 93453 set option request (len 4) Jul 16 17:36:27 dhcp6c 93453 set IA_PD prefix Jul 16 17:36:27 dhcp6c 93453 set IA_PD Jul 16 17:36:27 dhcp6c 93453 send solicit to ff02::1:2%pppoe0 Jul 16 17:36:27 dhcp6c 93453 reset a timer on pppoe0, state=SOLICIT, timeo=1, retrans=1992 Jul 16 17:36:29 dhcp6c 93453 all information to be updated was canceled Jul 16 17:36:29 dhcp6c 93453 removing an event on pppoe0, state=RENEW Jul 16 17:36:29 dhcp6c 93453 Sending Solicit Jul 16 17:36:29 dhcp6c 93453 set client ID (len 14) Jul 16 17:36:29 dhcp6c 93453 set identity association Jul 16 17:36:29 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:36:29 dhcp6c 93453 set option request (len 4) Jul 16 17:36:29 dhcp6c 93453 set IA_PD prefix Jul 16 17:36:29 dhcp6c 93453 set IA_PD Jul 16 17:36:29 dhcp6c 93453 send solicit to ff02::1:2%pppoe0 Jul 16 17:36:29 dhcp6c 93453 reset a timer on pppoe0, state=SOLICIT, timeo=2, retrans=4305 Jul 16 17:36:29 dhcp6c 93453 Sending Solicit Jul 16 17:36:29 dhcp6c 93453 set client ID (len 14) Jul 16 17:36:29 dhcp6c 93453 set identity association Jul 16 17:36:29 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:36:29 dhcp6c 93453 set option request (len 4) Jul 16 17:36:29 dhcp6c 93453 set IA_PD prefix Jul 16 17:36:29 dhcp6c 93453 set IA_PD Jul 16 17:36:29 dhcp6c 93453 send solicit to ff02::1:2%pppoe0 Jul 16 17:36:29 dhcp6c 93453 reset a timer on pppoe0, state=SOLICIT, timeo=2, retrans=3810 Jul 16 17:36:30 dhcp6c 93453 all information to be updated was canceled Jul 16 17:36:30 dhcp6c 93453 removing an event on pppoe0, state=RENEW Jul 16 17:36:33 dhcp6c 93453 Sending Solicit Jul 16 17:36:33 dhcp6c 93453 set client ID (len 14) Jul 16 17:36:33 dhcp6c 93453 set identity association Jul 16 17:36:33 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:36:33 dhcp6c 93453 set option request (len 4) Jul 16 17:36:33 dhcp6c 93453 set IA_PD prefix Jul 16 17:36:33 dhcp6c 93453 set IA_PD Jul 16 17:36:33 dhcp6c 93453 send solicit to ff02::1:2%pppoe0 Jul 16 17:36:33 dhcp6c 93453 reset a timer on pppoe0, state=SOLICIT, timeo=3, retrans=7611 Jul 16 17:36:33 dhcp6c 93453 Sending Solicit Jul 16 17:36:33 dhcp6c 93453 set client ID (len 14) Jul 16 17:36:33 dhcp6c 93453 set identity association Jul 16 17:36:33 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:36:33 dhcp6c 93453 set option request (len 4) Jul 16 17:36:33 dhcp6c 93453 set IA_PD prefix Jul 16 17:36:33 dhcp6c 93453 set IA_PD Jul 16 17:36:33 dhcp6c 93453 send solicit to ff02::1:2%pppoe0 Jul 16 17:36:33 dhcp6c 93453 reset a timer on pppoe0, state=SOLICIT, timeo=3, retrans=8876 Jul 16 17:36:39 dhcp6c 93453 all information to be updated was canceled Jul 16 17:36:39 dhcp6c 93453 removing an event on pppoe0, state=REBIND Jul 16 17:36:41 dhcp6c 93453 Sending Solicit Jul 16 17:36:41 dhcp6c 93453 set client ID (len 14) Jul 16 17:36:41 dhcp6c 93453 set identity association Jul 16 17:36:41 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:36:41 dhcp6c 93453 set option request (len 4) Jul 16 17:36:41 dhcp6c 93453 set IA_PD prefix Jul 16 17:36:41 dhcp6c 93453 set IA_PD Jul 16 17:36:41 dhcp6c 93453 send solicit to ff02::1:2%pppoe0 Jul 16 17:36:41 dhcp6c 93453 reset a timer on pppoe0, state=SOLICIT, timeo=4, retrans=15518 Jul 16 17:36:42 dhcp6c 93453 Sending Solicit Jul 16 17:36:42 dhcp6c 93453 set client ID (len 14) Jul 16 17:36:42 dhcp6c 93453 set identity association Jul 16 17:36:42 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:36:42 dhcp6c 93453 set option request (len 4) Jul 16 17:36:42 dhcp6c 93453 set IA_PD prefix Jul 16 17:36:42 dhcp6c 93453 set IA_PD Jul 16 17:36:42 dhcp6c 93453 send solicit to ff02::1:2%pppoe0 Jul 16 17:36:42 dhcp6c 93453 reset a timer on pppoe0, state=SOLICIT, timeo=4, retrans=17814 Jul 16 17:36:49 dhcp6c 93453 all information to be updated was canceled Jul 16 17:36:49 dhcp6c 93453 removing an event on pppoe0, state=REBIND Jul 16 17:36:56 dhcp6c 93453 Sending Solicit Jul 16 17:36:56 dhcp6c 93453 set client ID (len 14) Jul 16 17:36:56 dhcp6c 93453 set identity association Jul 16 17:36:56 dhcp6c 93453 set elapsed time (len 2) Jul 16 17:36:56 dhcp6c 93453 set option request (len 4) Jul 16 17:36:56 dhcp6c 93453 set IA_PD prefix Jul 16 17:36:56 dhcp6c 93453 set IA_PD Jul 16 17:36:56 dhcp6c 93453 send solicit to ff02::1:2%pppoe0 Jul 16 17:36:56 dhcp6c 93453 reset a timer on pppoe0, state=SOLICIT, timeo=5, retrans=32179 Jul 16 17:37:00 dhcp6c 93453 Sending Solicit Jul 16 17:37:00 dhcp6c 93453 set client ID (len 14) Jul 16 17:37:00 dhcp6c 93453 set identity association -
I've tried turning off gateway monitoring and that didn't make a difference.
-
here you were inserting this line :
@YoLo88 said in Local ISP weird behaviour w/ IPv6 via DHCP6:
[From here is almost 10 minutes (9 minutes and 54s) from when the previous lease was acquired]
the logs were still showing showing that the dhcp6c client was trying hard to get a DHCP6 lease.
First 4 x times a time out while in RENEW mode. RENEW means here : the dhcp6c client ask for a renewal of the info (lease) it already has. This is the normal sequence. See below for what I have.Then, after several falures (probably : no answer from the server) it start to go one level lower, and rebuild the entire connection, it enters the REBIND phase, which means : it will ask for an all new DHCP6 lease. If that is done every 10 minutes, then that is pretty in the IPv4 days.
You didn't show the log lines where it eventually got eventually a valid DHCP6 lease ?
It was already on the third retry when REBINDing .....If this happens with IPv6, then consider that catastrophic. Changing IPv6 WAN info (and prefixes for the LAns) every 10 minutes == not good.
Renewing the DHCP6 info on WAN every 10 minutes isn't unusual, though.
Here are mine :
That's every 5 minutes ! (so lucky you).
But fater 5 minutes the dhcp6c client did got an answer from my upstream DHCP6 server (it 'lives' in my ISP router box, 50 cm away from pfSense).
I cant' tell why this need to be done every 5 minutes, but ok, guess I have to hit the "learn" button in a nearby future ;)Your issue is : it managed to get a 10 minutes DHCP6 lease ones.
And renewal is nearly impossible ....Is it something like : after the DHPC6 lease duration time out this also impacts the lower level connection : the pppoe link ? If something happens with the pppoe link, then yeah, DHCP6 won't work, the server can't be reached, it will try, retry retyr up until the pppoe comes back again, and so on.
I'm just brainstorming here. -
@Gertjan said in Local ISP weird behaviour w/ IPv6 via DHCP6:
You didn't show the log lines where it eventually got eventually a valid DHCP6 lease ?
Thank you very much for your response!!
Those were the first set of logs @17:26. It only get's a valid IPv6 lease if I disconnect/reconnect the WAN interface via the WebUI. And it reliably does get an IPv6 address every time I do this. and then.... 10 minutes later it drops and never recovers.
This must be a setting somewhere to replicate how the Fritz box was getting IPv6 because that would ... just ... work.
-
@YoLo88 said in Local ISP weird behaviour w/ IPv6 via DHCP6:
send renew to ff02::1:2%pppoe0
Is the problem this PPPoE IPv6 address - "ff02::1:2%pppoe0"
Jul 18 09:57:49 dhcp6c 86580 Sending Solicit Jul 18 09:57:49 dhcp6c 86580 set client ID (len 14) Jul 18 09:57:49 dhcp6c 86580 set identity association Jul 18 09:57:49 dhcp6c 86580 set elapsed time (len 2) Jul 18 09:57:49 dhcp6c 86580 set option request (len 4) Jul 18 09:57:49 dhcp6c 86580 set IA_PD prefix Jul 18 09:57:49 dhcp6c 86580 set IA_PD Jul 18 09:57:49 dhcp6c 86580 send solicit to ff02::1:2%pppoe0 Jul 18 09:57:49 dhcp6c 86580 reset a timer on pppoe0, state=SOLICIT, timeo=1135, retrans=108036Where the hell does that come from? I can't ping it and it doesn't look like it relates to either the fe80 link local addressing or real IPv6 addressing that I'm getting from my ISP...
-
Ahh, FF02::1 is Link-local multicast address All nodes (broadcast)
-
As this is IPV6 and IPv4 over PPPoE, did you set a MTU value less then 1500 ?
This one :
@YoLo88 said in Local ISP weird behaviour w/ IPv6 via DHCP6:
Jul 16 17:36:41 rc.gateway_alarm 99403 >>> Gateway alarm: WAN_DHCP6 (Addr:[fe80::xxx:xxxx:xxxx:xxxx]%pppoe0 Alarm:1 RTT:1.447ms RTTsd:.421ms Loss:21%)
is strange.
When the 10 minute DHCP6 lease is over, the IP6 info is still valid. Lease renewal starts to happen half way the lease duration. That is, DHCP4 works like that. When a device receives a DHCP4 lease valid for 6 hours, renewal start at 3 hours.
If that is the same for IPv6, then why ..... there is a gateway alarm = ping6 doesn't pass anymore.
I'm pretty sure that has nothing to do with the DHCP6 lease renewal.
Was the pppoe interface already reset before that gateway alarm line .
The pppoe connection itself went bad ? The pppoe renewal is a slow process. And while that's in progress, the IPv6 that goes over it can't be created.Does the IPv4 use the same pppoe connection ? IPv4 doesn't complain / stays in a working condition ?
I'm just brainstorming here. It's years now my ISP left pppoe for what is was : perfect for the waste bin.
-
@Gertjan Thanks again for your input. Much appreciated.
The MTU appears to set itself to 1492
I tried disabling gateway monitoring but it didn't make any difference.
IPv4 and IPv6 are sharing the same PPPoE connection yes, I have the "Use IPv4 connectivity as parent interface" - "Request a IPv6 prefix/information through the IPv4 connectivity link" option ticked and yes IPv4 is fine. It renews without a problem.
My ISP is garbage for tech support. I can't get anyone even remotely technical to speak to me. They just tell me to put the Fritz box back on there or it's my problem to figure out which is kind of fair enough. This IPv6 connection is stable on Fritzbox but not on PFSense. Therefore, it must be a setting in PFSense that I can tweak to fix the stability.
-
What about https://redmine.pfsense.org/issues/13237 ? Some notes in there about strange behaviour that happens repeatedly unless the firewall is physically rebooted? Going to give it a cold boot now and see how that goes...
-
Aaaaaaand 13 minutes of uptime and IPv6 is still stable!
-
And it lasted about 50 minutes before it died and didn't recover again. So, better but still not great.
-
So it did renew 4 times at least, and failed to do so the 5th time ?
-
Looks like I was lacking "rapid commit" under advanced IP options. I tried to post instructions here but it keeps getting flagged as Spam. Check out https://www.reddit.com/r/PFSENSE/comments/1duuc6o/ipv6_troubles_unstable_pppoe_ipv6_address_via/ for the full post.
