Connection dies with 'Protocol violation with EOF' after some time

[dwt]

Not sure what to make of it - the tunnel comes online and works for a short time, then dies with these error messages:

DEBUG:  Error reading from SSL connection (Protocol violation with EOF).
INFO:   Cancelling threads...
INFO:   Setting ppp interface down.
INFO:   Restoring routes...
INFO:   Removing VPN nameservers...
DEBUG:  Waiting for pppd to exit...
INFO:   Terminated pppd.
INFO:   Closed connection to gateway.
DEBUG:  Gateway certificate validation failed.
DEBUG:  Gateway certificate digest found in white list.
INFO:   Logged out.

Running master from 19. of January 2017 on Mac OS X 10.12.2 (16C68).

What further information can I give to help you debug this problem?

[mrbaseman]

The connection over which the tunnel was running was stable during that time? Any log entries of pppd which could provide a hint?

[dwt]

The connection was stable during that time, I'm not really sure how to reproduce this, it seems that the tunnel breaks sometimes very few seconds after establishing (the first time I connected) then it worked flawlessly for half an hour (till I hang up). The last time I used it, I couldn't get any connection to work for longer than 30 seconds before it broke.

Today I only got these messages out of pppd (and IMO they look fine?). The first connect failed, second and third where fine and manually closed. (I don't really see that first connect in the log though, not sure why)

Standard	10:57:00.903531 +0100	pppd	publish_entry SCDSet() failed: Success!
Standard	10:57:00.903579 +0100	pppd	publish_entry SCDSet() failed: Success!
Standard	10:57:00.904576 +0100	pppd	pppd 2.4.2 (Apple version 838) started by root, uid 0
Standard	10:57:00.905492 +0100	pppd	Connect: ppp0 <--> /dev/ttys001
Standard	10:57:01.387849 +0100	pppd	local  IP address 172.16.0.4
Standard	10:57:01.387951 +0100	pppd	remote IP address 1.1.1.1
Standard	10:57:01.388102 +0100	pppd	Committed PPP store
Standard	10:57:01.388942 +0100	pppd	Committed PPP store
Standard	10:59:27.025956 +0100	pppd	Modem hangup
Standard	10:59:27.027486 +0100	pppd	Connection terminated.
Standard	10:59:27.027635 +0100	pppd	LCP close (User request).
Standard	10:59:34.170679 +0100	pppd	publish_entry SCDSet() failed: Success!
Standard	10:59:34.170745 +0100	pppd	publish_entry SCDSet() failed: Success!
Standard	10:59:34.171804 +0100	pppd	pppd 2.4.2 (Apple version 838) started by root, uid 0
Standard	10:59:34.172616 +0100	pppd	Connect: ppp0 <--> /dev/ttys001
Standard	10:59:34.591208 +0100	pppd	local  IP address 172.16.0.4
Standard	10:59:34.591400 +0100	pppd	remote IP address 1.1.1.1
Standard	10:59:34.591550 +0100	pppd	Committed PPP store
Standard	10:59:34.594628 +0100	pppd	Committed PPP store

[dwt]

This is how the pppd log looks for a failed connection

Standard	11:24:31.915863 +0100	pppd	publish_entry SCDSet() failed: Success!
Standard	11:24:31.915919 +0100	pppd	publish_entry SCDSet() failed: Success!
Standard	11:24:31.917006 +0100	pppd	pppd 2.4.2 (Apple version 838) started by root, uid 0
Standard	11:24:31.917924 +0100	pppd	Connect: ppp0 <--> /dev/ttys001
Standard	11:24:32.334984 +0100	pppd	local  IP address 172.16.0.4
Standard	11:24:32.335170 +0100	pppd	remote IP address 1.1.1.1
Standard	11:24:32.335283 +0100	pppd	Committed PPP store
Standard	11:24:32.336616 +0100	pppd	Committed PPP store
Standard	11:24:34.766591 +0100	pppd	Modem hangup
Standard	11:24:34.767663 +0100	pppd	Connection terminated.
Standard	11:24:34.767706 +0100	pppd	LCP close (User request).

Here's the openforti log

dwt@crest ~/Code/Projekte/Locomore/openfortivpn (git)-[master] % ./start_tunnel.sh
INFO:   Connected to gateway.
INFO:   Authenticated.
INFO:   Remote gateway has allocated a VPN.
INFO:   Got addresses: [172.16.0.4], ns [0.0.0.0, 0.0.0.0]
INFO:   Interface ppp0 is UP.
INFO:   Setting new routes...
add net 10.3.140.0: gateway 172.16.0.4
add net 10.3.7.0: gateway 172.16.0.4
add net 10.3.9.0: gateway 172.16.0.4
INFO:   Adding VPN nameservers...
INFO:   Tunnel is up and running.
INFO:   Cancelling threads...
INFO:   Setting ppp interface down.
INFO:   Restoring routes...
INFO:   Removing VPN nameservers...
INFO:   Terminated pppd.
INFO:   Closed connection to gateway.
INFO:   Logged out.

[mrbaseman]

@dwt thanks. Unfortunately, I can't see any hint from the logs you have provided, but here a few thoughts:
I have observed that the connection sometimes can't be established when it takes too long (timeout during name resolution, expired mobile token, or alike), but probably the scenario you are observing is something different.
In other cases the connection may be established, but breaks down when the routes pushed by the fortigate create some kind of a loop (i.e. the route for the traffic building up the vpn tunnel is altered and points through the vpn channel once it is established). This might be corrected by manually setting up a proper route beforehand. The scenario should be the same with the official forticlient (provided that it handles this routing scenario the same way).
Another possible cause for an instable connection could be another device (e.g. a mobile device running a forticlient?) that tries to authenticate with the same credentials and invalidates the authentication for your vpn connection. On the fortigate one might observe log entries about such an event.

[DimitriPapadopoulos]

Have you perhaps tried with a newer version of openfortivpn? I suspect this has been fixed in version 1.3.1 and newer.

[dwt]

Sorry, I don't work at the place that requires this VPN anymore, so I can't.

But thanks for the reminder! :)

