No internet connection after upgrade from April 20 snapshot to May 19

PiBa · Jun 9, 2018, 3:59 PM

Okay seems i can reproduce it now with a reboot while WAN nic is disconnected, then after enabling the wan-nic, it does get a IP, but the default-route isn't set. Then when the PPPOE server side is restarted, the PPPOE client does automatically re-connected and then does set its default-route that time..

Trying to figure out now how where/how the first connection doesn't set the gateway and the second does. Seems to me like both should follow almost the same steps when the connection is established.

PiBa · Jun 9, 2018, 5:52 PM

FYI
what im seeing is this in my systemlog, both times the rc.newwanip is running, but only the second time it tells "Default gateway setting Interface WAN_PPPOE Gateway as default".
I presume you have something similar to the first one in your log.?

Jun 9 15:51:30	php-fpm	321	/rc.start_packages: Restarting/Starting all packages.
Jun 9 15:51:28	check_reload_status		Starting packages
Jun 9 15:51:28	php-fpm	322	/rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 10.30.20.163 -> 10.30.20.163 - Restarting packages.
Jun 9 15:51:26	php-fpm	322	/rc.newwanip: Creating rrd update script
Jun 9 15:51:26	php-fpm	322	/rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Jun 9 15:51:23	php-fpm	322	/rc.newwanip: Default gateway setting Interface WAN_PPPOE Gateway as default.
Jun 9 15:51:23	php-fpm	322	/rc.newwanip: rc.newwanip: on (IP address: 10.30.20.163) (interface: WAN[wan]) (real interface: pppoe0).
Jun 9 15:51:23	php-fpm	322	/rc.newwanip: rc.newwanip: Info: starting on pppoe0.
Jun 9 15:51:22	ppp		[wan] IFACE: Rename interface ng0 to pppoe0

Jun 9 15:47:55	php-fpm	73857	/rc.start_packages: Restarting/Starting all packages.
Jun 9 15:47:54	check_reload_status		Starting packages
Jun 9 15:47:54	php-fpm	321	/rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 10.30.20.163 -> 10.30.20.163 - Restarting packages.
Jun 9 15:47:52	php-fpm	321	/rc.newwanip: Creating rrd update script
Jun 9 15:47:52	php-fpm	321	/rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Jun 9 15:47:48	php-fpm	321	/rc.newwanip: rc.newwanip: on (IP address: 10.30.20.163) (interface: WAN[wan]) (real interface: pppoe0).
Jun 9 15:47:48	php-fpm	321	/rc.newwanip: rc.newwanip: Info: starting on pppoe0.
Jun 9 15:47:47	ppp		[wan] IFACE: Rename interface ng0 to pppoe0

w0w · Jun 9, 2018, 6:36 PM

@piba
Yep, looks exactly like that. Both. I've just found that on the latest snapshot it works a little bit different way or I just missed it before:
After setting my dynamic gateway manually as default I see that line

/rc.newwanip: Default gateway setting Interface WAN_PPPOE Gateway as default.

then I rebooted firewall and looked at system log again — when PPPoE starts on boot, I don't see this line anymore, system log is exactly like your second one and default route is missing, certainly. If I manually re-connect PPPoE without changing anything else, then I see this line again and everything works like it should be.

PiBa · Jun 9, 2018, 8:36 PM

It seems the dynamic pppoe gateway does not have a status yet when it hasn't connected before.. And the code assumes its a gatewaygroup as it cannot find the status a normal gateway normally does have..
Would you be able to try this little patch with 1 changed line ?:

 src/etc/inc/gwlb.inc | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/etc/inc/gwlb.inc b/src/etc/inc/gwlb.inc
index 9a059a7..e0b94be 100644
--- a/src/etc/inc/gwlb.inc
+++ b/src/etc/inc/gwlb.inc
@@ -1032,7 +1032,7 @@ function fixup_default_gateway($ipprotocol, $gateways_status, $gateways_arr) {
 	} else {
 		$gwdefault = $config['gateways']['defaultgw6'];
 	}
-	if (isset($gateways_status[$gwdefault])) {
+	if (isset($gateways_arr[$gwdefault])) {
 		// the configured gateway is a regular one. (not a gwgroup) use it as is..
 		$dfltgwname = $gwdefault;
 	} else {

PiBa · Jun 9, 2018, 10:45 PM

Redmine ticked and fix submitted for review: https://redmine.pfsense.org/issues/8561

w0w · Jun 10, 2018, 4:01 AM

@piba
I have patched manually this line, but problem still exists.
I need to select gateway manually and it works until reboot, after reboot I need 'Disconnect'/'Connect' PPPoE to make it work.
🔒 Log in to view
Also I am confused with that:
🔒 Log in to view

PiBa · Jun 10, 2018, 1:06 PM

That it says 'Default (IPv6)' seems just a 'display issue'. It is determined by a function that doesn't take dynamic gateways into account currently. Anyhow added a fix to the PR for that https://github.com/pfsense/pfsense/pull/3947/commits/092abdb6005072365bc860966b0e2ffce8d85e1b

Can you add this logging below and run another test? Please let me know what it tells. as my 'reproduction' is nolonger failing with the patch above and i'm currently out of ideas where to look, sorry but this is probably going to take a few rounds of trial and error.:

 src/etc/inc/gwlb.inc | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/src/etc/inc/gwlb.inc b/src/etc/inc/gwlb.inc
index 7b157b5..3a70fe3 100644
--- a/src/etc/inc/gwlb.inc
+++ b/src/etc/inc/gwlb.inc
@@ -1105,6 +1105,8 @@ function fixup_default_gateway($ipprotocol, $gateways_status, $gateways_arr) {
 			}
 		}
 	}
