nm-l2tp / NetworkManager-l2tp

L2TP and L2TP/IPsec support for NetworkManager
GNU General Public License v2.0
488 stars 84 forks source link

Ubuntu 17.04 - connection is dropped immediately #51

Closed rgerbranda closed 6 years ago

rgerbranda commented 7 years ago

Today I installed the PPA network-manger-l2tp 1.2.6 package on a brand new Ubuntu 17.04 system. Aftwerwards I started testing.

In the GUI, the VPN connection is closed directly after it is established (connection '70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25' established successfully)

When I do "sudo ipsec up ..." the connection stays alive.

Below the log when connection from the GUI

Jul 10 12:14:54 Ubuntu17 NetworkManager[588]: [1499681694.7011] audit: op="connection-activate" uuid="70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25" name="VPN connection 1" pid=3853 uid=1000 result="success" Jul 10 12:14:54 Ubuntu17 NetworkManager[588]: [1499681694.7187] vpn-connection[0x55e767fdb4f0,70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25,"VPN connection 1",0]: Started the VPN service, PID 4441 Jul 10 12:14:54 Ubuntu17 NetworkManager[588]: [1499681694.7383] vpn-connection[0x55e767fdb4f0,70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25,"VPN connection 1",0]: Saw the service appear; activating connection Jul 10 12:14:54 Ubuntu17 NetworkManager[588]: [1499681694.9099] vpn-connection[0x55e767fdb4f0,70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25,"VPN connection 1",0]: VPN connection: (ConnectInteractive) reply received Jul 10 12:14:54 Ubuntu17 nm-l2tp-service[4441]: Check port 1701 Jul 10 12:14:54 Ubuntu17 NetworkManager[588]: Stopping strongSwan IPsec failed: starter is not running Jul 10 12:14:56 Ubuntu17 NetworkManager[588]: Starting strongSwan 5.5.1 IPsec [starter]... Jul 10 12:14:56 Ubuntu17 NetworkManager[588]: Loading config setup Jul 10 12:14:56 Ubuntu17 NetworkManager[588]: Loading conn '70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25' Jul 10 12:14:56 Ubuntu17 NetworkManager[588]: found netkey IPsec stack Jul 10 12:14:57 Ubuntu17 charon: 00[DMN] Starting IKE charon daemon (strongSwan 5.5.1, Linux 4.10.0-26-generic, x86_64) Jul 10 12:14:57 Ubuntu17 charon: 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts' Jul 10 12:14:57 Ubuntu17 charon: 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts' Jul 10 12:14:57 Ubuntu17 charon: 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts' Jul 10 12:14:57 Ubuntu17 charon: 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts' Jul 10 12:14:57 Ubuntu17 charon: 00[CFG] loading crls from '/etc/ipsec.d/crls' Jul 10 12:14:57 Ubuntu17 charon: 00[CFG] loading secrets from '/etc/ipsec.secrets' Jul 10 12:14:57 Ubuntu17 charon: 00[CFG] loading secrets from '/etc/ipsec.d/nm-l2tp-ipsec-70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25.secrets' Jul 10 12:14:57 Ubuntu17 charon: 00[CFG] loaded IKE secret for xxx.74.250.121 Jul 10 12:14:57 Ubuntu17 charon: 00[LIB] loaded plugins: charon test-vectors aesni aes rc2 sha2 sha1 md4 md5 random nonce x509 revocation constraints pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey sshkey pem openssl fips-prf gmp agent xcbc hmac ccm gcm attr kernel-netlink resolve socket-default connmark stroke updown eap-mschapv2 xauth-generic Jul 10 12:14:57 Ubuntu17 charon: 00[LIB] dropped capabilities, running as uid 0, gid 0 Jul 10 12:14:57 Ubuntu17 charon: 00[JOB] spawning 16 worker threads Jul 10 12:14:57 Ubuntu17 charon: 05[CFG] received stroke: add connection '70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25' Jul 10 12:14:57 Ubuntu17 charon: 05[CFG] added configuration '70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25' Jul 10 12:14:58 Ubuntu17 charon: 07[CFG] rereading secrets Jul 10 12:14:58 Ubuntu17 charon: 07[CFG] loading secrets from '/etc/ipsec.secrets' Jul 10 12:14:58 Ubuntu17 charon: 07[CFG] loading secrets from '/etc/ipsec.d/nm-l2tp-ipsec-70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25.secrets' Jul 10 12:14:58 Ubuntu17 charon: 07[CFG] loaded IKE secret for xxx.74.250.121 Jul 10 12:14:58 Ubuntu17 charon: 09[CFG] received stroke: initiate '70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25' Jul 10 12:14:58 Ubuntu17 charon: 11[IKE] initiating Main Mode IKE_SA 70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25[1] to xxx.74.250.121 Jul 10 12:14:58 Ubuntu17 charon: 11[ENC] generating ID_PROT request 0 [ SA V V V V V ] Jul 10 12:14:58 Ubuntu17 charon: 11[NET] sending packet: from 10.0.2.15[500] to xxx.74.250.121[500] (240 bytes) Jul 10 12:14:58 Ubuntu17 charon: 12[NET] received packet: from xxx.74.250.121[500] to 10.0.2.15[500] (176 bytes) Jul 10 12:14:58 Ubuntu17 charon: 12[ENC] parsed ID_PROT response 0 [ SA V V V V V ] Jul 10 12:14:58 Ubuntu17 charon: 12[IKE] received strongSwan vendor ID Jul 10 12:14:58 Ubuntu17 charon: 12[IKE] received Cisco Unity vendor ID Jul 10 12:14:58 Ubuntu17 charon: 12[IKE] received XAuth vendor ID Jul 10 12:14:58 Ubuntu17 charon: 12[IKE] received DPD vendor ID Jul 10 12:14:58 Ubuntu17 charon: 12[IKE] received NAT-T (RFC 3947) vendor ID Jul 10 12:14:58 Ubuntu17 charon: 12[ENC] generating ID_PROT request 0 [ KE No NAT-D NAT-D ] Jul 10 12:14:58 Ubuntu17 charon: 12[NET] sending packet: from 10.0.2.15[500] to xxx.74.250.121[500] (524 bytes) Jul 10 12:14:58 Ubuntu17 charon: 13[NET] received packet: from xxx.74.250.121[500] to 10.0.2.15[500] (508 bytes) Jul 10 12:14:58 Ubuntu17 charon: 13[ENC] parsed ID_PROT response 0 [ KE No NAT-D NAT-D ] Jul 10 12:14:58 Ubuntu17 charon: 13[IKE] local host is behind NAT, sending keep alives Jul 10 12:14:58 Ubuntu17 charon: 13[ENC] generating ID_PROT request 0 [ ID HASH N(INITIAL_CONTACT) ] Jul 10 12:14:58 Ubuntu17 charon: 13[NET] sending packet: from 10.0.2.15[4500] to xxx.74.250.121[4500] (108 bytes) Jul 10 12:14:58 Ubuntu17 charon: 14[NET] received packet: from xxx.74.250.121[4500] to 10.0.2.15[4500] (76 bytes) Jul 10 12:14:58 Ubuntu17 charon: 14[ENC] parsed ID_PROT response 0 [ ID HASH ] Jul 10 12:14:58 Ubuntu17 charon: 14[IKE] IKE_SA 70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25[1] established between 10.0.2.15[10.0.2.15]...xxx.74.250.121[xxx.74.250.121] Jul 10 12:14:58 Ubuntu17 charon: 14[IKE] scheduling reauthentication in 10164s Jul 10 12:14:58 Ubuntu17 charon: 14[IKE] maximum IKE_SA lifetime 10704s Jul 10 12:14:58 Ubuntu17 charon: 14[ENC] generating QUICK_MODE request 1362568669 [ HASH SA No ID ID NAT-OA NAT-OA ] Jul 10 12:14:58 Ubuntu17 charon: 14[NET] sending packet: from 10.0.2.15[4500] to xxx.74.250.121[4500] (236 bytes) Jul 10 12:14:58 Ubuntu17 charon: 15[NET] received packet: from xxx.74.250.121[4500] to 10.0.2.15[4500] (172 bytes) Jul 10 12:14:58 Ubuntu17 charon: 15[ENC] parsed QUICK_MODE response 1362568669 [ HASH SA No ID ID ] Jul 10 12:14:58 Ubuntu17 charon: 15[IKE] CHILD_SA 70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25{1} established with SPIs cabeffb7_i 777d5cef_o and TS 10.0.2.15/32[udp/l2f] === xxx.74.250.121/32[udp/l2f] Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: initiating Main Mode IKE_SA 70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25[1] to xxx.74.250.121 Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: generating ID_PROT request 0 [ SA V V V V V ] Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: sending packet: from 10.0.2.15[500] to xxx.74.250.121[500] (240 bytes) Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: received packet: from xxx.74.250.121[500] to 10.0.2.15[500] (176 bytes) Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: parsed ID_PROT response 0 [ SA V V V V V ] Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: received strongSwan vendor ID Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: received Cisco Unity vendor ID Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: received XAuth vendor ID Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: received DPD vendor ID Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: received NAT-T (RFC 3947) vendor ID Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: generating ID_PROT request 0 [ KE No NAT-D NAT-D ] Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: sending packet: from 10.0.2.15[500] to xxx.74.250.121[500] (524 bytes) Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: received packet: from xxx.74.250.121[500] to 10.0.2.15[500] (508 bytes) Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: parsed ID_PROT response 0 [ KE No NAT-D NAT-D ] Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: local host is behind NAT, sending keep alives Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: generating ID_PROT request 0 [ ID HASH N(INITIAL_CONTACT) ] Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: sending packet: from 10.0.2.15[4500] to xxx.74.250.121[4500] (108 bytes) Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: received packet: from xxx.74.250.121[4500] to 10.0.2.15[4500] (76 bytes) Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: parsed ID_PROT response 0 [ ID HASH ] Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: IKE_SA 70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25[1] established between 10.0.2.15[10.0.2.15]...xxx.74.250.121[xxx.74.250.121] Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: scheduling reauthentication in 10164s Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: maximum IKE_SA lifetime 10704s Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: generating QUICK_MODE request 1362568669 [ HASH SA No ID ID NAT-OA NAT-OA ] Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: sending packet: from 10.0.2.15[4500] to xxx.74.250.121[4500] (236 bytes) Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: received packet: from xxx.74.250.121[4500] to 10.0.2.15[4500] (172 bytes) Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: parsed QUICK_MODE response 1362568669 [ HASH SA No ID ID ] Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: CHILD_SA 70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25{1} established with SPIs cabeffb7_i 777d5cef_o and TS 10.0.2.15/32[udp/l2f] === xxx.74.250.121/32[udp/l2f] Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: connection '70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25' established successfully Jul 10 12:14:58 Ubuntu17 charon: 15[ENC] generating QUICK_MODE request 1362568669 [ HASH ] Jul 10 12:14:58 Ubuntu17 charon: 15[NET] sending packet: from 10.0.2.15[4500] to xxx.74.250.121[4500] (76 bytes) Jul 10 12:14:58 Ubuntu17 nm-l2tp-service[4441]: xl2tpd started with pid 4516 Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: [1499681698.5325] vpn-connection[0x55e767fdb4f0,70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25,"VPN connection 1",0]: VPN plugin: state changed: starting (3) Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: xl2tpd[4516]: setsockopt recvref[30]: Protocol not available Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: xl2tpd[4516]: Using l2tp kernel support. Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: xl2tpd[4516]: xl2tpd version xl2tpd-1.3.8 started on Ubuntu17 PID:4516 Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: xl2tpd[4516]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc. Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: xl2tpd[4516]: Forked by Scott Balmos and David Stipp, (C) 2001 Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: xl2tpd[4516]: Inherited by Jeff McAdams, (C) 2002 Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: xl2tpd[4516]: Forked again by Xelerance (www.xelerance.com) (C) 2006-2016 Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: xl2tpd[4516]: Listening on IP address 0.0.0.0, port 1701 Jul 10 12:14:58 Ubuntu17 NetworkManager[588]: xl2tpd[4516]: Connecting to host xxx.74.250.121, port 1701 Jul 10 12:15:12 Ubuntu17 NetworkManager[588]: xl2tpd[4516]: death_handler: Fatal signal 15 received Jul 10 12:15:12 Ubuntu17 NetworkManager[588]: xl2tpd[4516]: Connection 0 closed to xxx.74.250.121, port 1701 (Server closing) Jul 10 12:15:12 Ubuntu17 NetworkManager[588]: Stopping strongSwan IPsec... Jul 10 12:15:12 Ubuntu17 NetworkManager[588]: [1499681712.5395] vpn-connection[0x55e767fdb4f0,70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25,"VPN connection 1",0]: VPN plugin: failed: connect-failed (1) Jul 10 12:15:12 Ubuntu17 NetworkManager[588]: [1499681712.5395] vpn-connection[0x55e767fdb4f0,70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25,"VPN connection 1",0]: VPN plugin: failed: connect-failed (1) Jul 10 12:15:12 Ubuntu17 NetworkManager[588]: [1499681712.5396] vpn-connection[0x55e767fdb4f0,70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25,"VPN connection 1",0]: VPN plugin: state changed: stopping (5) Jul 10 12:15:12 Ubuntu17 charon: 00[DMN] signal of type SIGINT received. Shutting down Jul 10 12:15:12 Ubuntu17 charon: 00[IKE] closing CHILD_SA 70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25{1} with SPIs cabeffb7_i (0 bytes) 777d5cef_o (544 bytes) and TS 10.0.2.15/32[udp/l2f] === xxx.74.250.121/32[udp/l2f] Jul 10 12:15:12 Ubuntu17 charon: 00[IKE] sending DELETE for ESP CHILD_SA with SPI cabeffb7 Jul 10 12:15:12 Ubuntu17 charon: 00[ENC] generating INFORMATIONAL_V1 request 697436545 [ HASH D ] Jul 10 12:15:12 Ubuntu17 charon: 00[NET] sending packet: from 10.0.2.15[4500] to xxx.74.250.121[4500] (92 bytes) Jul 10 12:15:12 Ubuntu17 charon: 00[IKE] deleting IKE_SA 70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25[1] between 10.0.2.15[10.0.2.15]...xxx.74.250.121[xxx.74.250.121] Jul 10 12:15:12 Ubuntu17 charon: 00[IKE] sending DELETE for IKE_SA 70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25[1] Jul 10 12:15:12 Ubuntu17 charon: 00[ENC] generating INFORMATIONAL_V1 request 1660002841 [ HASH D ] Jul 10 12:15:12 Ubuntu17 charon: 00[NET] sending packet: from 10.0.2.15[4500] to xxx.74.250.121[4500] (108 bytes) Jul 10 12:15:12 Ubuntu17 nm-l2tp-service[4441]: ipsec shut down Jul 10 12:15:12 Ubuntu17 NetworkManager[588]: [1499681712.5631] vpn-connection[0x55e767fdb4f0,70ea65ca-2b94-40f4-8dbb-0ff50ed0fa25,"VPN connection 1",0]: VPN service disappeared

