Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Not connecting over some internet connections Ubuntu 19.04 & 20.04 #764

Open
ke7kto opened this issue Aug 4, 2020 · 13 comments
Open

Not connecting over some internet connections Ubuntu 19.04 & 20.04 #764

ke7kto opened this issue Aug 4, 2020 · 13 comments

Comments

@ke7kto
Copy link

ke7kto commented Aug 4, 2020

I've come across a weird error that is outside my skills to fix, but I assume the problem may rest with openfortivpn. When I attempt to connect to my university VPN (which requires TFA) over a satellite connection (HughesNet, very slow), the two-factor authentication comes up successfully, and the service is authenticated, but the tunnel is never established. The error I'm seeing is ERROR: Timed out waiting for the ppp interface to be UP.

I can successfully connect the VPN if I use my phone's USB tethering. I have attached a sample of the verbose output with the timeout, and of the working connection.

forti_error.log
forti_tethering_working.log

@DimitriPapadopoulos
Copy link
Collaborator

DimitriPapadopoulos commented Aug 5, 2020

I suspect this a malfunction of the satellite connection, have a look at the path MTU using ping or tracepath:

@DimitriPapadopoulos
Copy link
Collaborator

See also:
Understand MTU and MRU – The Full Story.

@ke7kto
Copy link
Author

ke7kto commented Aug 5, 2020

The path MTU is 1500 for the satellite connection and 1430 for the tethered connection. The satellite connection works to establish the VPN if I boot up windows and use Windows FortiClient 6.0.4.0182, so there has to be something else going on as well.

@DimitriPapadopoulos
Copy link
Collaborator

The Windows FortiClient might be using VPN IPSec instead of VPN SSL. You'd have to make sure you're using VPN SSL when testing on Windows.

Can you show the output of ping when attempting to reach the VPN gateway through either networks, with the maximal MTU and then with the maximal MTU + 1? For example in my case the MTU is 1492:

$ ping -s $((1492 - 28)) -M do vpn2.case.edu -c 1
PING vpn2.case.edu (192.5.113.4) 1464(1492) bytes of data.
1472 bytes from 192.5.113.4 (192.5.113.4): icmp_seq=1 ttl=232 time=306 ms

--- vpn2.case.edu ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 306.509/306.509/306.509/0.000 ms
$ 
$ ping -s $((1492 - 28 + 1)) -M do vpn2.case.edu -c 1
PING vpn2.case.edu (192.5.113.4) 1465(1493) bytes of data.
ping: local error: Message too long, mtu=1492

--- vpn2.case.edu ping statistics ---
1 packets transmitted, 0 received, +1 errors, 100% packet loss, time 0ms

$ 

@ke7kto
Copy link
Author

ke7kto commented Aug 6, 2020

I believe you are right that my Windows client is using IPSec, I remember seeing that somewhere. Thank you for helping with this, by the way. Here are the results of using ping for the satellite network:

me@home:~$ ping -s $((1500 - 28)) -M do vpn2.case.edu -c 1
PING vpn2.cwru.edu (192.5.113.4) 1472(1500) bytes of data. 
1480 bytes from 192.5.113.4: icmp_seq=1 ttl=229 time=752 ms

--- vpn2.cwru.edu ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 752.086/752.086/752.086/0.000 ms
me@home:~$ ping -s $((1500 - 28 + 1)) -M do vpn2.case.edu -c 1
PING vpn2.cwru.edu (192.5.113.4) 1473(1501) bytes of data.
ping: local error: message too long, mtu=1500

--- vpn2.cwru.edu ping statistics ---
1 packets transmitted, 0 received, +1 errors, 100% packet loss, time 0ms

and for the cell phone network:

me@home:~$ ping -s $((1430 - 28)) -M do vpn2.case.edu -c 1
PING vpn2.cwru.edu (192.5.113.4) 1402(1430) bytes of data.
1410 bytes from 192.5.113.4: icmp_seq=1 ttl=237 time=136 ms

--- vpn2.cwru.edu ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 136.099/136.099/136.099/0.000 ms
me@home:~$ ping -s $((1430 - 28 + 1)) -M do vpn2.case.edu -c 1
PING vpn2.cwru.edu (192.5.113.4) 1403(1431) bytes of data.
ping: local error: message too long, mtu=1430

--- vpn2.cwru.edu ping statistics ---
1 packets transmitted, 0 received, +1 errors, 100% packet loss, time 0ms

The first time I try the slightly too large, I see a response as follows:
From _gateway (192.168.42.129) icmp_seq=1 Frag needed and DF set (mtu = 1430)

@ke7kto
Copy link
Author

