openfortivpn icon indicating copy to clipboard operation
openfortivpn copied to clipboard

openfortivpn doesn't exit even though pppd is terminated

Open taufikterdidik opened this issue 3 years ago • 6 comments

It doesn't happen often, but sometime the systemctl not restarted because openfortivpn not exit/error even though pppd is terminated. This cause systemctl cannot restarted successfully (detected as active/running). This is my systemctl log/journalctl on my raspberry pi

pi@rumah:~ $ sudo systemctl status --no-pager --full [email protected][email protected] - OpenFortiVPN for myvpn
   Loaded: loaded (/etc/systemd/system/[email protected]; enabled; vendor preset: enabled)
   Active: active (running) since Tue 2021-03-23 20:23:04 WIB; 5h 42min ago
     Docs: man:openfortivpn(1)
  Process: 6216 ExecStartPost=/home/pi/sharenet.sh enable (code=exited, status=0/SUCCESS)
 Main PID: 6215 (openfortivpn)
    Tasks: 1 (limit: 1173)
   CGroup: /system.slice/system-openfortivpn.slice/[email protected]
           └─6215 /usr/local/bin/openfortivpn -c /etc/openfortivpn/myvpn.conf

Mar 24 01:01:54 rumah openfortivpn[6215]: INFO:   Cleanup, joining threads...
Mar 24 01:01:54 rumah openfortivpn[6215]: INFO:   Setting ppp0 interface down.
Mar 24 01:01:54 rumah openfortivpn[6215]: INFO:   Restoring routes...
Mar 24 01:01:54 rumah openfortivpn[6215]: WARN:   Could not delete route through tunnel (No such device).
Mar 24 01:01:54 rumah openfortivpn[6215]: INFO:   Removing VPN nameservers...
Mar 24 01:01:54 rumah openfortivpn[6215]: Too few arguments.
Mar 24 01:01:54 rumah openfortivpn[6215]: Too few arguments.
Mar 24 01:01:54 rumah openfortivpn[6215]: ERROR:  pppd: The link was terminated by the modem hanging up.
Mar 24 01:01:54 rumah openfortivpn[6215]: INFO:   Terminated pppd.
Mar 24 01:01:54 rumah openfortivpn[6215]: INFO:   Closed connection to gateway.


pi@rumah:~ $ sudo journalctl -u [email protected] --since today
-- Logs begin at Tue 2021-03-23 06:19:20 WIB, end at Wed 2021-03-24 02:06:23 WIB. --
Mar 24 01:01:47 rumah pppd[6221]: No response to 4 echo-requests
Mar 24 01:01:47 rumah openfortivpn[6215]: No response to 4 echo-requests
Mar 24 01:01:47 rumah openfortivpn[6215]: Serial link appears to be disconnected.
Mar 24 01:01:47 rumah openfortivpn[6215]: Connect time 278.6 minutes.
Mar 24 01:01:47 rumah openfortivpn[6215]: Sent 10742211 bytes, received 181050981 bytes.
Mar 24 01:01:47 rumah pppd[6221]: Serial link appears to be disconnected.
Mar 24 01:01:47 rumah pppd[6221]: Connect time 278.6 minutes.
Mar 24 01:01:47 rumah pppd[6221]: Sent 10742211 bytes, received 181050981 bytes.
Mar 24 01:01:53 rumah pppd[6221]: Connection terminated.
Mar 24 01:01:53 rumah openfortivpn[6215]: Connection terminated.
Mar 24 01:01:53 rumah pppd[6221]: Modem hangup
Mar 24 01:01:53 rumah openfortivpn[6215]: Modem hangup
Mar 24 01:01:53 rumah pppd[6221]: Exit.
Mar 24 01:01:53 rumah openfortivpn[6215]: ERROR:  read: Input/output error
Mar 24 01:01:53 rumah openfortivpn[6215]: INFO:   Cancelling threads...
Mar 24 01:01:54 rumah openfortivpn[6215]: INFO:   Cleanup, joining threads...
Mar 24 01:01:54 rumah openfortivpn[6215]: INFO:   Setting ppp0 interface down.
Mar 24 01:01:54 rumah openfortivpn[6215]: INFO:   Restoring routes...
Mar 24 01:01:54 rumah openfortivpn[6215]: WARN:   Could not delete route through tunnel (No such device).
Mar 24 01:01:54 rumah openfortivpn[6215]: INFO:   Removing VPN nameservers...
Mar 24 01:01:54 rumah openfortivpn[6215]: Too few arguments.
Mar 24 01:01:54 rumah openfortivpn[6215]: Too few arguments.
Mar 24 01:01:54 rumah openfortivpn[6215]: ERROR:  pppd: The link was terminated by the modem hanging up.
Mar 24 01:01:54 rumah openfortivpn[6215]: INFO:   Terminated pppd.
Mar 24 01:01:54 rumah openfortivpn[6215]: INFO:   Closed connection to gateway.


pi@rumah:~ $ cat /etc/systemd/system/[email protected] 
[Unit]
Description=OpenFortiVPN for %I
After=network-online.target
Documentation=man:openfortivpn(1)

[Service]
Type=simple
PrivateTmp=true
ExecStart=/usr/local/bin/openfortivpn -c /etc/openfortivpn/%I.conf
OOMScoreAdjust=-100
Restart=always
RestartSec=90
StartLimitInterval=400
StartLimitBurst=3
ExecStartPost=/home/pi/sharenet.sh enable
ExecStopPost=/home/pi/sharenet.sh disable


[Install]
WantedBy=multi-user.target

How can I solve this? I left my Raspberry pi as internet gateway through openfortivpn

taufikterdidik avatar Mar 25 '21 13:03 taufikterdidik

How do you come to the conclusion that openfortivpn does not exit/error even though pppd is terminated? I currently cannot see how it could happen. Perhaps openfortivpn exits with an exit status 0 instead, in which case it might not be restarted by systemd. I may be wrong, but I don't see how you show this is an openfortivpn issue and what we learn about openfortivpn here. It would help if you could reproduce an issue clearly related to openfortivpn without systemd in the way.

Also, these lines look suspect, how do you explain them?

Mar 24 01:01:54 rumah openfortivpn[6215]: Too few arguments.
Mar 24 01:01:54 rumah openfortivpn[6215]: Too few arguments.

DimitriPapadopoulos avatar Mar 25 '21 13:03 DimitriPapadopoulos

INFO: Adding VPN nameservers... DEBUG: Attempting to run /usr/sbin/resolvconf. DEBUG: resolvconf_call: /usr/sbin/resolvconf -a "ppp0.openfortivpn" Too few arguments. Too few arguments. INFO: Tunnel is up and running.

This is the output when I run in debug.

taufikterdidik avatar Aug 01 '21 05:08 taufikterdidik

Thank you for the extra information. Let's disregard systemd for now. Running openfortivpn in debug mode as you do, until all things are sorted out, is the best way forward.

As far as I can see, openfortivpn itself does start as expected, it prints:

INFO: Tunnel is up and running.

Also, I do see these messages in the systemd log you had sent initially:

Mar 24 01:01:47 rumah pppd[6221]: No response to 4 echo-requests
Mar 24 01:01:47 rumah openfortivpn[6215]: No response to 4 echo-requests

It looks like pppd decides to terminate the connection because the VPN gateway does not respond. Perhaps that's simply the VPN gateway automatically closing the connection after a given time period. How long after openfortivpn has been started are the above messages printed? See issue #781. In that case, it's important to know if patch #798 has made it into your version of openfortivpn. Which exact version of openfortivpn are you using?

Finally, I have recently come across the Too few arguments error messages. They are caused by the resolvconf provided by openresolv, which seems broken on Raspberry Pi: openconnect#273 vpnc-scripts#24

So we first need to find the exact version of the resolvconf executable. Please show us the output of:

which -a resolvconf
type -a resolvconf
dpkg -S /usr/sbin/resolvconf
dpkg -S /sbin/resolvconf

DimitriPapadopoulos avatar Aug 01 '21 07:08 DimitriPapadopoulos

@DimitriPapadopoulos

I think I have the same issue. I start openfortivpn without systemd (I start it just in the console), and it does not exit. Here is how I start it: sudo openfortivpn -c $config_path Config:

### config file for openfortivpn, see man openfortivpn(1) ###
host = ....com
port = 8443
username = ...
password = ...
persistent = 10800

Output:

+++++ sudo openfortivpn -c $HOME/forti.conf
INFO:   Connected to gateway.
INFO:   Authenticated.
INFO:   Remote gateway has allocated a VPN.
Using interface ppp0
Connect: ppp0 <--> /dev/pts/34
INFO:   Got addresses: [172.16.10.20], ns [10.10.10.20, 10.10.10.21], ns_suffix [...]
INFO:   Negotiation complete.
INFO:   Got addresses: [172.16.10.20], ns [10.10.10.20, 10.10.10.21], ns_suffix [...]
INFO:   Negotiation complete.
INFO:   Got addresses: [172.16.10.20], ns [10.10.10.20, 10.10.10.21], ns_suffix [...]
INFO:   Negotiation complete.
INFO:   Got addresses: [172.16.10.20], ns [10.10.10.20, 10.10.10.21], ns_suffix [...]
INFO:   Negotiation complete.
INFO:   Got addresses: [172.16.10.20], ns [10.10.10.20, 10.10.10.21], ns_suffix [...]
INFO:   Negotiation complete.
INFO:   Got addresses: [172.16.10.20], ns [10.10.10.20, 10.10.10.21], ns_suffix [...]
INFO:   Negotiation complete.
INFO:   Negotiation complete.
local  IP address 172.16.10.20
remote IP address 192.0.2.1
INFO:   Interface ppp0 is UP.
INFO:   Setting new routes...
INFO:   Adding VPN nameservers...
INFO:   Tunnel is up and running.
INFO:   Cancelling threads...
INFO:   Cleanup, joining threads...
INFO:   Setting ppp0 interface down.
INFO:   Restoring routes...
INFO:   Removing VPN nameservers...
Hangup (SIGHUP)
Modem hangup
Connect time 779.8 minutes.
Sent 1199282 bytes, received 930682 bytes.
Connection terminated.
INFO:   pppd: The link was terminated by the modem hanging up.
INFO:   Terminated pppd.
INFO:   Closed connection to gateway.
INFO:   Logged out.

<nothing happens here>

version:

openfortivpn --version
1.15.0

I was hoping that persistent = 10800 will make it reconnect automatically every 3 hours... But instead, it neither reconnects, nor exits :)

DimanNe avatar Nov 21 '21 11:11 DimanNe

UPDATE It is very weird, but after 3(?) hours of being disconnected, it automatically reconnected... Should I put persistent = 1 to make it reconnect in 1 second after it got disconnected?..

DimanNe avatar Nov 21 '21 11:11 DimanNe

@DimanNe Please open a new ticket instead of hijacking an existing one. In your case, with --persistent=10800, of course it reconnects after 3 hours. That's what the option is supposed to: reconnect if the initial connection fails. It will not end an existing connection.

DimitriPapadopoulos avatar Nov 22 '21 12:11 DimitriPapadopoulos