dkosovic commented 7 years ago

I think there might be something wrong with the xl2tpd PPP options which we don't see the debugging output for. If you issue the following and try to connect it might give a hint, but the pppd debugging output will be in the journalctl output not the stdout/stderr of the following.

sudo systemctl restart NetworkManager
sudo /usr/lib/NetworkManager/nm-l2tp-service --debug
rgerbranda commented 7 years ago

I tried some debuging using

sudo pppd debug file /var/run/nm-l2tp-ppp-options-2d54f0ee-15bd-483d-996e-5286361091c5

The result:

Jul 11 16:54:26 Ubuntu17 pppd[2833]: Plugin /usr/lib/pppd/2.4.7/nm-l2tp-pppd-plugin.so loaded. Jul 11 16:54:26 Ubuntu17 pppd[2833]: nm-l2tp[???] [helper-2833] initializing Jul 11 16:54:26 Ubuntu17 pppd[2833]: pppd 2.4.7 started by remko, uid 0 Jul 11 16:54:26 Ubuntu17 pppd[2833]: nm-l2tp[???] [helper-2833] phasechange: status 3 / phase 'serial connection' Jul 11 16:54:26 Ubuntu17 pppd[2833]: using channel 2 Jul 11 16:54:26 Ubuntu17 pppd[2833]: Using interface ppp0 Jul 11 16:54:26 Ubuntu17 pppd[2833]: Connect: ppp0 <--> /dev/pts/0 Jul 11 16:54:26 Ubuntu17 pppd[2833]: nm-l2tp[???] [helper-2833] phasechange: status 5 / phase 'establish' Jul 11 16:54:26 Ubuntu17 pppd[2833]: sent [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0xcb85e497> ] Jul 11 16:54:26 Ubuntu17 NetworkManager[623]: ((devices/nm-device.c:970)): assertion '' failed Jul 11 16:54:26 Ubuntu17 NetworkManager[623]: [1499784866.2885] manager: (ppp0): new Generic device (/org/freedesktop/NetworkManager/Devices/3) Jul 11 16:54:26 Ubuntu17 NetworkManager[623]: [1499784866.3672] devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0) Jul 11 16:54:26 Ubuntu17 NetworkManager[623]: [1499784866.3673] device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration found. Jul 11 16:54:29 Ubuntu17 pppd[2833]: sent [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0xcb85e497> ] Jul 11 16:54:32 Ubuntu17 pppd[2833]: sent [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0xcb85e497> ] Jul 11 16:54:32 Ubuntu17 charon: 08[IKE] sending keep alive to xxx.74.250.121[4500] Jul 11 16:54:35 Ubuntu17 pppd[2833]: sent [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0xcb85e497> ] Jul 11 16:54:38 Ubuntu17 pppd[2833]: sent [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0xcb85e497> ] Jul 11 16:54:41 Ubuntu17 pppd[2833]: sent [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0xcb85e497> ] Jul 11 16:54:42 Ubuntu17 charon: 06[NET] received packet: from xxx.74.250.121[4500] to 10.0.2.15[4500] (108 bytes) Jul 11 16:54:42 Ubuntu17 charon: 06[ENC] parsed INFORMATIONAL_V1 request 3888426677 [ HASH N(DPD) ] Jul 11 16:54:42 Ubuntu17 charon: 06[ENC] generating INFORMATIONAL_V1 request 208137853 [ HASH N(DPD_ACK) ] Jul 11 16:54:42 Ubuntu17 charon: 06[NET] sending packet: from 10.0.2.15[4500] to xxx.74.250.121[4500] (108 bytes) Jul 11 16:54:44 Ubuntu17 pppd[2833]: sent [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0xcb85e497> ] Jul 11 16:54:44 Ubuntu17 systemd[1]: Started Session 8 of user remko. Jul 11 16:54:45 Ubuntu17 systemd[1268]: Starting Notification regarding a new release of Ubuntu... Jul 11 16:54:47 Ubuntu17 pppd[2833]: sent [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0xcb85e497> ] Jul 11 16:54:53 Ubuntu17 pppd[2833]: message repeated 2 times: [ sent [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0xcb85e497> ]] Jul 11 16:54:56 Ubuntu17 pppd[2833]: LCP: timeout sending Config-Requests Jul 11 16:54:56 Ubuntu17 pppd[2833]: nm-l2tp[???] [helper-2833] phasechange: status 11 / phase 'disconnect' Jul 11 16:54:56 Ubuntu17 pppd[2833]: Connection terminated. Jul 11 16:54:56 Ubuntu17 charon: 09[KNL] interface ppp0 deleted Jul 11 16:54:56 Ubuntu17 pppd[2833]: nm-l2tp[???] [helper-2833] phasechange: status 1 / phase 'dead' Jul 11 16:54:56 Ubuntu17 pppd[2833]: Modem hangup Jul 11 16:54:56 Ubuntu17 pppd[2833]: nm-l2tp[???] [helper-2833] exit: cleaning up Jul 11 16:54:56 Ubuntu17 pppd[2833]: Exit. Jul 11 16:54:56 Ubuntu17 NetworkManager[623]: [1499784896.3347] devices removed (path: /sys/devices/virtual/net/ppp0, iface: ppp0)

