[2.3.x] No default route on WAN PPPoE after link failure (with FIX, please test)
-
@cmb:
[…]
When you're left with no default gateway after a reconnect, check the system log. What is there from rc.newwanip? Should see something like:rc.newwanip: ROUTING: setting default route to x.x.x.xis that there? What else is logged at the time?
If you cause the WAN NIC to lose its link, in addition to rc.newwanip, rc.linkup will also set the default gateway and have a similar log. So you'll see it twice in that case, which is fine.
Note I'm talking about using strictly stock source code, not the change in this thread. Revert that change first if you made it.
Hi cmb, i revert the change, clear log and disconnect/reconnect PPPoE WAN interface. Here is the log. Look at line 71/72:
Jun 22 20:13:08 php-fpm 40496 /rc.dyndns.update: Curl error occurred: Could not resolve host: ipv4.tunnelbroker.net Jun 22 20:13:07 php-fpm 31985 /rc.newwanip: Curl error occurred: Could not resolve host: freedns.afraid.org Jun 22 20:13:07 php-fpm 31985 /rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): _checkStatus() starting. Jun 22 20:13:00 xinetd 14152 Reconfigured: new=0 old=1 dropped=0 (services) Jun 22 20:13:00 xinetd 14152 readjusting service 6969-udp Jun 22 20:13:00 xinetd 14152 Swapping defaults Jun 22 20:13:00 xinetd 14152 Starting reconfiguration Jun 22 20:12:59 php-fpm 31985 /rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): _update() starting. Jun 22 20:12:59 php-fpm 31985 /rc.newwanip: DynDns (casalener.mooo.com): Dynamic Dns: cacheIP != wan_ip. Updating. Cached IP: 82.51.169.204 WAN IP: 79.17.44.55 Jun 22 20:12:59 php-fpm 31985 /rc.newwanip: Dynamic Dns (casalener.mooo.com): Current WAN IP: 79.17.44.55 Cached IP: 82.51.169.204 Jun 22 20:12:59 php-fpm 31985 /rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): 79.17.44.55 extracted from local system. Jun 22 20:12:59 php-fpm 31985 /rc.newwanip: Dynamic DNS (casalener.mooo.com): running get_failover_interface for wan. found pppoe1 Jun 22 20:12:59 php-fpm 31985 /rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): 79.17.44.55 extracted from local system. Jun 22 20:12:59 php-fpm 40496 /rc.dyndns.update: Curl error occurred: Could not resolve host: freedns.afraid.org Jun 22 20:12:59 php-fpm 40496 /rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): _checkStatus() starting. Jun 22 20:12:59 php-fpm 31985 /rc.newwanip: Dynamic DNS: updatedns() starting Jun 22 20:12:58 xinetd 14152 Reconfigured: new=0 old=1 dropped=0 (services) Jun 22 20:12:58 xinetd 14152 readjusting service 6969-udp Jun 22 20:12:58 xinetd 14152 Swapping defaults Jun 22 20:12:58 xinetd 14152 Starting reconfiguration Jun 22 20:12:58 check_reload_status Reloading filter Jun 22 20:12:58 php-fpm 24848 /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing. Jun 22 20:12:58 php-fpm 31985 /rc.newwanip: Curl error occurred: Could not resolve host: dynupdate.no-ip.com Jun 22 20:12:57 xinetd 14152 Reconfigured: new=0 old=1 dropped=0 (services) Jun 22 20:12:57 xinetd 14152 readjusting service 6969-udp Jun 22 20:12:57 xinetd 14152 Swapping defaults Jun 22 20:12:57 xinetd 14152 Starting reconfiguration Jun 22 20:12:56 xinetd 14152 Reconfigured: new=0 old=1 dropped=0 (services) Jun 22 20:12:56 xinetd 14152 readjusting service 6969-udp Jun 22 20:12:56 xinetd 14152 Swapping defaults Jun 22 20:12:56 xinetd 14152 Starting reconfiguration Jun 22 20:12:56 check_reload_status Reloading filter Jun 22 20:12:56 php-fpm 46306 /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing. Jun 22 20:12:50 php-fpm 40496 /rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): _update() starting. Jun 22 20:12:50 php-fpm 40496 /rc.dyndns.update: DynDns (casalener.mooo.com): Dynamic Dns: cacheIP != wan_ip. Updating. Cached IP: 82.51.169.204 WAN IP: 79.17.44.55 Jun 22 20:12:50 php-fpm 40496 /rc.dyndns.update: Dynamic Dns (casalener.mooo.com): Current WAN IP: 79.17.44.55 Cached IP: 82.51.169.204 Jun 22 20:12:50 php-fpm 40496 /rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): 79.17.44.55 extracted from local system. Jun 22 20:12:50 php-fpm 40496 /rc.dyndns.update: Dynamic DNS (casalener.mooo.com): running get_failover_interface for wan. found pppoe1 Jun 22 20:12:50 php-fpm 40496 /rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): 79.17.44.55 extracted from local system. Jun 22 20:12:50 php-fpm 40496 /rc.dyndns.update: Dynamic DNS: updatedns() starting Jun 22 20:12:49 php-fpm 40496 /rc.dyndns.update: Curl error occurred: Could not resolve host: dynupdate.no-ip.com Jun 22 20:12:43 kernel gif0: link state changed to UP Jun 22 20:12:43 kernel gif0: link state changed to DOWN Jun 22 20:12:43 php-fpm 24848 /status_interfaces.php: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1 Jun 22 20:12:39 check_reload_status Reloading filter Jun 22 20:12:39 check_reload_status Restarting OpenVPN tunnels/interfaces Jun 22 20:12:39 check_reload_status Reloading filter Jun 22 20:12:39 check_reload_status Restarting ipsec tunnels Jun 22 20:12:39 check_reload_status Restarting OpenVPN tunnels/interfaces Jun 22 20:12:39 check_reload_status updating dyndns WAN_PPPOE Jun 22 20:12:39 check_reload_status Restarting ipsec tunnels Jun 22 20:12:39 check_reload_status updating dyndns HE_IPV6_TUNNELV6 Jun 22 20:12:37 ppp [wan] IPV6CP: LayerFinish Jun 22 20:12:37 ppp [wan] IPV6CP: state change Stopping --> Stopped Jun 22 20:12:36 php-fpm 31985 /rc.newwanip: Removing static route for monitor 2001:4860:4860::8888 and adding a new route through 2001:470:1f12:62c::1 Jun 22 20:12:36 php-fpm 40496 /rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.220.220 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.220.220 fib 0: not in table' Jun 22 20:12:36 php-fpm 40496 /rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.222.222 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.222.222 fib 0: not in table' Jun 22 20:12:36 php-fpm 40496 /rc.newwanipv6: rc.newwanipv6: No IPv6 address found for interface WAN [wan]. Jun 22 20:12:36 php-fpm 40496 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe1. Jun 22 20:12:35 xinetd 14152 Reconfigured: new=0 old=1 dropped=0 (services) Jun 22 20:12:35 xinetd 14152 readjusting service 6969-udp Jun 22 20:12:35 xinetd 14152 Swapping defaults Jun 22 20:12:35 xinetd 14152 Starting reconfiguration Jun 22 20:12:35 php-fpm 31985 /rc.newwanip: IP has changed, killing states on former IP 87.1.223.208. Jun 22 20:12:35 kernel gif0: link state changed to UP Jun 22 20:12:35 kernel gif0: link state changed to DOWN Jun 22 20:12:35 php-fpm 31985 /rc.newwanip: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1 Jun 22 20:12:35 kernel gif0: link state changed to UP Jun 22 20:12:35 kernel gif0: link state changed to DOWN Jun 22 20:12:35 php-fpm 31985 /rc.newwanip: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1 Jun 22 20:12:35 php-fpm 31985 /rc.newwanip: The command '/sbin/route delete -host 208.67.220.220 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.220.220 fib 0: not in table' Jun 22 20:12:35 php-fpm 31985 /rc.newwanip: The command '/sbin/route delete -host 208.67.222.222 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.222.222 fib 0: not in table' Jun 22 20:12:35 php-fpm 31985 /rc.newwanip: rc.newwanip: on (IP address: 79.17.44.55) (interface: WAN[wan]) (real interface: pppoe1). Jun 22 20:12:35 php-fpm 31985 /rc.newwanip: rc.newwanip: Info: starting on pppoe1. Jun 22 20:12:34 check_reload_status Rewriting resolv.conf Jun 22 20:12:34 ppp [wan] IPV6CP: LayerDown Jun 22 20:12:34 ppp [wan] IPV6CP: SendTerminateAck #2 Jun 22 20:12:34 ppp [wan] IPV6CP: state change Opened --> Stopping Jun 22 20:12:34 ppp [wan] IPV6CP: rec'd Terminate Request #91 (Opened) Jun 22 20:12:34 check_reload_status rc.newwanipv6 starting pppoe1 Jun 22 20:12:34 ppp [wan] 76d4:35ff:fe8a:b19c -> 02a0:a50f:fc86:8004 Jun 22 20:12:34 ppp [wan] IPV6CP: LayerUp Jun 22 20:12:34 ppp [wan] IPV6CP: state change Ack-Rcvd --> Opened Jun 22 20:12:34 ppp [wan] IPV6CP: SendConfigAck #90 Jun 22 20:12:34 ppp [wan] IPV6CP: rec'd Configure Request #90 (Ack-Rcvd) Jun 22 20:12:34 ppp [wan] IFACE: Rename interface ng0 to pppoe1 Jun 22 20:12:34 ppp [wan] IFACE: Up event Jun 22 20:12:34 check_reload_status rc.newwanip starting pppoe1 Jun 22 20:12:34 ppp [wan] 79.17.44.55 -> 192.168.100.1 Jun 22 20:12:34 ppp [wan] IPCP: LayerUp Jun 22 20:12:34 ppp [wan] IPCP: state change Ack-Rcvd --> Opened Jun 22 20:12:34 ppp [wan] IPADDR 192.168.100.1 Jun 22 20:12:34 ppp [wan] IPCP: SendConfigAck #26 Jun 22 20:12:34 ppp [wan] 192.168.100.1 is OK Jun 22 20:12:34 ppp [wan] IPADDR 192.168.100.1 Jun 22 20:12:34 ppp [wan] IPCP: rec'd Configure Request #26 (Ack-Rcvd) Jun 22 20:12:34 ppp [wan] IPCP: state change Req-Sent --> Ack-Rcvd Jun 22 20:12:34 ppp [wan] IPADDR 79.17.44.55 Jun 22 20:12:34 ppp [wan] IPCP: rec'd Configure Ack #3 (Req-Sent) Jun 22 20:12:34 ppp [wan] IPADDR 79.17.44.55 Jun 22 20:12:34 ppp [wan] IPCP: SendConfigReq #3 Jun 22 20:12:34 ppp [wan] 79.17.44.55 is OK Jun 22 20:12:34 ppp [wan] IPADDR 79.17.44.55 Jun 22 20:12:34 ppp [wan] IPCP: rec'd Configure Nak #2 (Req-Sent) Jun 22 20:12:34 ppp [wan] IPV6CP: state change Req-Sent --> Ack-Rcvd Jun 22 20:12:34 ppp [wan] IPV6CP: rec'd Configure Ack #1 (Req-Sent) Jun 22 20:12:34 ppp [wan] IPADDR 0.0.0.0 Jun 22 20:12:34 ppp [wan] IPCP: SendConfigReq #2 Jun 22 20:12:34 ppp [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Jun 22 20:12:34 ppp [wan] IPCP: rec'd Configure Reject #1 (Req-Sent) Jun 22 20:12:34 ppp [wan] IPV6CP: SendConfigReq #1 Jun 22 20:12:34 ppp [wan] IPV6CP: state change Starting --> Req-Sent Jun 22 20:12:34 ppp [wan] IPV6CP: Up event Jun 22 20:12:34 ppp [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Jun 22 20:12:34 ppp [wan] IPADDR 0.0.0.0 Jun 22 20:12:34 ppp [wan] IPCP: SendConfigReq #1 Jun 22 20:12:34 ppp [wan] IPCP: state change Starting --> Req-Sent Jun 22 20:12:34 ppp [wan] IPCP: Up event Jun 22 20:12:34 ppp [wan] IPV6CP: LayerStart Jun 22 20:12:34 ppp [wan] IPV6CP: state change Initial --> Starting Jun 22 20:12:34 ppp [wan] IPV6CP: Open event Jun 22 20:12:34 ppp [wan] IPCP: LayerStart Jun 22 20:12:34 ppp [wan] IPCP: state change Initial --> Starting Jun 22 20:12:34 ppp [wan] IPCP: Open event Jun 22 20:12:34 ppp [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps Jun 22 20:12:34 ppp [wan_link0] Link: Join bundle "wan" Jun 22 20:12:34 ppp [wan_link0] Link: Matched action 'bundle "wan" ""' Jun 22 20:12:34 ppp [wan_link0] LCP: authorization successful Jun 22 20:12:34 ppp [wan_link0] PAP: rec'd ACK #1 len: 5 Jun 22 20:12:34 ppp [wan_link0] LCP: LayerUp Jun 22 20:12:34 ppp [wan_link0] PAP: sending REQUEST #1 len: 24 Jun 22 20:12:34 ppp [wan_link0] PAP: using authname "aliceadsl" Jun 22 20:12:34 ppp [wan_link0] LCP: auth: peer wants PAP, I want nothing Jun 22 20:12:34 ppp [wan_link0] LCP: state change Ack-Sent --> Opened Jun 22 20:12:34 ppp [wan_link0] MAGICNUM 0x30806941 Jun 22 20:12:34 ppp [wan_link0] MRU 1492 Jun 22 20:12:34 ppp [wan_link0] PROTOCOMP Jun 22 20:12:34 ppp [wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent) Jun 22 20:12:34 ppp [wan_link0] LCP: state change Req-Sent --> Ack-Sent Jun 22 20:12:34 ppp [wan_link0] MAGICNUM 0x0107258b Jun 22 20:12:34 ppp [wan_link0] AUTHPROTO PAP Jun 22 20:12:34 ppp [wan_link0] MRU 1492 Jun 22 20:12:34 ppp [wan_link0] LCP: SendConfigAck #48 Jun 22 20:12:34 ppp [wan_link0] MAGICNUM 0x0107258b Jun 22 20:12:34 ppp [wan_link0] AUTHPROTO PAP Jun 22 20:12:34 ppp [wan_link0] MRU 1492 Jun 22 20:12:34 ppp [wan_link0] LCP: rec'd Configure Request #48 (Req-Sent) Jun 22 20:12:34 ppp [wan_link0] MAGICNUM 0x30806941 Jun 22 20:12:34 ppp [wan_link0] MRU 1492 Jun 22 20:12:34 ppp [wan_link0] PROTOCOMP Jun 22 20:12:34 ppp [wan_link0] LCP: SendConfigReq #1 Jun 22 20:12:34 ppp [wan_link0] LCP: state change Starting --> Req-Sent Jun 22 20:12:34 ppp [wan_link0] LCP: Up event Jun 22 20:12:34 ppp [wan_link0] Link: UP event Jun 22 20:12:34 ppp [wan_link0] PPPoE: connection successful Jun 22 20:12:33 ppp PPPoE: rec'd ACNAME "r-rm900" Jun 22 20:12:33 ppp [wan_link0] PPPoE: Connecting to 'TelecomFibra' Jun 22 20:12:33 ppp [wan_link0] LCP: LayerStart Jun 22 20:12:33 ppp [wan_link0] LCP: state change Initial --> Starting Jun 22 20:12:33 ppp [wan_link0] LCP: Open event Jun 22 20:12:33 kernel ng0: changing name to 'pppoe1' Jun 22 20:12:33 ppp [wan_link0] Link: OPEN event Jun 22 20:12:33 ppp [wan] Bundle: Interface ng0 created Jun 22 20:12:33 ppp web: web is not running Jun 22 20:12:33 ppp process 31483 started, version 5.8 (root@pfSense_v2_3_1_amd64-pfSense_v2_3_1-job-13 19:20 16-May-2016) Jun 22 20:12:33 ppp Multi-link PPP daemon for FreeBSD Jun 22 20:12:29 ppp process 5179 terminated Jun 22 20:12:29 ppp [wan_link0] Link: Shutdown Jun 22 20:12:29 ppp [wan] Bundle: Shutdown [b]Jun 22 20:12:28 php-fpm 24848 /rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.220.220 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.220.220 fib 0: not in table' Jun 22 20:12:28 php-fpm 24848 /rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.222.222 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.222.222 fib 0: not in table'[/b] Jun 22 20:12:27 ppp [wan_link0] LCP: state change Stopping --> Closing Jun 22 20:12:27 ppp [wan_link0] LCP: Close event Jun 22 20:12:27 ppp [wan_link0] Link: CLOSE event Jun 22 20:12:27 ppp [wan_link0] LCP: LayerDown Jun 22 20:12:27 ppp [wan_link0] LCP: SendTerminateAck #2 Jun 22 20:12:27 ppp [wan] IPV6CP: state change Closed --> Initial Jun 22 20:12:27 ppp [wan] IPV6CP: Down event Jun 22 20:12:27 ppp [wan] IPCP: state change Closed --> Initial Jun 22 20:12:27 ppp [wan] IPCP: Down event Jun 22 20:12:27 ppp [wan] IPV6CP: Close event Jun 22 20:12:27 ppp [wan] IPCP: Close event Jun 22 20:12:27 ppp [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Jun 22 20:12:27 ppp [wan_link0] Link: Leave bundle "wan" Jun 22 20:12:27 ppp [wan_link0] LCP: state change Opened --> Stopping Jun 22 20:12:27 ppp [wan_link0] LCP: rec'd Terminate Request #109 (Opened) Jun 22 20:12:27 ppp [wan] Bundle: closing link "wan_link0"... Jun 22 20:12:27 ppp [wan] Bundle: No NCPs left. Closing links... Jun 22 20:12:27 ppp [wan] IPCP: LayerFinish Jun 22 20:12:27 ppp [wan] IPCP: state change Closing --> Closed Jun 22 20:12:27 ppp [wan] IPCP: rec'd Terminate Ack #4 (Closing) Jun 22 20:12:27 ppp [wan] IPV6CP: state change Stopped --> Closed Jun 22 20:12:27 ppp [wan] IPV6CP: Close event Jun 22 20:12:27 ppp [wan] IFACE: Rename interface pppoe1 to pppoe1 Jun 22 20:12:27 ppp [wan] IFACE: Down event Jun 22 20:12:27 check_reload_status Rewriting resolv.conf Jun 22 20:12:27 ppp [wan] IPCP: LayerDown Jun 22 20:12:27 ppp [wan] IPCP: SendTerminateReq #4 Jun 22 20:12:27 ppp [wan] IPCP: state change Opened --> Closing Jun 22 20:12:27 ppp [wan] IPCP: Close event Jun 22 20:12:27 ppp [wan] IFACE: Close event Jun 22 20:12:27 ppp caught fatal signal TERM Jun 22 20:12:20 syslogd kernel boot file is /boot/kernel/kernel208.67.222.222 and 208.67.220.200 are my OpenDNS name server. IPv6 Tunnel is from HE.
Thanks in advance,
-
Hello all,
I'm having the same issue. Since 2.3.1 (up to 2.3.1_5), folowing a reboot, no default gateway and no Internet access.
No line similar to "ROUTING: setting default route to x.x.x.x" in the log. (cmb, I can send the log to you if required.)
However, going to System -> Routing -> Gateways and editing and saving the automatically created PPPoE default gateway entry creates it and everything is back up.
My capabilities for testing are limited as this is a production system and I only have remote access to it but I'll be glad to help if I can.
Thanks.
-
Hi cmb, i revert the change, clear log and disconnect/reconnect PPPoE WAN interface. Here is the log. Look at line 71/72:
Thanks for the logs, that helps. The route delete errors there are fine, just because the routes were dropped as part of PPP disconnecting so they aren't there to delete.
ppp-linkup calls rc.newwanip, which calls system_routing_configure. If it had an interface, and gateway IP, it would be adding it there. It's not apparent which it could be missing. Next, in /etc/inc/system.inc above this line:
if ($dont_add_route == false) {add this line:
log_error("DEBUG: interface: $interface interfacegw: $interfacegw gatewayip: $gatewayip");Then replicate again, and post the new logs.
-
Hi cmb,
@cmb:
[…]
add this line:log_error("DEBUG: interface: $interface interfacegw: $interfacegw gatewayip: $gatewayip");Then replicate again, and post the new logs.
I change /etc/inc/system.inc:
/* La linea seguente è stata aggiunta per il debug dell'errore Redmine #6495 */ log_error("DEBUG: interface: $interface interfacegw: $interfacegw gatewayip: $gatewayip"); if ($dont_add_route == false) { if (!empty($interface) && $interface != $interfacegw) {This is system log with strictly stock source:
Jun 24 10:38:03 xinetd 14152 Reconfigured: new=0 old=1 dropped=0 (services) Jun 24 10:38:03 xinetd 14152 readjusting service 6969-udp Jun 24 10:38:03 xinetd 14152 Swapping defaults Jun 24 10:38:03 xinetd 14152 Starting reconfiguration Jun 24 10:38:02 xinetd 14152 Reconfigured: new=0 old=1 dropped=0 (services) Jun 24 10:38:02 xinetd 14152 readjusting service 6969-udp Jun 24 10:38:02 xinetd 14152 Swapping defaults Jun 24 10:38:02 xinetd 14152 Starting reconfiguration Jun 24 10:38:01 ftp-proxy 5586 listening on 127.0.0.1 port 8021 Jun 24 10:38:01 check_reload_status Reloading filter Jun 24 10:38:01 check_reload_status Syncing firewall Jun 24 10:38:01 php-fpm 98299 [pfBlockerNG] Starting cron process. Jun 24 10:38:01 ftp-proxy 2171 listening on 127.0.0.1 port 8021 Jun 24 10:38:01 check_reload_status Reloading filter Jun 24 10:38:01 php-fpm 98299 /rc.start_packages: Restarting/Starting all packages. Jun 24 10:38:00 check_reload_status Starting packages Jun 24 10:38:00 php-fpm 65464 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 79.47.194.62 -> 79.56.147.131 - Restarting packages. Jun 24 10:37:59 xinetd 14152 Reconfigured: new=0 old=1 dropped=0 (services) Jun 24 10:37:59 xinetd 14152 readjusting service 6969-udp Jun 24 10:37:59 xinetd 14152 Swapping defaults Jun 24 10:37:59 xinetd 14152 Starting reconfiguration Jun 24 10:37:58 php-fpm 65464 /rc.newwanip: Creating rrd update script Jun 24 10:37:58 php-fpm 65464 /rc.newwanip: Resyncing OpenVPN instances for interface WAN. Jun 24 10:37:58 check_reload_status Reloading filter Jun 24 10:37:58 php-fpm 65464 /rc.newwanip: Forcefully reloading IPsec Jun 24 10:37:57 php-fpm 65464 /rc.newwanip: Curl error occurred: Could not resolve host: ipv4.tunnelbroker.net Jun 24 10:37:54 xinetd 14152 Reconfigured: new=0 old=1 dropped=0 (services) Jun 24 10:37:54 xinetd 14152 readjusting service 6969-udp Jun 24 10:37:54 xinetd 14152 Swapping defaults Jun 24 10:37:54 xinetd 14152 Starting reconfiguration Jun 24 10:37:53 check_reload_status Reloading filter Jun 24 10:37:53 php-fpm 55525 /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing. Jun 24 10:37:51 xinetd 14152 Reconfigured: new=0 old=1 dropped=0 (services) Jun 24 10:37:51 xinetd 14152 readjusting service 6969-udp Jun 24 10:37:51 xinetd 14152 Swapping defaults Jun 24 10:37:51 xinetd 14152 Starting reconfiguration Jun 24 10:37:50 xinetd 14152 Reconfigured: new=0 old=1 dropped=0 (services) Jun 24 10:37:50 xinetd 14152 readjusting service 6969-udp Jun 24 10:37:50 xinetd 14152 Swapping defaults Jun 24 10:37:50 xinetd 14152 Starting reconfiguration Jun 24 10:37:49 xinetd 14152 Reconfigured: new=0 old=1 dropped=0 (services) Jun 24 10:37:49 xinetd 14152 readjusting service 6969-udp Jun 24 10:37:49 xinetd 14152 Swapping defaults Jun 24 10:37:49 xinetd 14152 Starting reconfiguration Jun 24 10:37:48 php-fpm 74632 /rc.dyndns.update: Curl error occurred: Could not resolve host: ipv4.tunnelbroker.net Jun 24 10:37:47 php-fpm 65464 /rc.newwanip: Curl error occurred: Could not resolve host: freedns.afraid.org Jun 24 10:37:47 php-fpm 65464 /rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): _checkStatus() starting. Jun 24 10:37:38 php-fpm 65464 /rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): _update() starting. Jun 24 10:37:38 php-fpm 65464 /rc.newwanip: DynDns (casalener.mooo.com): Dynamic Dns: cacheIP != wan_ip. Updating. Cached IP: 80.181.221.144 WAN IP: 79.56.147.131 Jun 24 10:37:38 php-fpm 65464 /rc.newwanip: Dynamic Dns (casalener.mooo.com): Current WAN IP: 79.56.147.131 Cached IP: 80.181.221.144 Jun 24 10:37:38 php-fpm 65464 /rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): 79.56.147.131 extracted from local system. Jun 24 10:37:38 php-fpm 65464 /rc.newwanip: Dynamic DNS (casalener.mooo.com): running get_failover_interface for wan. found pppoe1 Jun 24 10:37:38 php-fpm 65464 /rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): 79.56.147.131 extracted from local system. Jun 24 10:37:38 php-fpm 65464 /rc.newwanip: Dynamic DNS: updatedns() starting Jun 24 10:37:38 php-fpm 74632 /rc.dyndns.update: Curl error occurred: Could not resolve host: freedns.afraid.org Jun 24 10:37:38 php-fpm 74632 /rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): _checkStatus() starting. Jun 24 10:37:38 check_reload_status Reloading filter Jun 24 10:37:38 php-fpm 55525 /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing. Jun 24 10:37:37 php-fpm 65464 /rc.newwanip: Curl error occurred: Could not resolve host: dynupdate.no-ip.com Jun 24 10:37:29 php-fpm 74632 /rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): _update() starting. Jun 24 10:37:29 php-fpm 74632 /rc.dyndns.update: DynDns (casalener.mooo.com): Dynamic Dns: cacheIP != wan_ip. Updating. Cached IP: 80.181.221.144 WAN IP: 79.56.147.131 Jun 24 10:37:29 php-fpm 74632 /rc.dyndns.update: Dynamic Dns (casalener.mooo.com): Current WAN IP: 79.56.147.131 Cached IP: 80.181.221.144 Jun 24 10:37:29 php-fpm 74632 /rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): 79.56.147.131 extracted from local system. Jun 24 10:37:29 php-fpm 74632 /rc.dyndns.update: Dynamic DNS (casalener.mooo.com): running get_failover_interface for wan. found pppoe1 Jun 24 10:37:29 php-fpm 74632 /rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): 79.56.147.131 extracted from local system. Jun 24 10:37:29 php-fpm 74632 /rc.dyndns.update: Dynamic DNS: updatedns() starting Jun 24 10:37:28 php-fpm 74632 /rc.dyndns.update: Curl error occurred: Could not resolve host: dynupdate.no-ip.com Jun 24 10:37:23 php-fpm 55525 /status_interfaces.php: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1 Jun 24 10:37:23 kernel gif0: link state changed to UP Jun 24 10:37:23 kernel gif0: link state changed to DOWN Jun 24 10:37:23 php-fpm 55525 /status_interfaces.php: DEBUG: interface: opt1 interfacegw: wan gatewayip: Jun 24 10:37:19 check_reload_status Reloading filter Jun 24 10:37:19 check_reload_status Restarting OpenVPN tunnels/interfaces Jun 24 10:37:19 check_reload_status Reloading filter Jun 24 10:37:19 check_reload_status Restarting ipsec tunnels Jun 24 10:37:19 check_reload_status Restarting OpenVPN tunnels/interfaces Jun 24 10:37:19 check_reload_status updating dyndns HE_IPV6_TUNNELV6 Jun 24 10:37:19 check_reload_status Restarting ipsec tunnels Jun 24 10:37:19 check_reload_status updating dyndns WAN_PPPOE Jun 24 10:37:16 ppp [wan] IPV6CP: LayerFinish Jun 24 10:37:16 ppp [wan] IPV6CP: state change Stopping --> Stopped Jun 24 10:37:16 php-fpm 65464 /rc.newwanip: Removing static route for monitor 2001:4860:4860::8888 and adding a new route through 2001:470:1f12:62c::1 Jun 24 10:37:16 php-fpm 65464 /rc.newwanip: DEBUG: interface: wan interfacegw: wan gatewayip: Jun 24 10:37:15 php-fpm 74632 /rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.220.220 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.220.220 fib 0: not in table' Jun 24 10:37:15 php-fpm 74632 /rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.222.222 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.222.222 fib 0: not in table' Jun 24 10:37:15 php-fpm 74632 /rc.newwanipv6: rc.newwanipv6: No IPv6 address found for interface WAN [wan]. Jun 24 10:37:15 php-fpm 74632 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe1. Jun 24 10:37:15 xinetd 14152 Reconfigured: new=0 old=1 dropped=0 (services) Jun 24 10:37:15 xinetd 14152 readjusting service 6969-udp Jun 24 10:37:15 xinetd 14152 Swapping defaults Jun 24 10:37:15 xinetd 14152 Starting reconfiguration Jun 24 10:37:15 php-fpm 65464 /rc.newwanip: IP has changed, killing states on former IP 79.47.194.62. Jun 24 10:37:15 php-fpm 65464 /rc.newwanip: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1 Jun 24 10:37:15 kernel gif0: link state changed to UP Jun 24 10:37:15 kernel gif0: link state changed to DOWN Jun 24 10:37:15 php-fpm 65464 /rc.newwanip: DEBUG: interface: opt1 interfacegw: wan gatewayip: Jun 24 10:37:15 php-fpm 65464 /rc.newwanip: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1 Jun 24 10:37:15 kernel gif0: link state changed to UP Jun 24 10:37:15 kernel gif0: link state changed to DOWN Jun 24 10:37:15 php-fpm 65464 /rc.newwanip: DEBUG: interface: opt1 interfacegw: wan gatewayip: Jun 24 10:37:15 php-fpm 65464 /rc.newwanip: The command '/sbin/route delete -host 208.67.220.220 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.220.220 fib 0: not in table' Jun 24 10:37:15 php-fpm 65464 /rc.newwanip: The command '/sbin/route delete -host 208.67.222.222 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.222.222 fib 0: not in table' Jun 24 10:37:15 php-fpm 65464 /rc.newwanip: rc.newwanip: on (IP address: 79.56.147.131) (interface: WAN[wan]) (real interface: pppoe1). Jun 24 10:37:15 php-fpm 65464 /rc.newwanip: rc.newwanip: Info: starting on pppoe1. Jun 24 10:37:14 check_reload_status Rewriting resolv.conf Jun 24 10:37:14 ppp [wan] IPV6CP: LayerDown Jun 24 10:37:14 ppp [wan] IPV6CP: SendTerminateAck #2 Jun 24 10:37:14 ppp [wan] IPV6CP: state change Opened --> Stopping Jun 24 10:37:14 ppp [wan] IPV6CP: rec'd Terminate Request #164 (Opened) Jun 24 10:37:14 check_reload_status rc.newwanipv6 starting pppoe1 Jun 24 10:37:14 ppp [wan] 76d4:35ff:fe8a:b19c -> 02a0:a50f:fc86:8004 Jun 24 10:37:14 ppp [wan] IPV6CP: LayerUp Jun 24 10:37:14 ppp [wan] IPV6CP: state change Ack-Rcvd --> Opened Jun 24 10:37:14 ppp [wan] IPV6CP: SendConfigAck #163 Jun 24 10:37:14 ppp [wan] IPV6CP: rec'd Configure Request #163 (Ack-Rcvd) Jun 24 10:37:14 ppp [wan] IFACE: Rename interface ng0 to pppoe1 Jun 24 10:37:14 ppp [wan] IFACE: Up event Jun 24 10:37:14 check_reload_status rc.newwanip starting pppoe1 Jun 24 10:37:13 ppp [wan] 79.56.147.131 -> 192.168.100.1 Jun 24 10:37:13 ppp [wan] IPCP: LayerUp Jun 24 10:37:13 ppp [wan] IPCP: state change Ack-Rcvd --> Opened Jun 24 10:37:13 ppp [wan] IPADDR 192.168.100.1 Jun 24 10:37:13 ppp [wan] IPCP: SendConfigAck #109 Jun 24 10:37:13 ppp [wan] 192.168.100.1 is OK Jun 24 10:37:13 ppp [wan] IPADDR 192.168.100.1 Jun 24 10:37:13 ppp [wan] IPCP: rec'd Configure Request #109 (Ack-Rcvd) Jun 24 10:37:13 ppp [wan] IPCP: state change Req-Sent --> Ack-Rcvd Jun 24 10:37:13 ppp [wan] IPADDR 79.56.147.131 Jun 24 10:37:13 ppp [wan] IPCP: rec'd Configure Ack #3 (Req-Sent) Jun 24 10:37:13 ppp [wan] IPADDR 79.56.147.131 Jun 24 10:37:13 ppp [wan] IPCP: SendConfigReq #3 Jun 24 10:37:13 ppp [wan] 79.56.147.131 is OK Jun 24 10:37:13 ppp [wan] IPADDR 79.56.147.131 Jun 24 10:37:13 ppp [wan] IPCP: rec'd Configure Nak #2 (Req-Sent) Jun 24 10:37:13 ppp [wan] IPV6CP: state change Req-Sent --> Ack-Rcvd Jun 24 10:37:13 ppp [wan] IPV6CP: rec'd Configure Ack #1 (Req-Sent) Jun 24 10:37:13 ppp [wan] IPADDR 0.0.0.0 Jun 24 10:37:13 ppp [wan] IPCP: SendConfigReq #2 Jun 24 10:37:13 ppp [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Jun 24 10:37:13 ppp [wan] IPCP: rec'd Configure Reject #1 (Req-Sent) Jun 24 10:37:13 ppp [wan] IPV6CP: SendConfigReq #1 Jun 24 10:37:13 ppp [wan] IPV6CP: state change Starting --> Req-Sent Jun 24 10:37:13 ppp [wan] IPV6CP: Up event Jun 24 10:37:13 ppp [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Jun 24 10:37:13 ppp [wan] IPADDR 0.0.0.0 Jun 24 10:37:13 ppp [wan] IPCP: SendConfigReq #1 Jun 24 10:37:13 ppp [wan] IPCP: state change Starting --> Req-Sent Jun 24 10:37:13 ppp [wan] IPCP: Up event Jun 24 10:37:13 ppp [wan] IPV6CP: LayerStart Jun 24 10:37:13 ppp [wan] IPV6CP: state change Initial --> Starting Jun 24 10:37:13 ppp [wan] IPV6CP: Open event Jun 24 10:37:13 ppp [wan] IPCP: LayerStart Jun 24 10:37:13 ppp [wan] IPCP: state change Initial --> Starting Jun 24 10:37:13 ppp [wan] IPCP: Open event Jun 24 10:37:13 ppp [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps Jun 24 10:37:13 ppp [wan_link0] Link: Join bundle "wan" Jun 24 10:37:13 ppp [wan_link0] Link: Matched action 'bundle "wan" ""' Jun 24 10:37:13 ppp [wan_link0] LCP: authorization successful Jun 24 10:37:13 ppp [wan_link0] PAP: rec'd ACK #1 len: 5 Jun 24 10:37:13 ppp [wan_link0] LCP: LayerUp Jun 24 10:37:13 ppp [wan_link0] PAP: sending REQUEST #1 len: 24 Jun 24 10:37:13 ppp [wan_link0] PAP: using authname "aliceadsl" Jun 24 10:37:13 ppp [wan_link0] LCP: auth: peer wants PAP, I want nothing Jun 24 10:37:13 ppp [wan_link0] LCP: state change Ack-Sent --> Opened Jun 24 10:37:13 ppp [wan_link0] MAGICNUM 0xb26eca2e Jun 24 10:37:13 ppp [wan_link0] MRU 1492 Jun 24 10:37:13 ppp [wan_link0] PROTOCOMP Jun 24 10:37:13 ppp [wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent) Jun 24 10:37:13 ppp [wan_link0] LCP: state change Req-Sent --> Ack-Sent Jun 24 10:37:13 ppp [wan_link0] MAGICNUM 0x5794e7e4 Jun 24 10:37:13 ppp [wan_link0] AUTHPROTO PAP Jun 24 10:37:13 ppp [wan_link0] MRU 1492 Jun 24 10:37:13 ppp [wan_link0] LCP: SendConfigAck #138 Jun 24 10:37:13 ppp [wan_link0] MAGICNUM 0x5794e7e4 Jun 24 10:37:13 ppp [wan_link0] AUTHPROTO PAP Jun 24 10:37:13 ppp [wan_link0] MRU 1492 Jun 24 10:37:13 ppp [wan_link0] LCP: rec'd Configure Request #138 (Req-Sent) Jun 24 10:37:13 ppp [wan_link0] MAGICNUM 0xb26eca2e Jun 24 10:37:13 ppp [wan_link0] MRU 1492 Jun 24 10:37:13 ppp [wan_link0] PROTOCOMP Jun 24 10:37:13 ppp [wan_link0] LCP: SendConfigReq #1 Jun 24 10:37:13 ppp [wan_link0] LCP: state change Starting --> Req-Sent Jun 24 10:37:13 ppp [wan_link0] LCP: Up event Jun 24 10:37:13 ppp [wan_link0] Link: UP event Jun 24 10:37:13 ppp [wan_link0] PPPoE: connection successful Jun 24 10:37:13 ppp PPPoE: rec'd ACNAME "r-rm900" Jun 24 10:37:13 ppp [wan_link0] PPPoE: Connecting to 'TelecomFibra' Jun 24 10:37:13 ppp [wan_link0] LCP: LayerStart Jun 24 10:37:13 ppp [wan_link0] LCP: state change Initial --> Starting Jun 24 10:37:13 ppp [wan_link0] LCP: Open event Jun 24 10:37:13 kernel ng0: changing name to 'pppoe1' Jun 24 10:37:13 ppp [wan_link0] Link: OPEN event Jun 24 10:37:13 ppp [wan] Bundle: Interface ng0 created Jun 24 10:37:13 ppp web: web is not running Jun 24 10:37:13 ppp process 65266 started, version 5.8 (root@pfSense_v2_3_1_amd64-pfSense_v2_3_1-job-13 19:20 16-May-2016) Jun 24 10:37:13 ppp Multi-link PPP daemon for FreeBSD Jun 24 10:37:03 syslogd kernel boot file is /boot/kernel/kernelThanks in advance,
-
Thanks, that narrows it down further. get_interface_gateway is returning null in that case. Which likely means that interface's router file is empty at the time. /tmp/pppoe1_router in your case.
What contents does /tmp/pppoe1_router have after doing that?
Appreciate your help tracking this down.
-
Hi cmb,
@cmb:
Thanks, that narrows it down further. get_interface_gateway is returning null in that case. Which likely means that interface's router file is empty at the time. /tmp/pppoe1_router in your case.
What contents does /tmp/pppoe1_router have after doing that?
Appreciate your help tracking this down.
It seems file doesn't exist in both code (reverted 2.2.6 and 2.3.x). The image show /tmp folder with 2.3.1_5 stock code.
-
It seems file doesn't exist in both code (reverted 2.2.6 and 2.3.x). The image show /tmp folder with 2.3.1_5 stock code.
Ok that's why, now just a question of why that's missing. What is your IPv6 configuration on that interface? Seems like it ends up with pppoe1_routerv6 but not the v4.
-
@cmb:
Ok that's why, now just a question of why that's missing. What is your IPv6 configuration on that interface? Seems like it ends up with pppoe1_routerv6 but not the v4.
I have a Hurricane Electric /64 on tunnelbroker.net (see attached image). Yes, there's pppoe_routerv6 but ipv4 is missing.
Thanks in advance,
–
Marlenio
-
So that pppoe1_routerv6 file contains your HE gateway IP?
-
@cmb:
So that pppoe1_routerv6 file contains your HE gateway IP?
No, the one in pppoe1_routerv6 seems to be a link local address, like the ip in /tmp/pppoe1_ipv6 (fe80::76d4:35ff:fe8a:b19c)
-
Odd, it's like ppp-linkup is somehow not getting called or getting called missing some of its arguments.
Last (I hope) thing to try to get to the bottom of this. In /usr/local/sbin/ppp-linkup under this line:
DNS2_RAW="${7}"Add this line:
logger "ppp-linkup IF: $IF | PROTOCOL: $PROTOCOL | LOCAL_IP: $LOCAL_IP | REMOTE_IP: $REMOTE_IP | AUTH_NAME: $AUTH_NAME | DNS1_RAW: $DNS1_RAW | DNS2_RAW: $DNS2_RAW"and replicate again. Then post the system log line that contains something like:
root: ppp-linkup IF: pppoe1 | PROTOCOL: …
-
Hi cmb,
@cmb:
Odd, it's like ppp-linkup is somehow not getting called or getting called missing some of its arguments.
Last (I hope) thing to try to get to the bottom of this. In /usr/local/sbin/ppp-linkup under this line:
Thank you, in late afternoon i'll made the change and then post the log here. :)
-
Hi cmb,
here is the system log with stock source:Jun 30 18:00:27 ftp-proxy 64428 listening on 127.0.0.1 port 8021 Jun 30 18:00:27 check_reload_status Syncing firewall Jun 30 18:00:27 php-fpm 42987 [pfBlockerNG] Starting cron process. Jun 30 18:00:27 ftp-proxy 60589 listening on 127.0.0.1 port 8021 Jun 30 18:00:27 check_reload_status Reloading filter Jun 30 18:00:27 php-fpm 42987 /rc.start_packages: Restarting/Starting all packages. Jun 30 18:00:26 xinetd 13847 Reconfigured: new=0 old=1 dropped=0 (services) Jun 30 18:00:26 xinetd 13847 readjusting service 6969-udp Jun 30 18:00:26 xinetd 13847 Swapping defaults Jun 30 18:00:26 xinetd 13847 Starting reconfiguration Jun 30 18:00:25 xinetd 13847 Reconfigured: new=0 old=1 dropped=0 (services) Jun 30 18:00:25 xinetd 13847 readjusting service 6969-udp Jun 30 18:00:25 xinetd 13847 Swapping defaults Jun 30 18:00:25 xinetd 13847 Starting reconfiguration Jun 30 18:00:23 xinetd 13847 Reconfigured: new=0 old=1 dropped=0 (services) Jun 30 18:00:23 xinetd 13847 readjusting service 6969-udp Jun 30 18:00:23 xinetd 13847 Swapping defaults Jun 30 18:00:23 xinetd 13847 Starting reconfiguration Jun 30 18:00:23 check_reload_status Reloading filter Jun 30 18:00:23 php-fpm 42987 /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing. Jun 30 18:00:08 check_reload_status Reloading filter Jun 30 18:00:08 php-fpm 42987 /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing. Jun 30 17:59:52 php-fpm 42987 /rc.dyndns.update: Curl error occurred: Could not resolve host: ipv4.tunnelbroker.net Jun 30 17:59:42 php-fpm 42987 /rc.dyndns.update: Curl error occurred: Could not resolve host: freedns.afraid.org Jun 30 17:59:42 php-fpm 42987 /rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): _checkStatus() starting. Jun 30 17:59:34 php-fpm 42987 /rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): _update() starting. Jun 30 17:59:34 php-fpm 42987 /rc.dyndns.update: DynDns (casalener.mooo.com): Dynamic Dns: cacheIP != wan_ip. Updating. Cached IP: 82.57.156.105 WAN IP: 95.247.53.52 Jun 30 17:59:34 php-fpm 42987 /rc.dyndns.update: Dynamic Dns (casalener.mooo.com): Current WAN IP: 95.247.53.52 Cached IP: 82.57.156.105 Jun 30 17:59:34 php-fpm 42987 /rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): 95.247.53.52 extracted from local system. Jun 30 17:59:34 php-fpm 42987 /rc.dyndns.update: Dynamic DNS (casalener.mooo.com): running get_failover_interface for wan. found pppoe1 Jun 30 17:59:34 php-fpm 42987 /rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): 95.247.53.52 extracted from local system. Jun 30 17:59:34 php-fpm 42987 /rc.dyndns.update: Dynamic DNS: updatedns() starting Jun 30 17:59:33 php-fpm 42987 /rc.dyndns.update: Curl error occurred: Could not resolve host: dynupdate.no-ip.com Jun 30 17:59:24 php-fpm 42987 /rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.220.220 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.220.220 fib 0: not in table' Jun 30 17:59:24 php-fpm 42987 /rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.222.222 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.222.222 fib 0: not in table' Jun 30 17:59:24 php-fpm 42987 /rc.newwanipv6: rc.newwanipv6: No IPv6 address found for interface WAN [wan]. Jun 30 17:59:24 php-fpm 42987 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe1. Jun 30 17:59:24 check_reload_status Starting packages Jun 30 17:59:24 php-fpm 42987 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 82.57.156.105 -> 95.247.53.52 - Restarting packages. Jun 30 17:59:22 php-fpm 42987 /rc.newwanip: Creating rrd update script Jun 30 17:59:22 php-fpm 42987 /rc.newwanip: Resyncing OpenVPN instances for interface WAN. Jun 30 17:59:22 check_reload_status Reloading filter Jun 30 17:59:22 php-fpm 42987 /rc.newwanip: Forcefully reloading IPsec Jun 30 17:59:21 php-fpm 42987 /rc.newwanip: Curl error occurred: Could not resolve host: ipv4.tunnelbroker.net Jun 30 17:59:11 php-fpm 42987 /rc.newwanip: Curl error occurred: Could not resolve host: freedns.afraid.org Jun 30 17:59:11 php-fpm 42987 /rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): _checkStatus() starting. Jun 30 17:59:03 php-cgi servicewatchdog_cron.php: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1467302343] unbound[3597:0] error: bind: address already in use [1467302343] unbound[3597:0] fatal error: could not open ports' Jun 30 17:59:02 php-fpm 42987 /rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): _update() starting. Jun 30 17:59:02 php-fpm 42987 /rc.newwanip: DynDns (casalener.mooo.com): Dynamic Dns: cacheIP != wan_ip. Updating. Cached IP: 82.57.156.105 WAN IP: 95.247.53.52 Jun 30 17:59:02 php-fpm 42987 /rc.newwanip: Dynamic Dns (casalener.mooo.com): Current WAN IP: 95.247.53.52 Cached IP: 82.57.156.105 Jun 30 17:59:02 php-fpm 42987 /rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): 95.247.53.52 extracted from local system. Jun 30 17:59:02 php-fpm 42987 /rc.newwanip: Dynamic DNS (casalener.mooo.com): running get_failover_interface for wan. found pppoe1 Jun 30 17:59:02 php-fpm 42987 /rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): 95.247.53.52 extracted from local system. Jun 30 17:59:02 php-fpm 42987 /rc.newwanip: Dynamic DNS: updatedns() starting Jun 30 17:59:01 php-fpm 42987 /rc.newwanip: Curl error occurred: Could not resolve host: dynupdate.no-ip.com Jun 30 17:58:04 php-cgi servicewatchdog_cron.php: Could not send the message to mario.lener@gmail.com -- Error: could not resolve the host domain "smtp.gmail.com" Jun 30 17:58:00 php-cgi servicewatchdog_cron.php: Service Watchdog detected service unbound stopped. Restarting unbound (Unbound DNS Resolver) Jun 30 17:57:55 check_reload_status Reloading filter Jun 30 17:57:55 check_reload_status Restarting OpenVPN tunnels/interfaces Jun 30 17:57:55 check_reload_status Reloading filter Jun 30 17:57:55 check_reload_status Restarting ipsec tunnels Jun 30 17:57:55 check_reload_status Restarting OpenVPN tunnels/interfaces Jun 30 17:57:55 check_reload_status updating dyndns HE_IPV6_TUNNELV6 Jun 30 17:57:55 check_reload_status Restarting ipsec tunnels Jun 30 17:57:55 check_reload_status updating dyndns WAN_PPPOE Jun 30 17:57:52 php-fpm 42987 /rc.newwanip: Removing static route for monitor 2001:4860:4860::8888 and adding a new route through 2001:470:1f12:62c::1 Jun 30 17:57:51 xinetd 13847 Reconfigured: new=0 old=1 dropped=0 (services) Jun 30 17:57:51 xinetd 13847 readjusting service 6969-udp Jun 30 17:57:51 xinetd 13847 Swapping defaults Jun 30 17:57:51 xinetd 13847 Starting reconfiguration Jun 30 17:57:50 php-fpm 42987 /rc.newwanip: IP has changed, killing states on former IP 82.57.156.105. Jun 30 17:57:50 php-fpm 42987 /rc.newwanip: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1 Jun 30 17:57:50 kernel gif0: link state changed to UP Jun 30 17:57:50 kernel gif0: link state changed to DOWN Jun 30 17:57:50 kernel gif0: link state changed to UP Jun 30 17:57:50 kernel gif0: link state changed to DOWN Jun 30 17:57:50 php-fpm 42987 /rc.newwanip: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1 Jun 30 17:57:50 php-fpm 42987 /rc.newwanip: The command '/sbin/route delete -host 208.67.220.220 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.220.220 fib 0: not in table' Jun 30 17:57:50 php-fpm 42987 /rc.newwanip: The command '/sbin/route delete -host 208.67.222.222 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.222.222 fib 0: not in table' Jun 30 17:57:50 php-fpm 42987 /rc.newwanip: rc.newwanip: on (IP address: 95.247.53.52) (interface: WAN[wan]) (real interface: pppoe1). Jun 30 17:57:50 php-fpm 42987 /rc.newwanip: rc.newwanip: Info: starting on pppoe1. Jun 30 17:57:49 xinetd 13847 Reconfigured: new=0 old=1 dropped=0 (services) Jun 30 17:57:49 xinetd 13847 readjusting service 6969-udp Jun 30 17:57:49 xinetd 13847 Swapping defaults Jun 30 17:57:49 xinetd 13847 Starting reconfiguration Jun 30 17:57:48 xinetd 13847 Reconfigured: new=0 old=1 dropped=0 (services) Jun 30 17:57:48 xinetd 13847 readjusting service 6969-udp Jun 30 17:57:48 xinetd 13847 Swapping defaults Jun 30 17:57:48 xinetd 13847 Starting reconfiguration Jun 30 17:57:48 kernel gif0: link state changed to UP Jun 30 17:57:48 kernel gif0: link state changed to DOWN Jun 30 17:57:48 php-fpm 42987 /status_interfaces.php: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1 Jun 30 17:57:45 ppp [wan] IPV6CP: LayerFinish Jun 30 17:57:45 ppp [wan] IPV6CP: state change Stopping --> Stopped Jun 30 17:57:43 check_reload_status Rewriting resolv.conf Jun 30 17:57:42 ppp [wan] IPV6CP: LayerDown Jun 30 17:57:42 ppp [wan] IPV6CP: SendTerminateAck #10 Jun 30 17:57:42 ppp [wan] IPV6CP: state change Opened --> Stopping Jun 30 17:57:42 ppp [wan] IPV6CP: rec'd Terminate Request #83 (Opened) Jun 30 17:57:42 check_reload_status rc.newwanipv6 starting pppoe1 Jun 30 17:57:42 root ppp-linkup IF: pppoe1 | PROTOCOL: inet6 | LOCAL_IP: fe80::76d4:35ff:fe8a:b19c%pppoe1 | REMOTE_IP: fe80::2a0:a50f:fc86:8004%pppoe1 | AUTH_NAME: - | DNS1_RAW: 00:00:00:00:00:00 | DNS2_RAW: - Jun 30 17:57:42 ppp [wan] 76d4:35ff:fe8a:b19c -> 02a0:a50f:fc86:8004 Jun 30 17:57:42 ppp [wan] IPV6CP: LayerUp Jun 30 17:57:42 ppp [wan] IPV6CP: state change Ack-Rcvd --> Opened Jun 30 17:57:42 ppp [wan] IPV6CP: SendConfigAck #82 Jun 30 17:57:42 ppp [wan] IPV6CP: rec'd Configure Request #82 (Ack-Rcvd) Jun 30 17:57:42 ppp [wan] IPV6CP: state change Req-Sent --> Ack-Rcvd Jun 30 17:57:42 ppp [wan] IPV6CP: rec'd Configure Ack #9 (Req-Sent) Jun 30 17:57:42 ppp [wan] IPV6CP: SendConfigReq #9 Jun 30 17:57:40 ppp [wan] IPV6CP: SendTerminateAck #8 Jun 30 17:57:40 ppp [wan] IPV6CP: state change Ack-Sent --> Req-Sent Jun 30 17:57:40 ppp [wan] IPV6CP: rec'd Terminate Request #168 (Ack-Sent) Jun 30 17:57:40 ppp [wan] IPV6CP: state change Req-Sent --> Ack-Sent Jun 30 17:57:40 ppp [wan] IPV6CP: SendConfigAck #167 Jun 30 17:57:40 ppp [wan] IPV6CP: rec'd Configure Request #167 (Req-Sent) Jun 30 17:57:40 ppp [wan] IPV6CP: SendTerminateAck #7 Jun 30 17:57:40 ppp [wan] IPV6CP: rec'd Terminate Request #166 (Req-Sent) Jun 30 17:57:40 ppp [wan] IPV6CP: SendTerminateAck #6 Jun 30 17:57:40 ppp [wan] IPV6CP: state change Ack-Rcvd --> Req-Sent Jun 30 17:57:40 ppp [wan] IPV6CP: rec'd Terminate Request #165 (Ack-Rcvd) Jun 30 17:57:40 ppp [wan] IPV6CP: state change Req-Sent --> Ack-Rcvd Jun 30 17:57:40 ppp [wan] IPV6CP: rec'd Configure Ack #5 (Req-Sent) Jun 30 17:57:40 ppp [wan] IPV6CP: SendConfigReq #5 Jun 30 17:57:38 ppp [wan] IPV6CP: SendTerminateAck #4 Jun 30 17:57:38 ppp [wan] IPV6CP: state change Ack-Sent --> Req-Sent Jun 30 17:57:38 ppp [wan] IPV6CP: rec'd Terminate Request #19 (Ack-Sent) Jun 30 17:57:38 ppp [wan] IPV6CP: state change Req-Sent --> Ack-Sent Jun 30 17:57:38 ppp [wan] IPV6CP: SendConfigAck #18 Jun 30 17:57:38 ppp [wan] IPV6CP: rec'd Configure Request #18 (Req-Sent) Jun 30 17:57:38 ppp [wan] IFACE: Rename interface ng0 to pppoe1 Jun 30 17:57:38 ppp [wan] IFACE: Up event Jun 30 17:57:38 check_reload_status rc.newwanip starting pppoe1 Jun 30 17:57:38 root ppp-linkup IF: pppoe1 | PROTOCOL: inet | LOCAL_IP: 95.247.53.52/32 | REMOTE_IP: 192.168.100.1 | AUTH_NAME: - | DNS1_RAW: | DNS2_RAW: Jun 30 17:57:38 ppp [wan] 95.247.53.52 -> 192.168.100.1 Jun 30 17:57:38 ppp [wan] IPCP: LayerUp Jun 30 17:57:38 ppp [wan] IPCP: state change Ack-Rcvd --> Opened Jun 30 17:57:38 ppp [wan] IPADDR 192.168.100.1 Jun 30 17:57:38 ppp [wan] IPCP: SendConfigAck #175 Jun 30 17:57:38 ppp [wan] 192.168.100.1 is OK Jun 30 17:57:38 ppp [wan] IPADDR 192.168.100.1 Jun 30 17:57:38 ppp [wan] IPCP: rec'd Configure Request #175 (Ack-Rcvd) Jun 30 17:57:38 ppp [wan] IPV6CP: SendTerminateAck #3 Jun 30 17:57:38 ppp [wan] IPV6CP: rec'd Terminate Request #17 (Req-Sent) Jun 30 17:57:38 ppp [wan] IPV6CP: SendTerminateAck #2 Jun 30 17:57:38 ppp [wan] IPV6CP: state change Ack-Rcvd --> Req-Sent Jun 30 17:57:38 ppp [wan] IPV6CP: rec'd Terminate Request #16 (Ack-Rcvd) Jun 30 17:57:38 ppp [wan] IPCP: state change Req-Sent --> Ack-Rcvd Jun 30 17:57:38 ppp [wan] IPADDR 95.247.53.52 Jun 30 17:57:38 ppp [wan] IPCP: rec'd Configure Ack #3 (Req-Sent) Jun 30 17:57:38 ppp [wan] IPADDR 95.247.53.52 Jun 30 17:57:38 ppp [wan] IPCP: SendConfigReq #3 Jun 30 17:57:38 ppp [wan] 95.247.53.52 is OK Jun 30 17:57:38 ppp [wan] IPADDR 95.247.53.52 Jun 30 17:57:38 ppp [wan] IPCP: rec'd Configure Nak #2 (Req-Sent) Jun 30 17:57:38 ppp [wan] IPV6CP: state change Req-Sent --> Ack-Rcvd Jun 30 17:57:38 ppp [wan] IPV6CP: rec'd Configure Ack #1 (Req-Sent) Jun 30 17:57:38 ppp [wan] IPADDR 0.0.0.0 Jun 30 17:57:38 ppp [wan] IPCP: SendConfigReq #2 Jun 30 17:57:38 ppp [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Jun 30 17:57:38 ppp [wan] IPCP: rec'd Configure Reject #1 (Req-Sent) Jun 30 17:57:38 ppp [wan] IPV6CP: SendConfigReq #1 Jun 30 17:57:38 ppp [wan] IPV6CP: state change Starting --> Req-Sent Jun 30 17:57:38 ppp [wan] IPV6CP: Up event Jun 30 17:57:38 ppp [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Jun 30 17:57:38 ppp [wan] IPADDR 0.0.0.0 Jun 30 17:57:38 ppp [wan] IPCP: SendConfigReq #1 Jun 30 17:57:38 ppp [wan] IPCP: state change Starting --> Req-Sent Jun 30 17:57:38 ppp [wan] IPCP: Up event Jun 30 17:57:38 ppp [wan] IPV6CP: LayerStart Jun 30 17:57:38 ppp [wan] IPV6CP: state change Initial --> Starting Jun 30 17:57:38 ppp [wan] IPV6CP: Open event Jun 30 17:57:38 ppp [wan] IPCP: LayerStart Jun 30 17:57:38 ppp [wan] IPCP: state change Initial --> Starting Jun 30 17:57:38 ppp [wan] IPCP: Open event Jun 30 17:57:38 ppp [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps Jun 30 17:57:38 ppp [wan_link0] Link: Join bundle "wan" Jun 30 17:57:38 ppp [wan_link0] Link: Matched action 'bundle "wan" ""' Jun 30 17:57:38 ppp [wan_link0] LCP: authorization successful Jun 30 17:57:38 ppp [wan_link0] PAP: rec'd ACK #1 len: 5 Jun 30 17:57:38 ppp [wan_link0] LCP: LayerUp Jun 30 17:57:38 ppp [wan_link0] PAP: sending REQUEST #1 len: 24 Jun 30 17:57:38 ppp [wan_link0] PAP: using authname "aliceadsl" Jun 30 17:57:38 ppp [wan_link0] LCP: auth: peer wants PAP, I want nothing Jun 30 17:57:38 ppp [wan_link0] LCP: state change Ack-Sent --> Opened Jun 30 17:57:38 ppp [wan_link0] MAGICNUM 0x959498d9 Jun 30 17:57:38 ppp [wan_link0] MRU 1492 Jun 30 17:57:38 ppp [wan_link0] PROTOCOMP Jun 30 17:57:38 ppp [wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent) Jun 30 17:57:38 ppp [wan_link0] LCP: state change Req-Sent --> Ack-Sent Jun 30 17:57:38 ppp [wan_link0] MAGICNUM 0x484e41c9 Jun 30 17:57:38 ppp [wan_link0] AUTHPROTO PAP Jun 30 17:57:38 ppp [wan_link0] MRU 1492 Jun 30 17:57:38 ppp [wan_link0] LCP: SendConfigAck #51 Jun 30 17:57:38 ppp [wan_link0] MAGICNUM 0x484e41c9 Jun 30 17:57:38 ppp [wan_link0] AUTHPROTO PAP Jun 30 17:57:38 ppp [wan_link0] MRU 1492 Jun 30 17:57:38 ppp [wan_link0] LCP: rec'd Configure Request #51 (Req-Sent) Jun 30 17:57:38 ppp [wan_link0] MAGICNUM 0x959498d9 Jun 30 17:57:38 ppp [wan_link0] MRU 1492 Jun 30 17:57:38 ppp [wan_link0] PROTOCOMP Jun 30 17:57:38 ppp [wan_link0] LCP: SendConfigReq #1 Jun 30 17:57:38 ppp [wan_link0] LCP: state change Starting --> Req-Sent Jun 30 17:57:38 ppp [wan_link0] LCP: Up event Jun 30 17:57:38 ppp [wan_link0] Link: UP event Jun 30 17:57:38 ppp [wan_link0] PPPoE: connection successful Jun 30 17:57:38 ppp PPPoE: rec'd ACNAME "r-rm900" Jun 30 17:57:38 ppp [wan_link0] PPPoE: Connecting to 'TelecomFibra' Jun 30 17:57:38 ppp [wan_link0] LCP: LayerStart Jun 30 17:57:38 ppp [wan_link0] LCP: state change Initial --> Starting Jun 30 17:57:38 ppp [wan_link0] LCP: Open event Jun 30 17:57:38 kernel ng0: changing name to 'pppoe1' Jun 30 17:57:38 ppp [wan_link0] Link: OPEN event Jun 30 17:57:38 ppp [wan] Bundle: Interface ng0 created Jun 30 17:57:38 ppp web: web is not running Jun 30 17:57:38 ppp process 38583 started, version 5.8 (root@pfSense_v2_3_1_amd64-pfSense_v2_3_1-job-13 19:20 16-May-2016) Jun 30 17:57:38 ppp Multi-link PPP daemon for FreeBSD Jun 30 17:57:37 xinetd 13847 Reconfigured: new=0 old=1 dropped=0 (services) Jun 30 17:57:37 xinetd 13847 readjusting service 6969-udp Jun 30 17:57:37 xinetd 13847 Swapping defaults Jun 30 17:57:37 xinetd 13847 Starting reconfiguration Jun 30 17:57:36 php-fpm 42987 /rc.newipsecdns: IPsec ERROR: Could not find phase 1 source for connection Soflab MI (FW-MI01 Endpoint). Omitting from configuration file. Jun 30 17:57:36 php-fpm 42987 /rc.newipsecdns: IPsec ERROR: Could not find phase 1 source for connection Soflab RM (FW-LW01 Endpoint). Omitting from configuration file. Jun 30 17:57:36 check_reload_status Reloading filter Jun 30 17:57:36 php-fpm 42987 /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing. Jun 30 17:57:20 xinetd 13847 Reconfigured: new=0 old=1 dropped=0 (services) Jun 30 17:57:20 xinetd 13847 readjusting service 6969-udp Jun 30 17:57:20 xinetd 13847 Swapping defaults Jun 30 17:57:20 xinetd 13847 Starting reconfiguration Jun 30 17:57:20 php-fpm 42987 /rc.newipsecdns: IPsec ERROR: Could not find phase 1 source for connection Soflab MI (FW-MI01 Endpoint). Omitting from configuration file. Jun 30 17:57:20 php-fpm 42987 /rc.newipsecdns: IPsec ERROR: Could not find phase 1 source for connection Soflab RM (FW-LW01 Endpoint). Omitting from configuration file. Jun 30 17:57:20 check_reload_status Reloading filter Jun 30 17:57:20 php-fpm 42987 /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing. Jun 30 17:57:04 php-fpm 42987 /rc.dyndns.update: Dynamic DNS (310435) There was an error trying to determine the public IP for interface - wan (pppoe1 ). Jun 30 17:57:03 php-fpm 42987 /rc.dyndns.update: Dynamic DNS (casalener.mooo.com) There was an error trying to determine the public IP for interface - wan (pppoe1 ). Jun 30 17:57:03 php-fpm 42987 /rc.dyndns.update: Dynamic DNS (casalener.mooo.com): running get_failover_interface for wan. found pppoe1 Jun 30 17:57:03 php-fpm 42987 /rc.dyndns.update: Dynamic DNS: updatedns() starting Jun 30 17:57:02 php-fpm 42987 /rc.dyndns.update: Dynamic DNS (casalener.no-ip.info) There was an error trying to determine the public IP for interface - wan (pppoe1 ). Jun 30 17:57:01 check_reload_status Reloading filter Jun 30 17:57:01 check_reload_status Restarting OpenVPN tunnels/interfaces Jun 30 17:57:01 check_reload_status Restarting ipsec tunnels Jun 30 17:57:01 check_reload_status updating dyndns HE_IPV6_TUNNELV6 Jun 30 17:57:00 check_reload_status Reloading filter Jun 30 17:57:00 check_reload_status Restarting OpenVPN tunnels/interfaces Jun 30 17:57:00 check_reload_status Restarting ipsec tunnels Jun 30 17:57:00 check_reload_status updating dyndns WAN_PPPOE Jun 30 17:57:00 syslogd kernel boot file is /boot/kernel/kernelThanks in advance,
-
I have similar problem on one pfSense box after upgrade from 2.2 to 2.3, but my WAN interface is L2TP, not PPPoE.
- No default gateway after reboot;
- /tmp/l2tp1_defaultgw is empty after reboot;
- Edit+save of WAN interface or WAN gateway restores default route.
-
I have similar problem on one pfSense box after upgrade from 2.2 to 2.3, but my WAN interface is L2TP, not PPPoE.
- No default gateway after reboot;
- /tmp/l2tp1_defaultgw is empty after reboot;
- Edit+save of WAN interface or WAN gateway restores default route.
Have you try the mod to the code i post?
-
Thanks for the additional details Marlenio. Not immediately clear what's going on there, and we're about to release 2.3.2. In the interest of fixing this more common issue rather than the less common issue removing "set iface route default" fixed, I brought back 2.2.6 and prior behavior here for 2.3.2.
-
Thank you Chris,
tomorrow i install latest 2.3.2 build with fix. :)EDIT: test with 2.3.2 snapshot 20160715.0559. Works. :)
Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.