[DimitriPapadopoulos]

Thank you for the feedback! I'll close this ticket, there's not much we can do about it this context. If needed please reopen it.

[markri]

I have the same issue. Tried version 1.3.1 and 1.4.0 (both of them die after some time) on CentOS 6.4 and CentOS 7.3 (similar log and issue)

openfortivpn debug log CentOS 6.4

DEBUG:  gateway ---> pppd (6 bytes)
gtw:    xx xx xx xx xx x

DEBUG:  Got Address: 10.212.134.201
DEBUG:  if_config: not ready yet...
DEBUG:  pppd ---> gateway (6 bytes)
pppd:   xx xx xx xx xx x

DEBUG:  Got Address: 10.212.134.201
DEBUG:  Interface Name: ppp0
DEBUG:  Interface Addr: 10.212.134.201
INFO:   Interface ppp0 is UP.
INFO:   Setting new routes...
DEBUG:  ip route show to 0.0.0.0/0.0.0.0
DEBUG:  Setting route to vpn server...
DEBUG:  ip route add to xx.xx.xx.xx/255.255.255.255 via 192.168.1.2 dev eth0
DEBUG:  ip route add to xx.xx.xx.xx/255.255.255.224 via 10.212.134.201 dev ppp0
INFO:   Adding VPN nameservers...
INFO:   Tunnel is up and running.
DEBUG:  Error reading from SSL connection (Protocol violation with EOF).
INFO:   Cancelling threads...
INFO:   Setting ppp interface down.
INFO:   Restoring routes...
DEBUG:  ip route del to xx.xx.xx.xx/255.255.255.255 via 192.168.1.2 dev eth0
INFO:   Removing VPN nameservers...
DEBUG:  Waiting for pppd to exit...
INFO:   Terminated pppd.
INFO:   Closed connection to gateway.
DEBUG:  Gateway certificate validation failed.
DEBUG:  Gateway certificate digest found in white list.
INFO:   Logged out.

pppd log CentOS 6.4

Jul 27 15:33:47 server1 pppd[9422]: pppd 2.4.5 started by marco, uid 0
Jul 27 15:33:47 server1 pppd[9422]: Using interface ppp0
Jul 27 15:33:47 server1 pppd[9422]: Connect: ppp0 <--> /dev/pts/0
Jul 27 15:33:48 server1 pppd[9422]: local  IP address 10.212.134.201
Jul 27 15:33:48 server1 pppd[9422]: remote IP address 1.1.1.1
Jul 27 15:38:51 server1 pppd[9422]: Hangup (SIGHUP)
Jul 27 15:38:51 server1 pppd[9422]: Modem hangup
Jul 27 15:38:51 server1 pppd[9422]: Connect time 5.1 minutes.
Jul 27 15:38:51 server1 pppd[9422]: Sent 0 bytes, received 0 bytes.
Jul 27 15:38:51 server1 pppd[9422]: Connection terminated.
Jul 27 15:38:51 server1 pppd[9422]: Exit.

Reviewing the log for multiple times, I found that the connection is broken exactly after 5.1 minute.

On Ubuntu 16.04 hower, I use the GUI https://github.com/theinvisible/openfortigui (which includes the 1.4.0 version right now). When I connect to the same VPN server I get a stable connection. So it seems that this issue is somehow OS / library related.

[DimitriPapadopoulos]

@markri OK, I'm reopening this issue since you can reproduce this with CentOS and openfortivpn 1.4.0. Please note the initial poster was on Mac OS X 10.12.2. So is this OS / library related or not? This is a total mystery for now: could as well be identical symptoms with different reasons...

Also does #50 help at all? Modifies /etc/ppp/options but not sure whether this is an openfortivpn bug or not.

[markri]

Thnx, just tried the exact same install (without GUI) on Ubuntu. As it seems, the connection on Ubuntu spawns some messages every few seconds now and then (probably a keep-alive). These messages were missing in CentOS.

Seems like you already were a step ahead 👍 about that
Just implemented your mentioned fix in #50

As the default options file is empty but the "lock" option in both CentOS 6 and 7. My connection is now stable for over more than 10 minute now (it broke exactly at 5.1 minutes before). So it seems to be this exact issue. Will let it run over night, but for now we can assume that this (is / can be) fixed

[DimitriPapadopoulos]

@markri Thanks for the feedback. I can't decide whether this is an openfortivpn bug or not. Someone more knowledgeable might comment here...