dkosovic commented 7 years ago

Seems to be having some issues negotiating the LCP Configure-Request, in particular the MRU :

Jul 11 16:54:47 Ubuntu17 pppd[2833]: sent [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0xcb85e497> ]
Jul 11 16:54:53 Ubuntu17 pppd[2833]: message repeated 2 times: [ sent [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0xcb85e497> ]]
Jul 11 16:54:56 Ubuntu17 pppd[2833]: LCP: timeout sending Config-Requests

You might like to try a lower MTU/MRU setting in the VPN connection's PPP Options dialog box.

But doing a Google search, some people claim editing /etc/ppp/options and uncommenting the silent line might solve the LCP timeout issue, e.g. :

# With this option, pppd will not transmit LCP packets to initiate a
# connection until a valid LCP packet is received from the peer (as for
# the "passive" option with old versions of pppd).
silent
dkosovic commented 7 years ago

But in your case would add the silent option to /var/run/nm-l2tp-ppp-options-2d54f0ee-15bd-483d-996e-5286361091c5 to see if it has any effect.

But it could also be one of the exisiting options in the PPP Options dialog box that needs to be enabled/disabled.

rgerbranda commented 7 years ago

Reviewing /var/log/syslog of Ubuntu 16.04 and Ubuntu 17.04, I notice that on Ubuntu 17.04 "nm-l2tp-service[4441]: xl2tpd started with pid 4516"