ke7kto commented Aug 6, 2020

Maybe the issue is from the high latency? Also, when I connect using the network manager interface (kde), it fails immediately after I complete the two-factor authentication, but from the command line, it eventually just times out.

Here's the relevant network manager log for a working connection (cell phone):

Aug 06 10:38:22 home NetworkManager[1050]: <info>  [1596731902.0601] audit: op="connection-activate" uuid="9ae1e792-0343-4da4-a8de-dc5f645a1df4" name="Case Final" pid=2043 uid=1000 result="success"
Aug 06 10:38:22 home NetworkManager[1050]: <info>  [1596731902.0665] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",0]: Started the VPN service, PID 53539
Aug 06 10:38:22 home NetworkManager[1050]: <info>  [1596731902.0765] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",0]: Saw the service appear; activating connection
Aug 06 10:38:22 home NetworkManager[1050]: <info>  [1596731902.0866] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",0]: VPN plugin: state changed: starting (3)
Aug 06 10:38:22 home NetworkManager[53542]: INFO:   Connected to gateway.
Aug 06 10:38:27 home NetworkManager[53542]: INFO:   Authenticated.
Aug 06 10:38:28 home NetworkManager[53542]: INFO:   Remote gateway has allocated a VPN.
Aug 06 10:38:29 home pppd[53543]: Plugin /usr/lib/pppd/2.4.7/nm-fortisslvpn-pppd-plugin.so loaded.
Aug 06 10:38:29 home NetworkManager[53543]: Plugin /usr/lib/pppd/2.4.7/nm-fortisslvpn-pppd-plugin.so loaded.
Aug 06 10:38:29 home pppd[53543]: pppd 2.4.7 started by root, uid 0
Aug 06 10:38:29 home pppd[53543]: Using interface ppp0
Aug 06 10:38:29 home NetworkManager[53543]: Using interface ppp0
Aug 06 10:38:29 home NetworkManager[53543]: Connect: ppp0 <--> /dev/pts/4
Aug 06 10:38:29 home pppd[53543]: Connect: ppp0 <--> /dev/pts/4
Aug 06 10:38:29 home NetworkManager[1050]: <info>  [1596731909.2766] manager: (ppp0): new Ppp device (/org/freedesktop/NetworkManager/Devices/12)
Aug 06 10:38:30 home NetworkManager[53542]: INFO:   Got addresses: [10.X.X.231], ns [129.22.X.32, 129.22.XXX.25]
Aug 06 10:38:30 home NetworkManager[53542]: INFO:   negotiation complete
Aug 06 10:38:33 home NetworkManager[53542]: INFO:   Got addresses: [10.X.X.231], ns [129.22.X.32, 129.22.XXX.25]
Aug 06 10:38:33 home NetworkManager[53542]: INFO:   negotiation complete
Aug 06 10:38:36 home NetworkManager[53542]: INFO:   Got addresses: [10.X.X.231], ns [129.22.X.32, 129.22.XXX.25]
Aug 06 10:38:36 home NetworkManager[53542]: INFO:   negotiation complete
Aug 06 10:38:39 home NetworkManager[53542]: INFO:   Got addresses: [10.X.X.231], ns [129.22.X.32, 129.22.XXX.25]
Aug 06 10:38:39 home NetworkManager[53542]: INFO:   negotiation complete
Aug 06 10:38:42 home NetworkManager[53542]: INFO:   Got addresses: [10.X.X.231], ns [129.22.X.32, 129.22.XXX.25]
Aug 06 10:38:42 home NetworkManager[53542]: INFO:   negotiation complete
Aug 06 10:38:45 home NetworkManager[53542]: INFO:   Got addresses: [10.X.X.231], ns [129.22.X.32, 129.22.XXX.25]
Aug 06 10:38:45 home NetworkManager[53542]: INFO:   negotiation complete
Aug 06 10:38:45 home NetworkManager[53542]: INFO:   negotiation complete
Aug 06 10:38:45 home NetworkManager[53543]: local  IP address 10.X.X.231
Aug 06 10:38:45 home NetworkManager[53543]: remote IP address 192.X.X.1
Aug 06 10:38:45 home pppd[53543]: local  IP address 10.X.X.231
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1422] device (ppp0): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
Aug 06 10:38:45 home pppd[53543]: remote IP address 192.X.X.1
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1440] device (ppp0): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'external')
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1462] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",0]: VPN connection: (IP4 Config Get) reply received from old-style >
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1469] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",12:(ppp0)]: Data: VPN Gateway: 192.X.XXX.4
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1470] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",12:(ppp0)]: Data: Tunnel Device: "ppp0"
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1470] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",12:(ppp0)]: Data: IPv4 configuration:
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1470] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",12:(ppp0)]: Data:   Internal Address: 10.X.X.231
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1471] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",12:(ppp0)]: Data:   Internal Prefix: 32
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1471] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",12:(ppp0)]: Data:   Internal Point-to-Point Address: 192.X.X.1
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1471] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",12:(ppp0)]: Data:   Static Route: 0.0.0.0/0   Next Hop: 0.0.0.0
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1471] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",12:(ppp0)]: Data:   Static Route: 192.X.X.1/32   Next Hop: 0.0.0.0
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1471] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",12:(ppp0)]: Data:   DNS Domain: '(none)'
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1472] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",12:(ppp0)]: Data: No IPv6 configuration
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1472] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",12:(ppp0)]: VPN plugin: state changed: started (4)
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1490] vpn-connection[0x55d19133a520,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",12:(ppp0)]: VPN connection: (IP Config Get) complete
Aug 06 10:38:45 home NetworkManager[1050]: <info>  [1596731925.1699] policy: set 'Case Final' (ppp0) as default for IPv4 routing and DNS
Aug 06 10:38:45 home NetworkManager[53542]: INFO:   Interface ppp0 is UP.
Aug 06 10:38:45 home NetworkManager[53542]: INFO:   Tunnel is up and running.
Aug 06 10:38:46 home NetworkManager[1050]: <info>  [1596731926.3493] audit: op="statistics" arg="refresh-rate-ms" pid=2043 uid=1000 result="success"

and here's the log from trying and failing (satellite):

Aug 06 10:46:26 home NetworkManager[1050]: <info>  [1596732386.6134] audit: op="connection-activate" uuid="9ae1e792-0343-4da4-a8de-dc5f645a1df4" name="Case Final" pid=2043 uid=1000 result="success"
Aug 06 10:46:26 home NetworkManager[1050]: <info>  [1596732386.6218] vpn-connection[0x55d19133a730,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",0]: Started the VPN service, PID 54038
Aug 06 10:46:26 home NetworkManager[1050]: <info>  [1596732386.6308] vpn-connection[0x55d19133a730,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",0]: Saw the service appear; activating connection
Aug 06 10:46:26 home NetworkManager[1050]: <info>  [1596732386.6408] vpn-connection[0x55d19133a730,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",0]: VPN plugin: state changed: starting (3)
Aug 06 10:46:27 home NetworkManager[1050]: <info>  [1596732387.6642] dhcp6 (enp5s0): activation: beginning transaction (timeout in 45 seconds)
Aug 06 10:46:27 home NetworkManager[1050]: <info>  [1596732387.6660] policy: set 'Wired connection 1' (enp5s0) as default for IPv6 routing and DNS
Aug 06 10:46:27 home NetworkManager[1050]: <info>  [1596732387.6671] dhcp6 (enp5s0): option dhcp6_name_servers   => '2001:5b0:51c6:5be0:0:ff:fec6:fd83 fd0d:edc3:e12a::1'
Aug 06 10:46:27 home NetworkManager[1050]: <info>  [1596732387.6672] dhcp6 (enp5s0): state changed unknown -> bound
Aug 06 10:46:28 home NetworkManager[54041]: INFO:   Connected to gateway.
Aug 06 10:46:36 home NetworkManager[1050]: <warn>  [1596732396.6492] vpn-connection[0x55d19133a730,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",0]: VPN plugin: failed: connect-failed (1)
Aug 06 10:46:36 home NetworkManager[1050]: <warn>  [1596732396.6493] vpn-connection[0x55d19133a730,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",0]: VPN plugin: failed: connect-failed (1)
Aug 06 10:46:36 home NetworkManager[1050]: <info>  [1596732396.6494] vpn-connection[0x55d19133a730,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",0]: VPN plugin: state changed: stopping (5)
Aug 06 10:46:36 home NetworkManager[1050]: <info>  [1596732396.6498] vpn-connection[0x55d19133a730,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",0]: VPN plugin: state changed: stopped (6)
Aug 06 10:46:36 home NetworkManager[1050]: <info>  [1596732396.6554] vpn-connection[0x55d19133a730,9ae1e792-0343-4da4-a8de-dc5f645a1df4,"Case Final",0]: VPN service disappeared
Aug 06 10:46:40 home NetworkManager[1050]: <info>  [1596732400.9065] audit: op="statistics" arg="refresh-rate-ms" pid=2043 uid=1000 result="success"

in case that information may be helpful somehow. I'm using version 1.12.0

@DimitriPapadopoulos
Copy link
Collaborator

Indeed it's nor an MTU issue as far as I can see.

Perhaps a latency issue as you say. That's the main characteristic of a satellite connection, especially if the satellite is geostationary - which is the case for HughesNet.

@DimitriPapadopoulos
Copy link
Collaborator

Can you try VPN SSL from WIndows with FortiClient? It would be great if we could compare openfortivpn and FortiClient and find whether they differ or not. Perhaps there's a time out on the VPN gateway that needs to be modified (for VPN SSL only).

@ke7kto
Copy link
Author

ke7kto commented Aug 8, 2020

I can confirm that the VPN SSL from Windows with FortiClient successfully establishes a VPN.

@ke7kto
Copy link
Author

ke7kto commented Aug 8, 2020

Here are some relevant lines from a logfile using FortiClient, representing a successful connection and disconnection to an SSL VPN:

<log time="08/08/2020 07:19:06" level="4" source="12">id=96850 user=DBLOG_SOURCE_SYSTEM msg=&quot;FortiShield is disabled&quot;</log>
<log time="08/08/2020 07:19:06" level="6" source="16">id=96602 msg=&quot;SSLVPN service started successfully.&quot; vpntype=ssl</log>
<log time="08/08/2020 07:22:49" level="6" source="16">FortiSslvpn: 14328: fortissl_connect: device=ftvnic</log>
<log time="08/08/2020 07:22:52" level="6" source="16">FortiSslvpn: 14848: PreferDtlsTunnel=0</log>
<log time="08/08/2020 07:22:58" level="5" source="2">date=2020-08-08 time=07:22:57 logver=1 type=traffic level=notice sessionid=539985552 hostname=Frankendesktop pcdomain= uid=52XX56AB85B8435F8X992XXX879615X1 devid=XXX800349XXX5160 fgtserial=N/A emsserial=N/A regip=N/A srcname=sslvpn srcproduct=N/A srcip=10.X.X.XX srcport=N/A direction=outbound dstip=vpn2.case.edu remotename=N/A dstport=443 user=aar93 proto=6 rcvdbyte=1236 sentbyte=4502 utmaction=passthrough utmevent=vpn threat=connect vd=N/A fctver=6.0.4.0182 os=&quot;Microsoft Windows 10 , 64-bit (build 19041)&quot; usingpolicy=&quot;&quot; service= url=N/A userinitiated=0 browsetime=N/A</log>
<log time="08/08/2020 07:22:58" level="6" source="16">id=96600 user=ke7kto msg=&quot;SSLVPN tunnel status&quot; vpnstate=connected vpntunnel=&quot;SSL VPN&quot; vpntype=ssl</log>

I don't see anything here that looks useful, but I'm just a user

@DimitriPapadopoulos
Copy link
Collaborator

I really don't know. Hard to tell anything useful without debugging the connection myself.

There's one thing of interest though:

<log time="08/08/2020 07:19:06" level="6" source="16">id=96602 msg=&quot;SSLVPN service started successfully.&quot; vpntype=ssl</log>
<log time="08/08/2020 07:22:49" level="6" source="16">FortiSslvpn: 14328: fortissl_connect: device=ftvnic</log>

Almost 3 minutes between SSLVPN service started successfully and fortissl_connect events: am I reading this corretly? That's pretty long and we might hit a timeout in pppd for example, that would be beyond our (current) control. FortiClient embarks its own PPP code and we should perhaps embark our own PPP code too instead of relying on pppd. On the other hand I cannot find any pppd option related to timeouts.

Then there might be a timeout in the underlying TCP stack that could be modified by a system-level option. Anything useful in the system log while openfortivpn waits for this apparent timeout? Could you get access to a recent FortiClient for Linux with VPN support? The one freely available on internet does not support VPN. It would be great if you could find whether the FortiClient VPN SSL client is able to connect to the same VPN gateway from the same Linux machine - or not.

@ke7kto
Copy link
Author

ke7kto commented Aug 11, 2020

The connection takes 20 seconds to be fully established on windows, but the log doesn't get updated until the session disconnects for some reason. I will check other logs, and look for a recent FortiClient for Linux with VPN support.

@allanfreitas
Copy link

I've downloaded the forticlient-sslvpn
Package: forticlient-sslvpn
Version: 4.4.2333-1

And It works on my satelite connection, but the openfortivpn don't work, on windows it's normal too.
The "openfortivpn" package works on any other type of connection, but the high-latency of satelite don't let it work,
I have a 550ms latency on Satelite, and 50ms on 4G connection, on 4G works but on Satelite don't, the only variable is the latency.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants