Cannot establish an IPSEC connection

Hi,

when trying to use your nm-plugin, my log shows the following lines:

I'm not sure what's going wrong here, as I can't see any meaningful error message. But it seems like it doesn't start up the connection at all. As you can see, I'm on Gentoo using libreswan and your latest code.

I tried to establish an ipsec connection via the command line and did succeed:

systemlog2.txt

So there must be any configuration error with the plugin. Do you have a clue what's wrong here?

I greatly appreciate any help and like to thank you in advance.

Raimund

Could you try establishing a connection on the command-line using the config files generated by this vpn plugin.

First, start it up in debug mode and then kill it (as using debug mode won't delete the generated config files).

sudo killall -TERM nm-l2tp-service
sudo /usr/libexec/nm-l2tp-service --debug
^C

But you may need to replace /usr/libexec/nm-l2tp-service with whatever Gentoo uses.

Then try the following:

sudo ipsec restart
sleep 2
sudo ipsec auto --config /var/run/nm-l2tp-ipsec-3daf-4234-9b32-3234ed87655e.conf --verbose --add 3daf-4234-9b32-3234ed87655e
sudo ipsec auto --up 3daf-4234-9b32-3234ed87655e

sudo ipsec status

The above is almost identical to what this vpn plugin does, except the sleep command is replaced by a loop that runs ipsec auto --ready which rereads the ipsec secrets files untill the ipsec service is ready.

Forgot to mention in regards to ipsec auto --ready, the loop calls it at most 10 times with a 1 second delay between each call which is what you see with the ipsec reloads in the systemlog.txt output. But looks like the ipsec service never becomes ready.

Now that I think about it, it might be a SELinux or AppArmor issue which is preventing the ipsec restart working properly when called as a child process of NetworkManager. You might find running this vpn plugin from the command-line might work, e.g. like with the debug example and then try to connect with the GUI:

sudo killall -TERM nm-l2tp-service
sudo /usr/libexec/nm-l2tp-service --debug

Ok,

thank you for your quick response.

/usr/libexec/nm-l2tp-service --debug

gives me:

nm-l2tp[14786] <debug> nm-l2tp-service (version 1.2.8) starting...
nm-l2tp[14786] <debug>  uses default --bus-name "org.freedesktop.NetworkManager.l2tp"

then /etc/init.d/ipsec restart results in

(...)
Sep 13 12:01:07 [pluto] Using Linux XFRM/NETKEY IPsec interface code on 4.11.0-gentoo
Sep 13 12:01:08 [pluto] seccomp security not supported
Sep 13 12:01:09 [pluto] added connection description "v6neighbor-hole-in"
Sep 13 12:01:09 [pluto] added connection description "v6neighbor-hole-out"
Sep 13 12:01:09 [pluto] listening for IKE messages
Sep 13 12:01:09 [pluto] adding interface vboxnet0/vboxnet0 192.168.56.1:500
Sep 13 12:01:09 [pluto] adding interface vboxnet0/vboxnet0 192.168.56.1:4500
Sep 13 12:01:09 [pluto] adding interface wlan0/wlan0 172.21.58.225:500
Sep 13 12:01:09 [pluto] adding interface wlan0/wlan0 172.21.58.225:4500
Sep 13 12:01:09 [pluto] adding interface lo/lo 127.0.0.1:500
Sep 13 12:01:09 [pluto] adding interface lo/lo 127.0.0.1:4500
Sep 13 12:01:09 [pluto] adding interface lo/lo ::1:500
Sep 13 12:01:09 [pluto] loading secrets from "/etc/ipsec.secrets"
Sep 13 12:01:09 [pluto] loading secrets from "/etc/ipsec.d/nm-l2tp-ipsec-2347e3fe-3daf-4234-9b32-3234ed87655e.secrets"
Sep 13 12:01:09 [pluto] WARNING: using a weak secret (PSK)

ipsec auto --config /var/run/nm-l2tp-ipsec-2347e3fe-3daf-4234-9b32-3234ed87655e.conf --verbose --add 2347e3fe-3daf-4234-9b32-3234ed87655e

results in Sep 13 12:04:41 [pluto] added connection description "2347e3fe-3daf-4234-9b32-3234ed87655e"

in the log and

opening file: /var/run/nm-l2tp-ipsec-2347e3fe-3daf-4234-9b32-3234ed87655e.conf
debugging mode enabled
end of file /var/run/nm-l2tp-ipsec-2347e3fe-3daf-4234-9b32-3234ed87655e.conf
Loading conn 2347e3fe-3daf-4234-9b32-3234ed87655e
starter: left is KH_DEFAULTROUTE
loading named conns: 2347e3fe-3daf-4234-9b32-3234ed87655e
seeking_src = 1, seeking_gateway = 1, has_peer = 1
seeking_src = 0, seeking_gateway = 1, has_dst = 1
dst  via 172.21.255.254 dev wlan0 src  table 254
set nexthop: 172.21.255.254
dst 172.21.0.0 via  dev wlan0 src 172.21.58.225 table 254
dst 192.168.56.0 via  dev vboxnet0 src 192.168.56.1 table 254
dst 127.0.0.0 via  dev lo src 127.0.0.1 table 255 (ignored)
dst 127.0.0.0 via  dev lo src 127.0.0.1 table 255 (ignored)
dst 127.0.0.1 via  dev lo src 127.0.0.1 table 255 (ignored)
dst 127.255.255.255 via  dev lo src 127.0.0.1 table 255 (ignored)
dst 172.21.0.0 via  dev wlan0 src 172.21.58.225 table 255 (ignored)
dst 172.21.58.225 via  dev wlan0 src 172.21.58.225 table 255 (ignored)
dst 172.21.255.255 via  dev wlan0 src 172.21.58.225 table 255 (ignored)
dst 192.168.56.0 via  dev vboxnet0 src 192.168.56.1 table 255 (ignored)
dst 192.168.56.1 via  dev vboxnet0 src 192.168.56.1 table 255 (ignored)
dst 192.168.56.255 via  dev vboxnet0 src 192.168.56.1 table 255 (ignored)

seeking_src = 1, seeking_gateway = 0, has_peer = 1
seeking_src = 1, seeking_gateway = 0, has_dst = 1
dst 172.21.255.254 via  dev wlan0 src 172.21.58.225 table 254
set addr: 172.21.58.225

seeking_src = 0, seeking_gateway = 0, has_peer = 1
conn: "2347e3fe-3daf-4234-9b32-3234ed87655e" modecfgdomain=(null)
conn: "2347e3fe-3daf-4234-9b32-3234ed87655e" modecfgbanner=(null)
conn: "2347e3fe-3daf-4234-9b32-3234ed87655e" mark-in=(null)
conn: "2347e3fe-3daf-4234-9b32-3234ed87655e" mark-out=(null)
conn: "2347e3fe-3daf-4234-9b32-3234ed87655e" vti_iface=(null)
002 added connection description "2347e3fe-3daf-4234-9b32-3234ed87655e"

on the console. Everything alright, so far... now fire up connection: >ipsec auto --up 2347e3fe-3daf-4234-9b32-3234ed87655e leads to following log entries...

Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: initiating Main Mode
Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: WARNING: connection 2347e3fe-3daf-4234-9b32-3234ed87655e PSK length of 6 bytes is too short for sha PRF in FIPS mode (10 bytes required)
Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: STATE_MAIN_I2: sent MI2, expecting MR2
Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: STATE_MAIN_I3: sent MI3, expecting MR3
Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: Peer ID is ID_IPV4_ADDR: 'XXX.XXX.XXX.XXX'
Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: STATE_MAIN_I4: ISAKMP SA established {auth=PRESHARED_KEY cipher=3des_cbc_192 integ=sha group=MODP1024}
Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: initiating Quick Mode PSK+ENCRYPT+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#1 msgid:661ddc6d proposal=defaults pfsgroup=no-pfs}
Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: ignoring informational payload IPSEC_RESPONDER_LIFETIME, msgid=661ddc6d, length=28
Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: STATE_QUICK_I2: sent QI2, IPsec SA established transport mode {ESP=>0x3e129eb1 <0x60330281 xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=passive}
Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: message ignored because it contains an unexpected payload type (ISAKMP_NEXT_HASH)
Sep 13 12:07:59 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: sending encrypted notification INVALID_PAYLOAD_TYPE to XXX.XXX.XXX.XXX:500

and nearly the same appeared on the terminal:

002 "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: initiating Main Mode
104 "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: STATE_MAIN_I1: initiate
002 "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: WARNING: connection 2347e3fe-3daf-4234-9b32-3234ed87655e PSK length of 6 bytes is too short for sha PRF in FIPS mode (10 bytes required)
002 "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
106 "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: STATE_MAIN_I2: sent MI2, expecting MR2
002 "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
108 "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: STATE_MAIN_I3: sent MI3, expecting MR3
002 "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: Peer ID is ID_IPV4_ADDR: 'XXX.XXX.XXX.XXX'
002 "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
004 "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: STATE_MAIN_I4: ISAKMP SA established {auth=PRESHARED_KEY cipher=3des_cbc_192 integ=sha group=MODP1024}
002 "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: initiating Quick Mode PSK+ENCRYPT+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#1 msgid:661ddc6d proposal=defaults pfsgroup=no-pfs}
117 "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: STATE_QUICK_I1: initiate
003 "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: ignoring informational payload IPSEC_RESPONDER_LIFETIME, msgid=661ddc6d, length=28
002 "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
004 "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: STATE_QUICK_I2: sent QI2, IPsec SA established transport mode {ESP=>0x3e129eb1 <0x60330281 xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=passive}

So this works without errors, but still no success with the GUI.

Maybe I should also mention that I had to add the following line to the /var/run/nm-l2tp-ipsec-....conf: ike=3des-sha1;modp1024, otherwise I get the

ignoring informational payload, type NO_PROPOSAL_CHOSEN msgid=00000000

error.

I put the expression in the 'Phase1 Algorithms' field in the GUI, but the conf file did not update. You are right, the problems seems to be the ipsec auto --ready part, how can I debug that?

Hmm, each call of ipsec auto --ready produces the lines in the log:

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-2347e3fe-3daf-4234-9b32-3234ed87655e.secrets"
003 WARNING: using a weak secret (PSK)

how does the plugin determine if the ipsec service is ready? I guess, it actually is ready at this point?

So, here is the problem:

from https://github.com/nm-l2tp/network-manager-l2tp/blob/master/src/nm-l2tp-service.c, line 998-1003:

    snprintf (cmdbuf, sizeof(cmdbuf), "%s auto --ready", priv->ipsec_binary_path);
    sys = system (cmdbuf);
    for (retry = 0; retry < 10 && sys != 0; retry++) {
        sleep (1);
        sys = system (cmdbuf);
    }

sys is expected to be 0, but when I call ipsec auto --ready I get

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-2347e3fe-3daf-4234-9b32-3234ed87655e.secrets"
003 WARNING: using a weak secret (PSK)

I assume this warning results in error code 3: echo $? --> 3 sys is 3 and the script doesn't recognize it's just a warning. Hmm. Any ideas?

Meanwhile, I simply exchanged the problematic block with a simple one-liner: sleep (2); One second is not enough, if ipsec auto --up is called before the service is ready, I get a 024 need --listen before --initiate error. But two seconds seem to be fine (it works for me).

Now I'm stuck inside the xl2tpd-part, here is the /usr/libexec/nm-l2tp-service --debug output:

nm-l2tp[25460] <info>  Libreswan IPsec tunnel is up.
** Message: xl2tpd started with pid 26053
xl2tpd[26053]: setsockopt recvref[30]: Protocol not available
xl2tpd[26053]: This binary does not support kernel L2TP.
xl2tpd[26053]: xl2tpd version xl2tpd-1.3.10 started on TPad470p PID:26053
xl2tpd[26053]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc.
xl2tpd[26053]: Forked by Scott Balmos and David Stipp, (C) 2001
xl2tpd[26053]: Inherited by Jeff McAdams, (C) 2002
xl2tpd[26053]: Forked again by Xelerance (www.xelerance.com) (C) 2006-2016
xl2tpd[26053]: Listening on IP address 0.0.0.0, port 56540
xl2tpd[26053]: get_call: allocating new tunnel for host XXX.XXX.XXX.XXX, port 1701.
xl2tpd[26053]: Connecting to host XXX.XXX.XXX.XXX, port 1701
xl2tpd[26053]: control_finish: message type is (null)(0).  Tunnel is 0, call is 0.
xl2tpd[26053]: control_finish: sending SCCRQ
xl2tpd[26053]: message_type_avp: message type 2 (Start-Control-Connection-Reply)
xl2tpd[26053]: protocol_version_avp: peer is using version 1, revision 0.
xl2tpd[26053]: framing_caps_avp: supported peer frames: sync
xl2tpd[26053]: bearer_caps_avp: supported peer bearers:
xl2tpd[26053]: firmware_rev_avp: peer reports firmware version 1537 (0x0601)
xl2tpd[26053]: hostname_avp: peer reports hostname 'vpnserver.com'
xl2tpd[26053]: vendor_avp: peer reports vendor 'Microsoft'
xl2tpd[26053]: assigned_tunnel_avp: using peer's tunnel 1489
xl2tpd[26053]: receive_window_size_avp: peer wants RWS of 8.  Will use flow control.
xl2tpd[26053]: control_finish: message type is Start-Control-Connection-Reply(2).  Tunnel is 1489, call is 0.
xl2tpd[26053]: control_finish: sending SCCCN
xl2tpd[26053]: Connection established to XXX.XXX.XXX.XXX, 1701.  Local: 13065, Remote: 1489 (ref=0/0).
xl2tpd[26053]: Calling on tunnel 13065
xl2tpd[26053]: control_finish: message type is (null)(0).  Tunnel is 1489, call is 0.
xl2tpd[26053]: control_finish: sending ICRQ
xl2tpd[26053]: message_type_avp: message type 11 (Incoming-Call-Reply)
xl2tpd[26053]: assigned_call_avp: using peer's call 2
xl2tpd[26053]: control_finish: message type is Incoming-Call-Reply(11).  Tunnel is 1489, call is 2.
xl2tpd[26053]: control_finish: Sending ICCN
xl2tpd[26053]: Call established with XXX.XXX.XXX.XXX, Local: 2933, Remote: 2, Serial: 1 (ref=0/0)
xl2tpd[26053]: start_pppd: I'm running: 
xl2tpd[26053]: "/usr/sbin/pppd" 
xl2tpd[26053]: "/dev/pts/20" 
xl2tpd[26053]: "passive" 
xl2tpd[26053]: "nodetach" 
xl2tpd[26053]: ":" 
xl2tpd[26053]: "debug" 
xl2tpd[26053]: "file" 
xl2tpd[26053]: "/var/run/nm-l2tp-ppp-options-2347e3fe-3daf-4234-9b32-3234ed87655e" 
xl2tpd[26053]: message_type_avp: message type 14 (Call-Disconnect-Notify)
xl2tpd[26053]: result_code_avp: peer closing for reason 3 (Control channel already exists), error = 0 ()
xl2tpd[26053]: assigned_call_avp: using peer's call 2
xl2tpd[26053]: control_finish: message type is Call-Disconnect-Notify(14).  Tunnel is 1489, call is 2.
xl2tpd[26053]: control_finish: Connection closed to XXX.XXX.XXX.XXX, serial 1 ()
xl2tpd[26053]: Terminating pppd: sending TERM signal to pid 26054
nm-l2tp[25460] <info>  Terminated xl2tpd daemon with PID 26053.
xl2tpd[26053]: death_handler: Fatal signal 15 received
002 "2347e3fe-3daf-4234-9b32-3234ed87655e": deleting non-instance connection
002 "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: deleting state (STATE_QUICK_I2) and sending notification
005 "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: ESP traffic information: in=0B out=0B
002 "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: deleting state (STATE_MAIN_I4) and sending notification

and meanwhile, this appears in the system log:

Sep 13 16:57:24 [NetworkManager] <info>  [1505314644.0834] vpn-connection[0x557efca604b0,2347e3fe-3daf-4234-9b32-3234ed87655e,"my-vpn",0]: VPN plugin: state changed: starting (3)
Sep 13 16:57:24 [pppd] Plugin /usr/lib64/pppd/2.4.7/nm-l2tp-pppd-plugin.so loaded.
Sep 13 16:57:24 [pppd] nm-l2tp[10277] <info>  [helper-10871] initializing_
Sep 13 16:57:24 [pppd] pppd 2.4.7 started by user, uid 0
Sep 13 16:57:24 [pppd] nm-l2tp[10277] <info>  [helper-10871] phasechange: status 3 / phase 'serial connection'_
Sep 13 16:57:24 [pppd] Using interface ppp0
Sep 13 16:57:24 [pppd] Connect: ppp0 <--> /dev/pts/20
Sep 13 16:57:24 [pppd] nm-l2tp[10277] <info>  [helper-10871] phasechange: status 5 / phase 'establish'_
Sep 13 16:57:24 [NetworkManager] <info>  [1505314644.1270] manager: (ppp0): new Generic device (/org/freedesktop/NetworkManager/Devices/18)
Sep 13 16:57:24 [pppd] Modem hangup
Sep 13 16:57:24 [pppd] nm-l2tp[10277] <info>  [helper-10871] phasechange: status 11 / phase 'disconnect'_
Sep 13 16:57:24 [pppd] Connection terminated.
Sep 13 16:57:24 [NetworkManager] <warn>  [1505314644.1318] vpn-connection[0x557efca604b0,2347e3fe-3daf-4234-9b32-3234ed87655e,"my-vpn",0]: VPN plugin: failed: connect-failed (1)
Sep 13 16:57:24 [NetworkManager] <info>  [1505314644.1320] vpn-connection[0x557efca604b0,2347e3fe-3daf-4234-9b32-3234ed87655e,"my-vpn",0]: VPN plugin: state changed: stopping (5)
Sep 13 16:57:24 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e": deleting non-instance connection
Sep 13 16:57:24 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: deleting state (STATE_QUICK_I2) and sending notification
Sep 13 16:57:24 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #2: ESP traffic information: in=0B out=0B
Sep 13 16:57:24 [pppd] nm-l2tp[10277] <info>  [helper-10871] phasechange: status 1 / phase 'dead'_
Sep 13 16:57:24 [pppd] nm-l2tp[10277] <info>  [helper-10871] exit: cleaning up_
Sep 13 16:57:24 [pppd] Exit.
Sep 13 16:57:24 [pluto] "2347e3fe-3daf-4234-9b32-3234ed87655e" #1: deleting state (STATE_MAIN_I4) and sending notification

Again, I can't see a meaningful error message. And again, thank you so much for your input.

Not sure why libreswan is not working after using ipsec auto --ready, in the libreswan code it just seems to print out a weak secret PSK warning:

https://github.com/libreswan/libreswan/blob/master/lib/libswan/secrets.c#L625

But guess it might have some side effect somewhere else in the libreswan code and sounds like a libreswan bug.

Before my time in maintaining this vpn-plugin, the code had no sleep which caused issues for many people, then sleep(1) was introduced and apparently that wasn't enough and some needed sleep(2) or even longer. When I took over 18 months ago, I added ipsec auto --ready and soon after it became a loop which stopped reports of timing bugs.

In regards to xl2tpd, see "Issue with not stopping system xl2tpd service" in the README.md file :

https://github.com/nm-l2tp/network-manager-l2tp#issue-with-not-stopping-system-xl2tpd-service

From the logs, the xl2tpd child process is using port 56540 instead of port 1701 so suspect the VPN server or firewall doesn't like the use of port 56540.

Hi,

regarding the ipsec auto --ready issue, I also think, this solution is better then a simple sleep(#). And if I'm the only one complaining you may of course leave the code as it is, or maybe reduce the loop counter to say 3, increase the sleep in the loop from 1 to 2 and then continue in any case, that is, do not check if (!sys) in line 1035. If there is really no ipsec service, it will probably fail in the block at line 1113ff. No computers will be harmed. :-)

Regarding xl2pd: This is strange. I made sure no xl2tpd is running before trying to connect with the GUI. But the error and log stays nearly the same, except one line: xl2tpd[31548]: Listening on IP address 0.0.0.0, port 1701

Everything else is the same as in the above logs, where you can also see the lines

xl2tpd[31548]: get_call: allocating new tunnel for host XXX.XXX.XXX.XXX, port 1701.
xl2tpd[31548]: Connecting to host XXX.XXX.XXX.XXX, port 1701

and later

xl2tpd[31548]: Connection established to XXX.XXX.XXX.XXX, 1701.  Local: 45400, Remote: 1539 (ref=0/0).
xl2tpd[31548]: Calling on tunnel 45400

It must be something different. I could establish a ipsec/l2tp connection on the command line, so it's not an issue with missing kernel modules or other version conflicts on my system. The only awkward log lines I still see are these:

(...)
xl2tpd[31548]: start_pppd: I'm running: 
xl2tpd[31548]: "/usr/sbin/pppd" 
xl2tpd[31548]: "/dev/pts/21" 
xl2tpd[31548]: "passive" 
xl2tpd[31548]: "nodetach" 
xl2tpd[31548]: ":" 
xl2tpd[31548]: "debug" 
xl2tpd[31548]: "file" 
xl2tpd[31548]: "/var/run/nm-l2tp-ppp-options-2347e3fe-3daf-4234-9b32-3234ed87655e" 
xl2tpd[31548]: message_type_avp: message type 14 (Call-Disconnect-Notify)
xl2tpd[31548]: result_code_avp: peer closing for reason 3 (Control channel already exists), error = 0 ()
xl2tpd[31548]: assigned_call_avp: using peer's call 2
xl2tpd[31548]: control_finish: message type is Call-Disconnect-Notify(14).  Tunnel is 1539, call is 2.
(...)

At the moment, I have no further ideas how to debug this.

Regarding libreswan, I'm open to your code modification suggestion, but want to do some more investigation. I actually misunderstood the issue you had, I made the assumption that if ipsec auto --ready was called at least once it would subsequently break things for you.

I've done some more digging into libreswan's exit codes, pluto is libreswan's IKE daemon and its return codes are :

running.
dead but subsys locked.
stopped.
status unknown due to insufficient privileges.

Which version of libreswan are you using? Are you using systemd with Gentoo? Perhaps you might be the first that has hit this bug because you are using a new version of libreswan.

Regarding the xl2tpd control channel already exists issue, I'm guessing it is because the following named pipe already exists and can't be overwritten for some reason :

/var/run/nm-l2tp-xl2tpd-control-3daf-4234-9b32-3234ed87655e

I've never encountered that issue, so not sure why it is happening and /usr/sbin/xl2tpd-control isn't used so this vpn plugin doesn't need that named pipe anyway.

My Gentoo uses an unmodified version of https://download.libreswan.org/libreswan-3.21.tar.gz. And no, I'm not using systemd, but OpenRC, which is still the default for Gentoo, and thankfully there are many Gentoo admins who do much effort in keeping everything compatible with OpenRC. However, anyone could also use systemd with Gentoo.

But I just tried with libreswan-3.18, and get the same result.

An alternative to ipsec auto --ready could be ipsec status, or ipsec auto --status, which returns a lot of messages when ipsec is running, and return code 0, or, when it's not running, whack: Pluto is not running (no "/var/run/pluto/pluto.ctl"), and return code 1.

Thank you for the hint regarding the /var/run/nm-l2tp-xl2tpd-control... file, I try to check that.

I just stumbled across this here: ipsec verify gives me:

Verifying installed system and configuration files

Version check and ipsec on-path                     [OK]
Libreswan 3.21 (netkey) on 4.11.0-gentoo
Checking for IPsec support in kernel                [OK]
 NETKEY: Testing XFRM related proc values
         ICMP default/send_redirects                [OK]
         ICMP default/accept_redirects              [OK]
         XFRM larval drop                           [OK]
Pluto ipsec.conf syntax                             [OK]
Two or more interfaces found, checking IP forwarding    [OK]
Checking rp_filter                                  [OK]
Checking that pluto is running                      [OK]
 Pluto listening for IKE on udp 500                 [OK]
 Pluto listening for IKE/NAT-T on udp 4500          [OK]
 Pluto ipsec.secret syntax                        INTERNAL ERROR - unknown rcode:WARNING
  003 WARNING: using a weak secret (PSK)
Checking 'ip' command                               [OK]
Checking 'iptables' command                         [OK]
Checking 'prelink' command does not interfere with FIPS [OK]
Checking for obsolete ipsec.conf options            [OK]

and I've read somewhere that the valid rcode should be 'WARN' instead of 'WARNING', but I'm not sure if this is the main problem.

Yeah!!! I finally managed to get a working vpn connection via the GUI! Meanwhile, also the manual connection didn't work anymore, without useful error messages. In the last hours, I tried to insert, change, and delete many options in various conf files, and I can't say which change made the breakthrough.

And I didn't find any /var/run/nm-l2tp-xl2tpd-control...-file until right now, having a working connection. So once again: Thank you very much for your help!!

That's great news you got it going!

And no, I'm not using systemd, but OpenRC, which is still the default for Gentoo

Only reason I brought up systemd is because I remember reading with the Debian package that the libreswan SysV init.d script suppled with the upstream source was no longer maintained and had some bugs and wasn't being bundled until it got fixed. As /usr/sbin/ipsec is partially tied to systemd or init.d, I didn't want to rule it out that the RC script was related to --ready returning a status code of 3. But chances are it isn't releated.

That's an interesting theory regarding 'WARN' vs 'WARNING'.

ipsec auto --status used to return a wrong status code in some cases with some older versions of libreswan, but it got fixed. But I agree, it probably could be used as a replacement for --ready.

Another fix is not to restart libreswan if it is already running and then no need for a loop. There are historical reasons why --restart was used, but most aren't applicable now for libreswan (but other reasons are applicable for strongswan).

nm-l2tp / NetworkManager-l2tp

Cannot establish an IPSEC connection #64