I only get this when I start the xl2tpd service on Ubuntu 16.04 Not when xl2tpd service is not running.

I verified is the xl2tpd service was running on Ubuntu 17.04, it isn't.

So somehow I think that xl2tpd is interrupting the proces.

dkosovic commented 7 years ago

With the following :

Jul 10 12:15:12 Ubuntu17 NetworkManager[588]: xl2tpd[4516]: death_handler: Fatal signal 15 received

As there is no "Looks like pppd didn't initialize our dbus module" message, it could be a NetworkManager timeout rather than NetworkManager-l2tp timeout. NetworkManager indirectly calls the real_disconect() function :

which sends the SIGTERM (15) kill signal to xl2tpd as it (or its pppd child process) is taking too long to establish a connection.

dkosovic commented 7 years ago

You could also try building xl2tpd from source and installing into /usr/local, I used to recommend that in the past when there were issues with the system xl2tpd e.g. :

Stop and disable xl2tpd, then rename /usr/sbin/xl2tpd so this VPN plug-in doesn't find it at runtime :

sudo systemctl stop xl2tpd
sudo systemctl disable xl2tpd
sudo mv /usr/sbin/xl2tpd /usr/sbin/xl2tpd.bak

Install a build dependency for xl2tpd, obtain the source code, select version 1.3.6 of xl2tpd (as that's what you got working on Ubuntu 16.04), build and install.

sudo apt install libpcap0.8-dev

git clone https://github.com/xelerance/xl2tpd.git
cd xl2tpd
git checkout v1.3.6  
make  
sudo make install  

If it doesn't work, you could try disabling the L2TP kernel module support by commenting out the OSFLAGS+= -DUSE_KERNEL line in the Makefile file, then rebuild and re-install:

sudo systemctl restart network-manager
make clean
make
sudo make install
dkosovic commented 6 years ago

network-manager-l2tp and network-manager-l2tp-gnome are in the Ubuntu 17.10 standard repository. Hopefully it now works for you once again in Ubuntu 17.10.

The following is the code in src/nm-l2tp-service.c where it prints out "xl2tpd started with pid". The xl2tpd child process is asynchronously spawned (i.e. a forked process) and the "xl2tpd started with pid" message is printed out almost immediately after, so I can't explain why you don't see it in some cases. It's probably best not to have the system xl2tpd service running anyway as some VPN servers don't like the use of an ethereal port as mentioned in the README.md file.

    l2tpd_argv = g_ptr_array_new ();
    g_ptr_array_add (l2tpd_argv, (gpointer) g_strdup (l2tpd_binary));
    g_ptr_array_add (l2tpd_argv, (gpointer) g_strdup ("-D"));
    g_ptr_array_add (l2tpd_argv, (gpointer) g_strdup ("-c"));
    g_ptr_array_add (l2tpd_argv, (gpointer) g_strdup_printf (RUNDIR"/nm-l2tp-xl2tpd-%s.conf", priv->uuid));
    g_ptr_array_add (l2tpd_argv, (gpointer) g_strdup ("-C"));
    g_ptr_array_add (l2tpd_argv, (gpointer) g_strdup_printf (RUNDIR"/nm-l2tp-xl2tpd-control-%s", priv->uuid));
    g_ptr_array_add (l2tpd_argv, (gpointer) g_strdup ("-p"));
    g_ptr_array_add (l2tpd_argv, (gpointer) g_strdup_printf (RUNDIR"/nm-l2tp-xl2tpd-%s.pid", priv->uuid));
    g_ptr_array_add (l2tpd_argv, NULL);

    if (!g_spawn_async (NULL, (char **) l2tpd_argv->pdata, NULL,
                        G_SPAWN_DO_NOT_REAP_CHILD, NULL, NULL, &pid, error)) {
        g_ptr_array_free (l2tpd_argv, TRUE);
        return FALSE;
    }
    free_l2tpd_args (l2tpd_argv);

    g_message ("xl2tpd started with pid %d", pid);
cabelitos commented 6 years ago

Hello @dkosovic,

I'm having trouble with your plugin. I'm not able to stabilish a connection with the VPN server, due the following problem:

nm-l2tp[13943] <warn>  Looks like pppd didn't initialize our dbus module

I alredy tried to recompile your package with a bigger timeout, but the problem still persists. I also tried to use xl2tpd 1.3.6, but it did not help.

Here's a extract of the service running on debug mode.

no acceptable traffic selectors found
establishing connection '2ad0c116-2a58-4943-b02e-2501834738fa' failed
nm-l2tp[13943] <info>  strongSwan IPsec tunnel is up.
** Message: xl2tpd started with pid 14011
xl2tpd[14011]: setsockopt recvref[30]: Protocol not available
xl2tpd[14011]: Using l2tp kernel support.
xl2tpd[14011]: xl2tpd version xl2tpd-1.3.10 started on icaros PID:14011
xl2tpd[14011]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc.
xl2tpd[14011]: Forked by Scott Balmos and David Stipp, (C) 2001
xl2tpd[14011]: Inherited by Jeff McAdams, (C) 2002
xl2tpd[14011]: Forked again by Xelerance (www.xelerance.com) (C) 2006-2016
xl2tpd[14011]: Listening on IP address 0.0.0.0, port 1701
xl2tpd[14011]: get_call: allocating new tunnel for host ~THE HOST~, port 1701.
xl2tpd[14011]: Connecting to host ~THE HOST~, port 1701
xl2tpd[14011]: control_finish: message type is (null)(0).  Tunnel is 0, call is 0.
xl2tpd[14011]: control_finish: sending SCCRQ
nm-l2tp[13943] <warn>  Looks like pppd didn't initialize our dbus module
nm-l2tp[13943] <info>  Terminated xl2tpd daemon with PID 14011.
xl2tpd[14011]: death_handler: Fatal signal 15 received
xl2tpd[14011]: Connection 0 closed to ~THE HOST~, port 1701 (Server closing)
Stopping strongSwan IPsec...
** Message: ipsec shut down
nm-l2tp[13943] <warn>  xl2tpd exited with error code 1
Stopping strongSwan IPsec failed: starter is not running
** Message: ipsec shut down

The stronswan config file generated by the plugin.

conn 2ad0c116-2a58-4943-b02e-2501834738fa
  auto=add
  type=transport
  authby=secret
  keyingtries=0
  left=%defaultroute
  leftprotoport=udp/l2tp
  right=~THE HOST~
  rightid=%any
  rightprotoport=udp/l2tp
  keyexchange=ikev1
  ike=3des-sha1-modp1024
  esp=3des-sha1

I'm running ArchLinux with the following packages:

networkmanager-l2tp 1.2.8-1
ppp 2.4.7-4
xl2tpd 1.3.10-1
linux 4.15.5-1

Could you help me? What kind of logs it would be useful for you? I also tried to connect to the VPN by using a fresh installed virtual machine running Ubuntu 17.10, but I had the same problem. Thank you for your help

dkosovic commented 6 years ago

@cabelitos using debug mode increases the debugging, but most of it goes to the systemd journal, view it with journalctl -b.

Are you seeing something like the following in the journal ?

xl2tpd[10000]: udp_xmit failed to 123.54.76.8:1701 with err=-1:No such device

If so, I think something broke pppd in the latest kernels as I don't see that in earlier kernels.

cabelitos commented 6 years ago

Hello @dkosovic

There's no such message in my journalctl, but I can say that xl2tpd tries to send 3 SCCRQ messages before the timeout happens.

As a quick note I already tried xl2tpd with and without kernel support and the same problem happens to both versions.

Should I try to downgrade my kernel?

dkosovic commented 6 years ago

@cabelitos I'm not sure.

With the unreleased Ubuntu 18.04, there have been patches to the ppp package which required rebuilding xl2tpd and network-manager-l2tp packages (but not code changes in those packages). I think the patches were something to do with kernel ppp changes, but didn't look into it too much yet.

If you downgrade kernel on Arch, I would probably try whatever the LTS kernel is.

If you didn't do a apt upgrade on Ubuntu 17.10, I would imagine you would still be using old original packages and maybe older kernel?

cabelitos commented 6 years ago

I tried linux Kernel 4.13.13-1, but no luck :crying_cat_face: (in arch) On ubuntu I did an apt upgrade, so I'm running the latest package verisons. I'm not really sure what to do, I looked at PPP's github repo and the last patch is from 18/March/2017.

cabelitos commented 6 years ago

@dkosovic Hello again,

I tried to switch the backend from strongswan to libreswan and I managed to get the VPN working. However I had to create a hack, which I'm not proud of.

For some reason when using libreswan, calls to ipsec auto --ready (see nm-l2tp-service.c in nm_l2tp_start_ipsec()) returns the code 768. Here's an output

002 listening for IKE messages
002 forgetting secrets
002 loading secrets from "/etc/ipsec.secrets"
002 loading secrets from "/etc/ipsec.d/nm-l2tp-ipsec-a9679924-bdc7-4757-af89-89402be2a330.secrets"
003 WARNING: using a weak secret (PSK)
nm-l2tp[1081] <warn>  cmd: /sbin/ipsec auto --ready - 768 # <- I added this print where 786 is the return code of ipsec.

I did an extremist solution which I just ignore the return code and keep executing the function. I know this is extremely wrong, but at least I'm able to establish the connection..

dkosovic commented 6 years ago

@cabelitos Glad to hear you got it working.

You've hit the Libreswan weak secret (PSK) (i.e. PSK < 8 characters) issue that I put a workaround in place with commit # https://github.com/nm-l2tp/network-manager-l2tp/commit/900233275bf07886dd6161bf9a5de4c62b1bd60e but haven't made a new git release which has it. I probably should release NetworkManager-l2tp 1.2.10

cabelitos commented 6 years ago

@dkosovic awesome, so my patch is not wrong! :smile_cat:

Anyways, once you release a new version I'll update my AUR package. Thank you very much for your help!

dkosovic commented 6 years ago

@cabelitos network-manager-l2tp-1.2.10 release created

Was thinking I was going to add another bug fix, so kept on delaying the release.