+	log_error("fixup_default_gateway  dfltgwdown:{$dfltgwdown} upgw:{$upgw}  dfltgwname:{$dfltgwname} , gwdefault:{$gwdefault}");
+	log_error("gateways_arr:".print_r($gateways_arr,true));
 	if ($dfltgwdown == true && !empty($upgw)) {
 		setdefaultgateway($gateways_arr[$upgw]);
 	} else if (!empty($dfltgwname)) {

w0w · Jun 10, 2018, 5:25 PM

@piba
Thats fun! This comes on system boot BEFORE PPPoE connection is established :

Jun 10 19:49:56 	php-cgi 		rc.bootup: gateways_arr:Array ( [WAN_PPPOE] => Array ( [dynamic] => [ipprotocol] => inet [gateway] => [interface] => pppoe0 [friendlyiface] => wan [name] => WAN_PPPOE [attribute] => system [descr] => Interface WAN_PPPOE Gateway ) [Null4] => Array ( [name] => Null4 [interface] => lo0 [ipprotocol] => inet [gateway] => 127.0.0.1 ) [Null6] => Array ( [name] => Null6 [interface] => lo0 [ipprotocol] => inet6 [gateway] => ::1 ) )
Jun 10 19:49:56 	php-cgi 		rc.bootup: fixup_default_gateway dfltgwdown: upgw: dfltgwname: , gwdefault:
Jun 10 19:49:56 	php-cgi 		rc.bootup: gateways_arr:Array ( [WAN_PPPOE] => Array ( [dynamic] => [ipprotocol] => inet [gateway] => [interface] => pppoe0 [friendlyiface] => wan [name] => WAN_PPPOE [attribute] => system [descr] => Interface WAN_PPPOE Gateway ) [Null4] => Array ( [name] => Null4 [interface] => lo0 [ipprotocol] => inet [gateway] => 127.0.0.1 ) [Null6] => Array ( [name] => Null6 [interface] => lo0 [ipprotocol] => inet6 [gateway] => ::1 ) )

PPPoE is established 2 seconds later just start of session!

Jun 10 19:49:58 	ppp 		[wan_link0] PPPoE: connection successful

And this coming when I manually re-connect PPPoE

Jun 10 19:53:28 	php-fpm 	335 	/rc.newwanip: gateways_arr:Array ( [WAN_PPPOE] => Array ( [dynamic] => 1 [ipprotocol] => inet [gateway] => 212.7.29.236 [interface] => pppoe0 [friendlyiface] => wan [name] => WAN_PPPOE [attribute] => system [monitor] => 212.7.29.236 [descr] => Interface WAN_PPPOE Gateway ) [Null4] => Array ( [name] => Null4 [interface] => lo0 [ipprotocol] => inet [gateway] => 127.0.0.1 ) [Null6] => Array ( [name] => Null6 [interface] => lo0 [ipprotocol] => inet6 [gateway] => ::1 ) )
Jun 10 19:53:28 	php-fpm 	335 	/rc.newwanip: fixup_default_gateway dfltgwdown: upgw: dfltgwname: , gwdefault:
Jun 10 19:53:28 	php-fpm 	335 	/rc.newwanip: Default gateway setting Interface WAN_PPPOE Gateway as default.
Jun 10 19:53:28 	php-fpm 	335 	/rc.newwanip: gateways_arr:Array ( [WAN_PPPOE] => Array ( [dynamic] => 1 [ipprotocol] => inet [gateway] => 212.7.29.236 [interface] => pppoe0 [friendlyiface] => wan [name] => WAN_PPPOE [attribute] => system [monitor] => 212.7.29.236 [descr] => Interface WAN_PPPOE Gateway ) [Null4] => Array ( [name] => Null4 [interface] => lo0 [ipprotocol] => inet [gateway] => 127.0.0.1 ) [Null6] => Array ( [name] => Null6 [interface] => lo0 [ipprotocol] => inet6 [gateway] => ::1 ) )

PPPoE session is established completely 1 second before:

Jun 10 19:53:27 	ppp 		[wan] IFACE: Rename interface ng0 to pppoe0

PiBa · Jun 10, 2018, 6:09 PM

I suppose between the 'Rename interface ng0 to pppoe0' and the manual re-connect you do have these 2 lines?:

Jun 10 19:49:13	php-fpm	322	/rc.newwanip: rc.newwanip: on (IP address: 10.30.20.163) (interface: WAN[wan]) (real interface: pppoe0).
Jun 10 19:49:13	php-fpm	322	/rc.newwanip: rc.newwanip: Info: starting on pppoe0.

And then the "rc.newwanip" just stops running .? While it should log a few more lines and set the gateway like in previous posts.? I think there is a race condition there where the script exit's during bootup...

w0w · Jun 10, 2018, 6:30 PM

@piba
Here is more:

PiBa · Jun 10, 2018, 7:00 PM

Yep thats the 2 lines right there..

Jun 10 19:50:00 	php-fpm 	334 	/rc.newwanip: rc.newwanip: on (IP address: 84.52.**.200) (interface: WAN[wan]) (real interface: pppoe0).
Jun 10 19:50:00 	php-fpm 	334 	/rc.newwanip: rc.newwanip: Info: starting on pppoe0.

So indeed in your case it is 'aborting' that script before its done running.
Seems like this 'exit' is supposed to be avoiding a race condition where its actually causing one...:
https://github.com/pfsense/pfsense/blob/d84eec807d6216cfbc073438ce57e01f1c52a2f4/src/etc/rc.newwanip#L192

@jimp any insights on what would be the right order to call things?

initialize PPPOE-client while booting
initialize routes and packages and rules and stuff after PPPOE gets connected
finish the rc.newwanip to configure routes and other things that depends on the newly assigned wan-ip..
finish booting..

I think it was previously working because every call to return_gateway_groups_array() would again try and fix the gateways.. and eventually one did catch.. Now the return_gateway_groups_array() most of the time skips these actions as fixing the gateway should not happen as a 'side-effect' of 'requesting information'.. But that does seem to cause this problem..

PiBa · Jun 10, 2018, 7:15 PM

Perhaps the fix could be as simple as removing that 'exit' from the rc.newwanip .? (in addition to the PR made)

w0w · Jun 11, 2018, 4:04 AM

@piba
I've deleted this line and this fixes the problem with connection on boot, really.

PiBa · Jun 15, 2018, 4:10 AM

@w0w
I've discussed with jimp, and he didn't like removing the exit completely to avoid bringing the old previous race condition back. we agreed upon a specific 'ppp check' to avoid the exit. Can you put the exit back in, but apply this extra check instead.? That should still fix the issue.. does it.? :

https://github.com/pfsense/pfsense/pull/3947/commits/627b0941889f4b19ad419ddfe01d329bef2c2bd6

w0w · Jun 15, 2018, 4:10 AM

@piba
Looks like with BOTH (gwlib.inc and rc.newwanip) fixes applied — I now have internet connection. One thing is still need to be fixed — after upgrade from previous version and after applying those patches I need also to select default gateway in drop-down list on system_gateways.php page.
If I restore old configuration on patched system the same thing happens also, I need manually select gateway on system_gateways.php via GUI, is it feature or bug?

PiBa · Jun 15, 2018, 7:10 PM

Yes the first link https://github.com/pfsense/pfsense/pull/3947 contains 3 fixes/commits, the 2 you refer to, and one that fixes the displaying of the IPv6 for a IPv4 gateway..

The gui 'none' selection is is still something to fix. Lets call that a 'unwanted feature' ;) . Ill probably work on that soon..

w0w · Jun 16, 2018, 6:07 AM

@piba
Thank you, let me know if you need further testing.

PiBa · Jun 23, 2018, 5:27 PM

@w0w
Thank you for testing and reporting back each time :).

Can you try latest snapshot? Its build with these (slightly modified) fixes included.

p.s. not the 'none' selection yet though, still working on that.

w0w · Jun 24, 2018, 5:10 AM

@piba
I have tried this one:

2.4.4-DEVELOPMENT (amd64)
built on Sat Jun 23 01:57:55 EDT 2018
FreeBSD 11.2-RC3

I've found that internet not working with this snapshot on reboot, but both fixes are present.
I think it's modified line that was looked like

if (platform_booting() && strpos($interface_real, "ppp") !== 0) {

before,
and now it's

if (platform_booting() && in_array(substr($interface_real, 0, 3), array("ppp", "ppt", "l2t"))) {

because if I change it back, it works again.

PiBa · Jun 24, 2018, 1:13 PM

@w0w
Ah crap, i forgot to do the inverse, '!'.

if (platform_booting() && !in_array(substr($interface_real, 0, 3), array("ppp", "ppt", "l2t"))) {

sorry, thanks for testing!

new PR made: https://github.com/pfsense/pfsense/pull/3956