Nasty pppoe reconnection bug returns in 2.2 RC
-
im on the alix nanobsd 2.2 RC and it seems the old bug has returned mentioned in the below bounty page. If my fiber optic modem goes down and then up or its reset then pfsense wont connect at all unless its rebooted
-
I am not sure but there are a lot of changes since this commit https://github.com/pfsense/pfsense/commit/9510780ffa41bf1b19989b418e9a356702ba5576
and mpd version is also changed, I think you need to continue your old thread with posting new logs. -
other than the above commit, there was one more to the nic driver and that was the main reason why reconenct wasnt working, log wise the situation is the same
-
Is you modem connected to straight cable to pfSense.
Than the linkup message on your nic(vr0/re0) will trigger re-creation of the session.Can you provide your log messages from system on this?
-
my modem has always been connected to pfsense directly and even using a switch it doesnt help the situation, the last time the bug was fixed in the mentioned bounty thread, it had worked flawless but since 2.2 seems back to square one
system log
Dec 15 17:35:11 kernel: vr1: link state changed to DOWN Dec 15 17:35:40 check_reload_status: Configuring interface wan Dec 15 17:35:44 php: rc.kill_states: rc.kill_states: Removing states for IP 92.98.234.6/32 Dec 15 17:35:44 check_reload_status: Rewriting resolv.conf Dec 15 17:36:02 syslogd: exiting on signal 15 Dec 15 17:36:03 syslogd: kernel boot file is /boot/kernel/kernel Dec 15 17:36:09 kernel: ovpnc1: link state changed to DOWN Dec 15 17:36:13 check_reload_status: Linkup starting vr1 Dec 15 17:36:13 kernel: vr1: link state changed to UP Dec 15 17:36:17 check_reload_status: updating dyndns WAN Dec 15 17:36:17 check_reload_status: Restarting ipsec tunnels Dec 15 17:36:17 check_reload_status: Restarting OpenVPN tunnels/interfaces Dec 15 17:36:17 check_reload_status: Reloading filter Dec 15 17:36:17 check_reload_status: updating dyndns EXPRESSVPN_VPNV4 Dec 15 17:36:17 check_reload_status: Restarting ipsec tunnels Dec 15 17:36:17 check_reload_status: Restarting OpenVPN tunnels/interfaces Dec 15 17:36:21 php-fpm[63344]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN. Dec 15 17:36:21 php-fpm[63344]: /rc.openvpn: OpenVPN: Resync client1 ExpressVPN Dec 15 17:36:21 check_reload_status: Reloading filter Dec 15 17:36:23 php-fpm[62053]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:23 php-fpm[62053]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:23 php-fpm[62053]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:23 php-fpm[62053]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:24 php-fpm[62053]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:24 php-fpm[62053]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:24 php-fpm[62053]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:24 php-fpm[62053]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:24 php-fpm[62053]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:28 php-fpm[63344]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use EXPRESSVPN_VPNV4. Dec 15 17:36:29 login: login on ttyu0 as root Dec 15 17:36:29 sshlockout[70842]: sshlockout/webConfigurator v3.0 starting up Dec 15 17:36:33 php-fpm[63597]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:33 php-fpm[63597]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:33 php-fpm[63597]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:33 php-fpm[63597]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:33 php-fpm[63597]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:33 php-fpm[63597]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:33 php-fpm[63597]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:33 php-fpm[63597]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 15 17:36:34 php-fpm[63597]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
ppp log
Dec 15 17:36:07 ppp: [wan_link0] Link: DOWN event Dec 15 17:36:07 ppp: [wan_link0] LCP: Down event Dec 15 17:36:07 ppp: [wan_link0] Link: reconnection attempt 2 in 4 seconds Dec 15 17:36:11 ppp: [wan_link0] Link: reconnection attempt 2 Dec 15 17:36:11 ppp: [wan_link0] PPPoE: Connecting to '' Dec 15 17:36:20 ppp: [wan_link0] PPPoE connection timeout after 9 seconds Dec 15 17:36:20 ppp: [wan_link0] Link: DOWN event Dec 15 17:36:20 ppp: [wan_link0] LCP: Down event Dec 15 17:36:20 ppp: [wan_link0] Link: reconnection attempt 3 in 1 seconds Dec 15 17:36:21 ppp: [wan_link0] Link: reconnection attempt 3 Dec 15 17:36:21 ppp: [wan_link0] PPPoE: Connecting to '' Dec 15 17:36:30 ppp: [wan_link0] PPPoE connection timeout after 9 seconds Dec 15 17:36:30 ppp: [wan_link0] Link: DOWN event Dec 15 17:36:30 ppp: [wan_link0] LCP: Down event Dec 15 17:36:30 ppp: [wan_link0] Link: reconnection attempt 4 in 2 seconds Dec 15 17:36:32 ppp: [wan_link0] Link: reconnection attempt 4 Dec 15 17:36:32 ppp: [wan_link0] PPPoE: Connecting to '' Dec 15 17:36:41 ppp: [wan_link0] PPPoE connection timeout after 9 seconds Dec 15 17:36:41 ppp: [wan_link0] Link: DOWN event Dec 15 17:36:41 ppp: [wan_link0] LCP: Down event Dec 15 17:36:41 ppp: [wan_link0] Link: reconnection attempt 5 in 1 seconds
-
Which version you are running?
Normally in the RC you should have interface configure trigger the reconnection cause i see the linkup in your logs?Also can you show me the result of /tmp/rules.debug during this issue?
-
im on the below snap, nanobsd, alix
2.2-RC (i386) built on Sun Dec 14 23:20:40 CST 2014 FreeBSD 10.1-RELEASE-p1
ill get back with the logs shortly
-
here is the log, kindly delete once u have looked at it
Removed
what i remember is the patch u applied in the below commit had fixed the issue last time
https://github.com/pfsense/pfsense-tools/commit/4d298135387ef551ccc6eff62a1705059956c64e -
Can you try this patch please and let me know if it fixes the issue.
diff --git a/etc/rc.newwanip b/etc/rc.newwanip index 56c2453..63da663 100755 --- a/etc/rc.newwanip +++ b/etc/rc.newwanip @@ -237,9 +237,9 @@ if (!is_ipaddr($oldip) || $curwanip != $oldip || !is_ipaddrv4($config['interface services_snmpd_configure(); restart_packages(); -} else { - /* signal filter reload */ - filter_configure(); } +/* signal filter reload */ +filter_configure(); + ?>
-
tried it, still same, i think its something to do with the via chipset drivers, is there any way to bring it down and up or something like that which can make it work after link up because the last time there was a driver patch or something applied and then it was flawless
system log
Dec 17 16:11:41 kernel: vr1: link state changed to DOWN Dec 17 16:12:34 check_reload_status: updating dyndns WAN Dec 17 16:12:34 check_reload_status: Restarting ipsec tunnels Dec 17 16:12:34 check_reload_status: Restarting OpenVPN tunnels/interfaces Dec 17 16:12:34 check_reload_status: Reloading filter Dec 17 16:12:37 php-fpm[33561]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN. Dec 17 16:12:37 php-fpm[33561]: /rc.openvpn: OpenVPN: Resync client1 ExpressVPN Dec 17 16:12:38 php-fpm[33102]: /rc.dyndns.update: phpDynDNS (firewall): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Dec 17 16:12:38 kernel: ovpnc1: link state changed to DOWN Dec 17 16:12:38 check_reload_status: Reloading filter Dec 17 16:12:45 php: rc.kill_states: rc.kill_states: Removing states for IP 86.99.127.170/32 Dec 17 16:12:45 check_reload_status: Rewriting resolv.conf Dec 17 16:12:46 php-fpm[33265]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:46 php-fpm[33265]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:47 php-fpm[33265]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:47 php-fpm[33265]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:47 php-fpm[33265]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:47 php-fpm[33265]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:47 php-fpm[33265]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:47 php-fpm[33265]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:47 php-fpm[33265]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:53 php-fpm[33561]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:53 php-fpm[33561]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:53 php-fpm[33561]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:53 php-fpm[33561]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:53 php-fpm[33561]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:53 php-fpm[33561]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:53 php-fpm[33561]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:53 php-fpm[33561]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:53 php-fpm[33561]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 17 16:12:56 check_reload_status: Linkup starting vr1 Dec 17 16:12:56 kernel: vr1: link state changed to UP Dec 17 16:13:29 syslogd: exiting on signal 15 Dec 17 16:13:29 syslogd: kernel boot file is /boot/kernel/kernel
ppp log is same
-
Ok can you apply this and let me know if you see the new message on system log?
diff --git a/etc/rc.linkup b/etc/rc.linkup index 59e2089..b6f06dd 100755 --- a/etc/rc.linkup +++ b/etc/rc.linkup @@ -142,8 +143,10 @@ if (!empty($realiface)) { /* The loop here is because ppp types can have real and assigned interfaces as members */ $tmpiface = get_real_interface($parent_if); $tmpiface = convert_real_interface_to_friendly_interface_name($tmpiface); - if (!empty($tmpiface)) + if (!empty($tmpiface)) { + log_error("Reconfiguring $realiface, $parent_if, $tmpiface"); interface_configure($tmpiface, true, true); + } } } }
-
do i use with the first patch or shall i revert the first patch and then apply the second one?
-
It does not matter.You can apply both or either
-
i applied both and then tried but i dont seem to get that message in system log and issue is as it is
Dec 18 08:57:45 kernel: vr1: link state changed to DOWN Dec 18 08:58:49 php: rc.kill_states: rc.kill_states: Removing states for IP 2.51.127.81/32 Dec 18 08:59:01 check_reload_status: Linkup starting vr1 Dec 18 08:59:01 kernel: vr1: link state changed to UP Dec 18 08:59:41 kernel: ovpnc1: link state changed to DOWN Dec 18 08:59:41 check_reload_status: Reloading filter Dec 18 08:59:48 php-fpm[5482]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 08:59:48 php-fpm[5482]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 08:59:48 php-fpm[5482]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 08:59:48 php-fpm[5482]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 08:59:48 php-fpm[5482]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 08:59:48 php-fpm[5482]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 08:59:48 php-fpm[5482]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 08:59:48 php-fpm[5482]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 08:59:49 php-fpm[5482]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 09:00:11 php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 09:00:11 php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 09:00:11 php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 09:00:11 php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 09:00:11 php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 09:00:11 php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 09:00:12 php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 09:00:12 php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan). Dec 18 09:00:12 php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 18 08:58:18 ppp: [wan_link0] LCP: no reply to 2 echo request(s) Dec 18 08:58:38 ppp: [wan_link0] LCP: no reply to 4 echo request(s) Dec 18 08:58:48 ppp: [wan_link0] LCP: no reply to 5 echo request(s) Dec 18 08:58:48 ppp: [wan_link0] LCP: peer not responding to echo requests Dec 18 08:58:48 ppp: [wan_link0] LCP: state change Opened --> Stopping Dec 18 08:58:48 ppp: [wan_link0] Link: Leave bundle "wan" Dec 18 08:58:48 ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Dec 18 08:58:48 ppp: [wan] IPCP: Close event Dec 18 08:58:48 ppp: [wan] IPCP: state change Opened --> Closing Dec 18 08:58:48 ppp: [wan] IPCP: SendTerminateReq #4 Dec 18 08:58:48 ppp: [wan] IPCP: LayerDown Dec 18 08:58:50 ppp: [wan] IFACE: Delete route 0.0.0.0/0 2.48.4.1 failed: No such process Dec 18 08:58:50 ppp: [wan] IFACE: Down event Dec 18 08:58:50 ppp: [wan] IFACE: Rename interface pppoe0 to pppoe0 Dec 18 08:58:50 ppp: [wan] IPV6CP: Close event Dec 18 08:58:50 ppp: [wan] IPV6CP: state change Stopped --> Closed Dec 18 08:58:50 ppp: [wan] IPCP: Down event Dec 18 08:58:50 ppp: [wan] IPCP: LayerFinish Dec 18 08:58:50 ppp: [wan] Bundle: No NCPs left. Closing links... Dec 18 08:58:50 ppp: [wan] IPCP: state change Closing --> Initial Dec 18 08:58:50 ppp: [wan] IPV6CP: Down event Dec 18 08:58:50 ppp: [wan] IPV6CP: state change Closed --> Initial Dec 18 08:58:50 ppp: [wan_link0] LCP: SendTerminateReq #3 Dec 18 08:58:50 ppp: [wan_link0] LCP: LayerDown Dec 18 08:58:53 ppp: [wan_link0] LCP: SendTerminateReq #4 Dec 18 08:58:55 ppp: [wan_link0] LCP: state change Stopping --> Stopped Dec 18 08:58:55 ppp: [wan_link0] LCP: LayerFinish Dec 18 08:58:55 ppp: [wan_link0] PPPoE: connection closed Dec 18 08:58:55 ppp: [wan_link0] Link: DOWN event Dec 18 08:58:55 ppp: [wan_link0] LCP: Down event Dec 18 08:58:55 ppp: [wan_link0] LCP: state change Stopped --> Starting Dec 18 08:58:55 ppp: [wan_link0] LCP: LayerStart Dec 18 08:58:55 ppp: [wan_link0] Link: reconnection attempt 1 in 3 seconds Dec 18 08:58:58 ppp: [wan_link0] Link: reconnection attempt 1 Dec 18 08:58:58 ppp: [wan_link0] PPPoE: Connecting to ''
-
Can you show me from config.xml the interface section where pppoe is configured.
Also from ppp section related to this interface? -
<interfaces><wan><if>pppoe0</if> <bandwidth>100</bandwidth> <bandwidthtype>Mb</bandwidthtype> <spoofmac><disableftpproxy><enable><blockpriv><blockbogons><mtu>1492</mtu> <ipaddr>pppoe</ipaddr></blockbogons></blockpriv></enable></disableftpproxy></spoofmac></wan> <lan><if>vr0</if> <bandwidth>100</bandwidth> <bandwidthtype>Mb</bandwidthtype> <bridge><disableftpproxy><enable><spoofmac><ipaddr>192.168.0.1</ipaddr> <subnet>24</subnet></spoofmac></enable></disableftpproxy></bridge></lan> <opt2><if>ovpnc1</if> <spoofmac><enable></enable></spoofmac></opt2></interfaces>
<ppps><ppp><ptpid>0</ptpid> <type>pppoe</type> <if>pppoe0</if> <ports>vr1</ports> <username>username</username> <password>password</password> <ondemand><bandwidth><mtu><mru><mrru><provider><pppoe-reset-type>custom</pppoe-reset-type></provider></mrru></mru></mtu></bandwidth></ondemand></ppp></ppps>
-
I just pushed a fix beacause the code in rc.linkup was wrong.
The commit will apear or on github for you to test.
-
could u kindly give me the link so i can test?
-
ok dont bother, found it and applied and seems to work but will test once more tomorrow after a reboot and all possible scenarios and then give u final confirmation.
bytheway i found one bug, when pppoe reconnects, the serial console shows this which actually it shouldnt (check the last 2 lines)
FreeBSD/i386 (firewall) (ttyu0) *** Welcome to pfSense 2.2-RC-nanobsd (i386) on firewall *** WAN (wan) -> pppoe0 -> v4/PPPoE: x.x.x.x/32 LAN (lan) -> vr0 -> v4: 192.168.0.1/24 VPN (opt2) -> ovpnc1 -> v4: 10.10.0.222/32 0) Logout (SSH only) 9) pfTop 1) Assign Interfaces 10) Filter Logs 2) Set interface(s) IP address 11) Restart webConfigurator 3) Reset webConfigurator password 12) pfSense Developer Shell 4) Reset to factory defaults 13) Upgrade from console 5) Reboot system 14) Disable Secure Shell (sshd) 6) Halt system 15) Restore recent configuration 7) Ping host 16) Restart PHP-FPM 8) Shell Enter an option: Dec 18 18:45:13 php-fpm[52868]: /rc.newwanip: Removing static r oute for monitor y.y.y.y and adding a new route through z.z.z.z
-
The error log is during bootup or after?