Issues changing ipsec configuration

akshatd commented 3 years ago

Summary

Hi, am trying to connect an L2Tp VPN using NetworkManager, but it forces the use of port 1701 during the "Quick Mode proposal", and so if two machines behind the same NAT try to use it at the same time, the connection fails with the error message "cannot install eroute -- it is in use for "l2tp-psk"[49] x.x.x.x #223" on the VPN Server.

One of the machines that proposes the port 1701 is a windows server 2019, and i cannot change its settings, so I was trying to see if I can change the ipsec configuration on my side. If only the windows server is connected or if only my linux machine is connected, then the VPN connects just fine. However, if any of these machines tries to connect while the other one is already connected, it fails.

This happens with both libreswan and strongswan

Things I have tried

noticed that the normal way to change this would be to add the option rightprotoport=17/%any in /etc/ipsec.conf under conn 7be1fd4b-5560-4b9d-82e3-4091ddf3f3f9 as described in the "L2TP/IPsec client configuration" section here, but that did not do anything, the port proposal is still the same
NetworkManager uses the connection settings in /var/ru/nm-l2tp-7be1fd4b-5560-4b9d-82e3-4091ddf3f3f9/ipsec.conf, so tried to edit that file and put the rightprotoport=17/%any option there, but that entire folder gets deleted once the VPN is disconnected and is re-generated during runtime so changing it doesnt work
I am really at a loss, pls help :(

Config

VPN Server configured using: https://github.com/hwdsl2/setup-ipsec-vpn
Linux VPN Client configured using: https://github.com/hwdsl2/setup-ipsec-vpn/blob/master/docs/clients.md#ubuntu-linux

My system: uname -a

Linux akshat-tp 5.10.68-1-MANJARO #1 SMP PREEMPT Wed Sep 22 12:29:47 UTC 2021 x86_64 GNU/Linux

Packages installed: pacman -Qe | grep network

kdenetwork-filesharing 21.08.1-2
networkmanager 1.32.12-1
networkmanager-l2tp 1.8.6-5
networkmanager-openconnect 1.2.7dev+65+gca4187c-1
networkmanager-openvpn 1.8.14-1
networkmanager-pptp 1.2.9dev+10+gb41b0d0-4
networkmanager-strongswan 1.5.2-2
networkmanager-vpnc 1.2.7dev+20+gdca3aea-2

pacman -Qe | grep swan

networkmanager-strongswan 1.5.2-2
strongswan 5.9.3-1

My connection file: cat /etc/NetworkManager/system-connections/new.nmconnection


[connection]
id=new
uuid=c9bc3ec7-4541-4eba-93e7-f209455c12d8
type=vpn
permissions=user:akshatd:;

[vpn] gateway=vpn-server-addr.org ipsec-enabled=yes ipsec-esp=aes128-sha1 ipsec-ike=aes128-sha1-modp2048 ipsec-psk=some-psk password-flags=1 user=user@company.com service-type=org.freedesktop.NetworkManager.l2tp

[ipv4] dns-search= method=auto

[ipv6] addr-gen-mode=stable-privacy dns-search= method=auto

[proxy]


### Logs
- I have obfuscated the client and server public IP addresses to `<client.public.ip.addr>` and `<vpnserver.public.ip.addr>`
- A successful connection looks like this (when the windows server is disconnected):
- - VPN Server: `sudo tail -f /var/log/auth.log`

Oct 1 06:22:35 hq-vpn pluto[443976]: "l2tp-psk"[52] #247: responding to Main Mode from unknown peer :500 Oct 1 06:22:35 hq-vpn pluto[443976]: "l2tp-psk"[52] #247: STATE_MAIN_R1: sent MR1, expecting MI2 Oct 1 06:22:35 hq-vpn pluto[443976]: "l2tp-psk"[52] #247: STATE_MAIN_R2: sent MR2, expecting MI3 Oct 1 06:22:35 hq-vpn pluto[443976]: "l2tp-psk"[52] #247: Peer ID is ID_IPV4_ADDR: '192.168.0.112' Oct 1 06:22:35 hq-vpn pluto[443976]: "l2tp-psk"[52] #247: switched from "l2tp-psk"[52] to "l2tp-psk" Oct 1 06:22:35 hq-vpn pluto[443976]: "l2tp-psk"[57] #247: Peer ID is ID_IPV4_ADDR: '192.168.0.112' Oct 1 06:22:35 hq-vpn pluto[443976]: "l2tp-psk"[57] #247: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=PRESHARED_KEY cipher=AES_CBC_128 integ=HMAC_SHA1 group=MODP2048} Oct 1 06:22:35 hq-vpn pluto[443976]: "l2tp-psk"[57] #247: the peer proposed: /32:17/1701 -> 192.168.0.112/32:17/0 Oct 1 06:22:35 hq-vpn pluto[443976]: "l2tp-psk"[57] #247: NAT-Traversal: received 2 NAT-OA. Using first; ignoring others Oct 1 06:22:35 hq-vpn pluto[443976]: "l2tp-psk"[57] #248: responding to Quick Mode proposal {msgid:a4940b12} Oct 1 06:22:35 hq-vpn pluto[443976]: "l2tp-psk"[57] #248: us: 192.168.100.2[]:17/1701 Oct 1 06:22:35 hq-vpn pluto[443976]: "l2tp-psk"[57] #248: them: [192.168.0.112]:17/1701 Oct 1 06:22:35 hq-vpn pluto[443976]: "l2tp-psk"[57] #248: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2 transport mode {ESP/NAT=>0xc67f5d22 <0xef5cd554 xfrm=AES_CBC_128-HMAC_SHA1_96 NATOA=192.168.0.112 NATD=:4500 DPD=active} Oct 1 06:22:35 hq-vpn pluto[443976]: "l2tp-psk"[57] #248: STATE_QUICK_R2: IPsec SA established transport mode {ESP/NAT=>0xc67f5d22 <0xef5cd554 xfrm=AES_CBC_128-HMAC_SHA1_96 NATOA=192.168.0.112 NATD=:4500 DPD=active}


-  - Linux Client: `journalctl --no-hostname _SYSTEMD_UNIT=NetworkManager.service + SYSLOG_IDENTIFIER=pppd -xf`

Oct 01 14:22:30 NetworkManager[3301]: [1633069350.6009] audit: op="statistics" interface="enp4s0f3u1u2" ifindex=4 args="2000" pid=1293 uid=1000 result="success" Oct 01 14:22:30 NetworkManager[3301]: [1633069350.6166] audit: op="statistics" interface="wlp3s0" ifindex=3 args="2000" pid=1293 uid=1000 result="success" Oct 01 14:22:32 NetworkManager[3301]: [1633069352.2432] audit: op="connection-activate" uuid="c9bc3ec7-4541-4eba-93e7-f209455c12d8" name="new" pid=1293 uid=1000 result="success" Oct 01 14:22:32 NetworkManager[3301]: [1633069352.2473] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",0]: Started the VPN service, PID 6500 Oct 01 14:22:32 NetworkManager[3301]: [1633069352.2571] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",0]: Saw the service appear; activating connection Oct 01 14:22:32 NetworkManager[3301]: [1633069352.2697] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",0]: VPN connection: (ConnectInteractive) reply received Oct 01 14:22:32 nm-l2tp-service[6500]: Check port 1701 Oct 01 14:22:32 NetworkManager[6513]: Stopping strongSwan IPsec failed: starter is not running Oct 01 14:22:34 NetworkManager[6510]: Starting strongSwan 5.9.3 IPsec [starter]... Oct 01 14:22:34 NetworkManager[6510]: Loading config setup Oct 01 14:22:34 NetworkManager[6510]: Loading conn 'c9bc3ec7-4541-4eba-93e7-f209455c12d8' Oct 01 14:22:34 ipsec_starter[6510]: Starting strongSwan 5.9.3 IPsec [starter]... Oct 01 14:22:34 ipsec_starter[6510]: Loading config setup Oct 01 14:22:34 ipsec_starter[6510]: Loading conn 'c9bc3ec7-4541-4eba-93e7-f209455c12d8' Oct 01 14:22:34 ipsec_starter[6521]: Attempting to start charon... Oct 01 14:22:34 charon[6522]: 00[DMN] Starting IKE charon daemon (strongSwan 5.9.3, Linux 5.10.68-1-MANJARO, x86_64) Oct 01 14:22:34 charon[6522]: 00[CFG] PKCS11 module '' lacks library path Oct 01 14:22:34 charon[6522]: 00[LIB] plugin 'mysql' failed to load: libmariadb.so.3: cannot open shared object file: No such file or directory Oct 01 14:22:34 charon[6522]: 00[CFG] attr-sql plugin: database URI not set Oct 01 14:22:34 charon[6522]: 00[NET] using forecast interface wlp3s0 Oct 01 14:22:34 charon[6522]: 00[CFG] joining forecast multicast groups: 224.0.0.1,224.0.0.22,224.0.0.251,224.0.0.252,239.255.255.250 Oct 01 14:22:34 charon[6522]: 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts' Oct 01 14:22:34 charon[6522]: 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts' Oct 01 14:22:34 charon[6522]: 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts' Oct 01 14:22:34 charon[6522]: 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts' Oct 01 14:22:34 charon[6522]: 00[CFG] loading crls from '/etc/ipsec.d/crls' Oct 01 14:22:34 charon[6522]: 00[CFG] loading secrets from '/etc/ipsec.secrets' Oct 01 14:22:34 charon[6522]: 00[CFG] loading secrets from '/etc/ipsec.d/ipsec.nm-l2tp.secrets' Oct 01 14:22:34 charon[6522]: 00[CFG] loaded IKE secret for %any Oct 01 14:22:34 charon[6522]: 00[CFG] sql plugin: database URI not set Oct 01 14:22:34 charon[6522]: 00[CFG] opening triplet file /etc/ipsec.d/triplets.dat failed: No such file or directory Oct 01 14:22:34 charon[6522]: 00[CFG] loaded 0 RADIUS server configurations Oct 01 14:22:34 charon[6522]: 00[CFG] HA config misses local/remote address Oct 01 14:22:34 charon[6522]: 00[CFG] no script for ext-auth script defined, disabled Oct 01 14:22:34 charon[6522]: 00[LIB] loaded plugins: charon ldap pkcs11 aesni aes des rc2 sha2 sha3 sha1 md5 mgf1 random nonce x509 revocation constraints pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey sshkey pem openssl fips-prf gmp curve25519 agent chapoly xcbc cmac hmac ntru drbg newhope bliss curl sqlite attr kernel-netlink resolve socket-default bypass-lan connmark forecast farp stroke vici updown eap-identity eap-sim eap-aka eap-aka-3gpp2 eap-simaka-pseudonym eap-simaka-reauth eap-md5 eap-gtc eap-mschapv2 eap-dynamic eap-radius eap-tls eap-ttls eap-peap xauth-generic xauth-eap xauth-pam xauth-noauth dhcp radattr unity counters Oct 01 14:22:34 charon[6522]: 00[LIB] dropped capabilities, running as uid 0, gid 0 Oct 01 14:22:34 charon[6522]: 00[JOB] spawning 16 worker threads Oct 01 14:22:34 charon[6522]: 05[IKE] installed bypass policy for 192.168.0.0/24 Oct 01 14:22:34 charon[6522]: 05[IKE] installed bypass policy for ::1/128 Oct 01 14:22:34 charon[6522]: 05[IKE] installed bypass policy for fe80::/64 Oct 01 14:22:34 charon[6522]: 05[IKE] interface change for bypass policy for 192.168.0.0/24 (from enp4s0f3u1u2 to wlp3s0) Oct 01 14:22:34 charon[6522]: 05[IKE] interface change for bypass policy for fe80::/64 (from enp4s0f3u1u2 to wlp3s0) Oct 01 14:22:34 ipsec_starter[6521]: charon (6522) started after 40 ms Oct 01 14:22:34 charon[6522]: 11[CFG] received stroke: add connection 'c9bc3ec7-4541-4eba-93e7-f209455c12d8' Oct 01 14:22:34 charon[6522]: 11[CFG] added configuration 'c9bc3ec7-4541-4eba-93e7-f209455c12d8' Oct 01 14:22:35 charon[6522]: 05[CFG] rereading secrets Oct 01 14:22:35 charon[6522]: 05[CFG] loading secrets from '/etc/ipsec.secrets' Oct 01 14:22:35 charon[6522]: 05[CFG] loading secrets from '/etc/ipsec.d/ipsec.nm-l2tp.secrets' Oct 01 14:22:35 charon[6522]: 05[CFG] loaded IKE secret for %any Oct 01 14:22:35 charon[6522]: 14[CFG] received stroke: initiate 'c9bc3ec7-4541-4eba-93e7-f209455c12d8' Oct 01 14:22:35 charon[6522]: 15[IKE] initiating Main Mode IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] to Oct 01 14:22:35 charon[6522]: 15[IKE] initiating Main Mode IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] to Oct 01 14:22:35 charon[6522]: 15[ENC] generating ID_PROT request 0 [ SA V V V V V ] Oct 01 14:22:35 charon[6522]: 15[NET] sending packet: from 192.168.0.112[500] to [500] (240 bytes) Oct 01 14:22:35 charon[6522]: 01[NET] received packet: from [500] to 192.168.0.112[500] (144 bytes) Oct 01 14:22:35 charon[6522]: 01[ENC] parsed ID_PROT response 0 [ SA V V V ] Oct 01 14:22:35 charon[6522]: 01[IKE] received FRAGMENTATION vendor ID Oct 01 14:22:35 charon[6522]: 01[IKE] received DPD vendor ID Oct 01 14:22:35 charon[6522]: 01[IKE] received NAT-T (RFC 3947) vendor ID Oct 01 14:22:35 charon[6522]: 01[CFG] selected proposal: IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048 Oct 01 14:22:35 charon[6522]: 01[ENC] generating ID_PROT request 0 [ KE No NAT-D NAT-D ] Oct 01 14:22:35 charon[6522]: 01[NET] sending packet: from 192.168.0.112[500] to [500] (372 bytes) Oct 01 14:22:35 charon[6522]: 13[NET] received packet: from [500] to 192.168.0.112[500] (372 bytes) Oct 01 14:22:35 charon[6522]: 13[ENC] parsed ID_PROT response 0 [ KE No NAT-D NAT-D ] Oct 01 14:22:35 charon[6522]: 13[IKE] local host is behind NAT, sending keep alives Oct 01 14:22:35 charon[6522]: 13[IKE] remote host is behind NAT Oct 01 14:22:35 charon[6522]: 13[ENC] generating ID_PROT request 0 [ ID HASH ] Oct 01 14:22:35 charon[6522]: 13[NET] sending packet: from 192.168.0.112[4500] to [4500] (76 bytes) Oct 01 14:22:35 charon[6522]: 07[NET] received packet: from [4500] to 192.168.0.112[4500] (76 bytes) Oct 01 14:22:35 charon[6522]: 07[ENC] parsed ID_PROT response 0 [ ID HASH ] Oct 01 14:22:35 charon[6522]: 07[IKE] IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] established between 192.168.0.112[192.168.0.112]...[] Oct 01 14:22:35 charon[6522]: 07[IKE] IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] established between 192.168.0.112[192.168.0.112]...[] Oct 01 14:22:35 charon[6522]: 07[IKE] scheduling reauthentication in 9963s Oct 01 14:22:35 charon[6522]: 07[IKE] maximum IKE_SA lifetime 10503s Oct 01 14:22:35 charon[6522]: 07[ENC] generating QUICK_MODE request 2761165586 [ HASH SA No ID ID NAT-OA NAT-OA ] Oct 01 14:22:35 charon[6522]: 07[NET] sending packet: from 192.168.0.112[4500] to [4500] (252 bytes) Oct 01 14:22:35 charon[6522]: 08[NET] received packet: from [4500] to 192.168.0.112[4500] (172 bytes) Oct 01 14:22:35 charon[6522]: 08[ENC] parsed QUICK_MODE response 2761165586 [ HASH SA No ID ID ] Oct 01 14:22:35 charon[6522]: 08[CFG] selected proposal: ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ Oct 01 14:22:35 charon[6522]: 08[IKE] CHILD_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8{1} established with SPIs c67f5d22_i ef5cd554_o and TS 192.168.0.112/32[udp/l2f] === /32[udp/l2f] Oct 01 14:22:35 charon[6522]: 08[IKE] CHILD_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8{1} established with SPIs c67f5d22_i ef5cd554_o and TS 192.168.0.112/32[udp/l2f] === /32[udp/l2f] Oct 01 14:22:35 charon[6522]: 08[ENC] generating QUICK_MODE request 2761165586 [ HASH ] Oct 01 14:22:35 charon[6522]: 08[NET] sending packet: from 192.168.0.112[4500] to [4500] (60 bytes) Oct 01 14:22:35 NetworkManager[6549]: initiating Main Mode IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] to Oct 01 14:22:35 NetworkManager[6549]: generating ID_PROT request 0 [ SA V V V V V ] Oct 01 14:22:35 NetworkManager[6549]: sending packet: from 192.168.0.112[500] to [500] (240 bytes) Oct 01 14:22:35 NetworkManager[6549]: received packet: from [500] to 192.168.0.112[500] (144 bytes) Oct 01 14:22:35 NetworkManager[6549]: parsed ID_PROT response 0 [ SA V V V ] Oct 01 14:22:35 NetworkManager[6549]: received FRAGMENTATION vendor ID Oct 01 14:22:35 NetworkManager[6549]: received DPD vendor ID Oct 01 14:22:35 NetworkManager[6549]: received NAT-T (RFC 3947) vendor ID Oct 01 14:22:35 NetworkManager[6549]: selected proposal: IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048 Oct 01 14:22:35 NetworkManager[6549]: generating ID_PROT request 0 [ KE No NAT-D NAT-D ] Oct 01 14:22:35 NetworkManager[6549]: sending packet: from 192.168.0.112[500] to [500] (372 bytes) Oct 01 14:22:35 NetworkManager[6549]: received packet: from [500] to 192.168.0.112[500] (372 bytes) Oct 01 14:22:35 NetworkManager[6549]: parsed ID_PROT response 0 [ KE No NAT-D NAT-D ] Oct 01 14:22:35 NetworkManager[6549]: local host is behind NAT, sending keep alives Oct 01 14:22:35 NetworkManager[6549]: remote host is behind NAT Oct 01 14:22:35 NetworkManager[6549]: generating ID_PROT request 0 [ ID HASH ] Oct 01 14:22:35 NetworkManager[6549]: sending packet: from 192.168.0.112[4500] to [4500] (76 bytes) Oct 01 14:22:35 NetworkManager[6549]: received packet: from [4500] to 192.168.0.112[4500] (76 bytes) Oct 01 14:22:35 NetworkManager[6549]: parsed ID_PROT response 0 [ ID HASH ] Oct 01 14:22:35 NetworkManager[6549]: IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] established between 192.168.0.112[192.168.0.112]...[] Oct 01 14:22:35 NetworkManager[6549]: scheduling reauthentication in 9963s Oct 01 14:22:35 NetworkManager[6549]: maximum IKE_SA lifetime 10503s Oct 01 14:22:35 NetworkManager[6549]: generating QUICK_MODE request 2761165586 [ HASH SA No ID ID NAT-OA NAT-OA ] Oct 01 14:22:35 NetworkManager[6549]: sending packet: from 192.168.0.112[4500] to [4500] (252 bytes) Oct 01 14:22:35 NetworkManager[6549]: received packet: from [4500] to 192.168.0.112[4500] (172 bytes) Oct 01 14:22:35 NetworkManager[6549]: parsed QUICK_MODE response 2761165586 [ HASH SA No ID ID ] Oct 01 14:22:35 NetworkManager[6549]: selected proposal: ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ Oct 01 14:22:35 NetworkManager[6549]: CHILD_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8{1} established with SPIs c67f5d22_i ef5cd554_o and TS 192.168.0.112/32[udp/l2f] === /32[udp/l2f] Oct 01 14:22:35 NetworkManager[6549]: generating QUICK_MODE request 2761165586 [ HASH ] Oct 01 14:22:35 NetworkManager[6549]: connection 'c9bc3ec7-4541-4eba-93e7-f209455c12d8' established successfully Oct 01 14:22:35 nm-l2tp-service[6500]: xl2tpd started with pid 6555 Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: Not looking for kernel SAref support. Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: Using l2tp kernel support. Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: xl2tpd version xl2tpd-1.3.16 started on akshat-tp PID:6555 Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc. Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: Forked by Scott Balmos and David Stipp, (C) 2001 Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: Inherited by Jeff McAdams, (C) 2002 Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: Forked again by Xelerance (www.xelerance.com) (C) 2006-2016 Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: Listening on IP address 0.0.0.0, port 1701 Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: Connecting to host , port 1701 Oct 01 14:22:35 NetworkManager[3301]: [1633069355.6161] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",0]: VPN plugin: state changed: starting (3) Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: Connection established to , 1701. Local: 5199, Remote: 10148 (ref=0/0). Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: Calling on tunnel 5199 Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: Call established with , Local: 63394, Remote: 20464, Serial: 1 (ref=0/0) Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: start_pppd: I'm running: Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: "/usr/sbin/pppd" Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: "plugin" Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: "pppol2tp.so" Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: "pppol2tp" Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: "7" Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: "passive" Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: "nodetach" Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: ":" Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: "file" Oct 01 14:22:35 NetworkManager[6555]: xl2tpd[6555]: "/var/run/nm-l2tp-c9bc3ec7-4541-4eba-93e7-f209455c12d8/ppp-options" Oct 01 14:22:35 pppd[6556]: Plugin pppol2tp.so loaded. Oct 01 14:22:35 pppd[6556]: Plugin /usr/lib/pppd/2.4.9/nm-l2tp-pppd-plugin.so loaded. Oct 01 14:22:35 pppd[6556]: pppd 2.4.9 started by root, uid 0 Oct 01 14:22:35 pppd[6556]: Using interface ppp0 Oct 01 14:22:35 pppd[6556]: Connect: ppp0 <--> Oct 01 14:22:35 pppd[6556]: Overriding mtu 1500 to 1400 Oct 01 14:22:35 pppd[6556]: Overriding mru 1500 to mtu value 1400 Oct 01 14:22:35 NetworkManager[3301]: [1633069355.6347] manager: (ppp0): new Ppp device (/org/freedesktop/NetworkManager/Devices/10) Oct 01 14:22:36 NetworkManager[3301]: [1633069356.6148] audit: op="statistics" interface="enp4s0f3u1u2" ifindex=4 args="0" pid=1293 uid=1000 result="success" Oct 01 14:22:36 NetworkManager[3301]: [1633069356.6201] audit: op="statistics" interface="wlp3s0" ifindex=3 args="0" pid=1293 uid=1000 result="success" Oct 01 14:22:38 pppd[6556]: CHAP authentication succeeded: Access granted Oct 01 14:22:38 pppd[6556]: CHAP authentication succeeded Oct 01 14:22:38 pppd[6556]: Cannot determine ethernet address for proxy ARP Oct 01 14:22:38 pppd[6556]: local IP address 192.168.42.24 Oct 01 14:22:38 pppd[6556]: remote IP address 192.168.42.1 Oct 01 14:22:38 pppd[6556]: primary DNS address 8.8.8.8 Oct 01 14:22:38 pppd[6556]: secondary DNS address 8.8.4.4 Oct 01 14:22:38 charon[6522]: 06[KNL] 192.168.42.24 appeared on ppp0 Oct 01 14:22:38 charon[6522]: 11[KNL] 192.168.42.24 disappeared from ppp0 Oct 01 14:22:38 charon[6522]: 01[KNL] 192.168.42.24 appeared on ppp0 Oct 01 14:22:38 charon[6522]: 07[KNL] interface ppp0 activated Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6497] device (ppp0): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external') Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6505] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",0]: VPN connection: (IP4 Config Get) reply received from old-style plugin Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6509] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",11:(ppp0)]: Data: VPN Gateway: Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6509] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",11:(ppp0)]: Data: Tunnel Device: "ppp0" Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6509] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",11:(ppp0)]: Data: IPv4 configuration: Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6510] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",11:(ppp0)]: Data: Internal Address: 192.168.42.24 Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6510] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",11:(ppp0)]: Data: Internal Prefix: 32 Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6510] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",11:(ppp0)]: Data: Internal Point-to-Point Address: 192.168.42.1 Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6510] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",11:(ppp0)]: Data: Static Route: 0.0.0.0/0 Next Hop: 0.0.0.0 Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6510] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",11:(ppp0)]: Data: Static Route: 192.168.42.1/32 Next Hop: 0.0.0.0 Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6510] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",11:(ppp0)]: Data: Internal DNS: 8.8.8.8 Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6511] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",11:(ppp0)]: Data: Internal DNS: 8.8.4.4 Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6511] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",11:(ppp0)]: Data: DNS Domain: '(none)' Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6511] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",11:(ppp0)]: Data: No IPv6 configuration Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6511] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",11:(ppp0)]: VPN plugin: state changed: started (4) Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6520] vpn-connection[0x5561aaad2300,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",11:(ppp0)]: VPN connection: (IP Config Get) complete Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6525] device (ppp0): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'external') Oct 01 14:22:38 NetworkManager[3301]: [1633069358.6620] policy: set 'new' (ppp0) as default for IPv4 routing and DNS Oct 01 14:22:38 charon[6522]: 15[NET] using forecast interface wlp3s0 Oct 01 14:22:38 charon[6522]: 15[CFG] joining forecast multicast groups: 224.0.0.1,224.0.0.22,224.0.0.251,224.0.0.252,239.255.255.250 Oct 01 14:22:38 charon[6522]: 13[IKE] installed bypass policy for 192.168.0.1/32 Oct 01 14:22:38 charon[6522]: 13[IKE] installed bypass policy for 192.168.42.1/32 Oct 01 14:22:59 charon[6522]: 07[IKE] sending keep alive to [4500] Oct 01 14:23:05 charon[6522]: 11[NET] received packet: from [4500] to 192.168.0.112[4500] (92 bytes) Oct 01 14:23:05 charon[6522]: 11[ENC] parsed INFORMATIONAL_V1 request 2398335098 [ HASH N(DPD) ] Oct 01 14:23:05 charon[6522]: 11[ENC] generating INFORMATIONAL_V1 request 1910383977 [ HASH N(DPD_ACK) ] Oct 01 14:23:05 charon[6522]: 11[NET] sending packet: from 192.168.0.112[4500] to [4500] (92 bytes) Oct 01 14:23:25 charon[6522]: 11[IKE] sending keep alive to [4500] Oct 01 14:23:35 charon[6522]: 12[NET] received packet: from [4500] to 192.168.0.112[4500] (92 bytes) Oct 01 14:23:35 charon[6522]: 12[ENC] parsed INFORMATIONAL_V1 request 3986403466 [ HASH N(DPD) ] Oct 01 14:23:35 charon[6522]: 12[ENC] generating INFORMATIONAL_V1 request 1124458824 [ HASH N(DPD_ACK) ] Oct 01 14:23:35 charon[6522]: 12[NET] sending packet: from 192.168.0.112[4500] to [4500] (92 bytes)


- An unsuccessful connection looks like this (when the windows server is connected):
- - VPN Server: `sudo tail -f /var/log/auth.log` (I have included the logs showing a successful connection by the windows server)

Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[52] #249: responding to Main Mode from unknown peer :500 Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[52] #249: Oakley Transform [AES_CBC (256), HMAC_SHA1, DH20] refused Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[52] #249: Oakley Transform [AES_CBC (128), HMAC_SHA1, DH19] refused Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[52] #249: STATE_MAIN_R1: sent MR1, expecting MI2 Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[52] #249: STATE_MAIN_R2: sent MR2, expecting MI3 Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[52] #249: Peer ID is ID_IPV4_ADDR: '192.168.0.142' Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[52] #249: switched from "l2tp-psk"[52] to "l2tp-psk" Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[58] #249: Peer ID is ID_IPV4_ADDR: '192.168.0.142' Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[58] #249: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=PRESHARED_KEY cipher=AES_CBC_256 integ=HMAC_SHA1 group=MODP2048} Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[58] #249: Configured DPD (RFC 3706) support not enabled because remote peer did not advertise DPD support Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[58] #249: the peer proposed: /32:17/1701 -> 192.168.0.142/32:17/0 Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[58] #249: NAT-Traversal: received 2 NAT-OA. Using first; ignoring others Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[58] #250: responding to Quick Mode proposal {msgid:00000001} Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[58] #250: us: 192.168.100.2[]:17/1701 Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[58] #250: them: [192.168.0.142]:17/1701 Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[58] #250: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2 transport mode {ESP/NAT=>0x4974127a <0xd8a6a58c xfrm=AES_CBC_256-HMAC_SHA1_96 NATOA=192.168.0.142 NATD=:12661 DPD=unsupported} Oct 1 06:32:20 hq-vpn pluto[443976]: "l2tp-psk"[58] #250: STATE_QUICK_R2: IPsec SA established transport mode {ESP/NAT=>0x4974127a <0xd8a6a58c xfrm=AES_CBC_256-HMAC_SHA1_96 NATOA=192.168.0.142 NATD=:12661 DPD=unsupported} Oct 1 06:33:09 hq-vpn pluto[443976]: "l2tp-psk"[58] #251: responding to Main Mode from unknown peer :500 Oct 1 06:33:09 hq-vpn pluto[443976]: "l2tp-psk"[58] #251: STATE_MAIN_R1: sent MR1, expecting MI2 Oct 1 06:33:09 hq-vpn pluto[443976]: "l2tp-psk"[58] #251: STATE_MAIN_R2: sent MR2, expecting MI3 Oct 1 06:33:09 hq-vpn pluto[443976]: "l2tp-psk"[58] #251: Peer ID is ID_IPV4_ADDR: '192.168.0.112' Oct 1 06:33:09 hq-vpn pluto[443976]: "l2tp-psk"[58] #251: switched from "l2tp-psk"[58] to "l2tp-psk" Oct 1 06:33:09 hq-vpn pluto[443976]: "l2tp-psk"[59] #251: Peer ID is ID_IPV4_ADDR: '192.168.0.112' Oct 1 06:33:09 hq-vpn pluto[443976]: "l2tp-psk"[59] #251: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=PRESHARED_KEY cipher=AES_CBC_128 integ=HMAC_SHA1 group=MODP2048} Oct 1 06:33:09 hq-vpn pluto[443976]: "l2tp-psk"[59] #251: the peer proposed: /32:17/1701 -> 192.168.0.112/32:17/0 Oct 1 06:33:09 hq-vpn pluto[443976]: "l2tp-psk"[59] #251: NAT-Traversal: received 2 NAT-OA. Using first; ignoring others Oct 1 06:33:09 hq-vpn pluto[443976]: "l2tp-psk"[59] #252: responding to Quick Mode proposal {msgid:ef187325} Oct 1 06:33:09 hq-vpn pluto[443976]: "l2tp-psk"[59] #252: us: 192.168.100.2[]:17/1701 Oct 1 06:33:09 hq-vpn pluto[443976]: "l2tp-psk"[59] #252: them: [192.168.0.112]:17/1701 Oct 1 06:33:09 hq-vpn pluto[443976]: "l2tp-psk"[59] #252: cannot install eroute -- it is in use for "l2tp-psk"[58] #250 Oct 1 06:33:11 hq-vpn sshd[460374]: Unable to negotiate with 107.189.12.48 port 54450: no matching key exchange method found. Their offer: diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1 [preauth] Oct 1 06:33:13 hq-vpn pluto[443976]: "l2tp-psk"[59] #252: byte at offset 1 (29) of 'ISAKMP Hash Payload'.'reserved' is 0x02 but should have been zero (ignored) Oct 1 06:33:13 hq-vpn pluto[443976]: "l2tp-psk"[59] #252: 55421-byte length of ISAKMP Hash Payload is larger than can fit Oct 1 06:33:13 hq-vpn pluto[443976]: "l2tp-psk"[59] #252: malformed payload in packet Oct 1 06:33:19 hq-vpn pluto[443976]: "l2tp-psk"[59] #251: received Delete SA payload: self-deleting ISAKMP State #251 Oct 1 06:33:19 hq-vpn pluto[443976]: "l2tp-psk"[59] #251: deleting state (STATE_MAIN_R3) aged 10.006s and sending notification Oct 1 06:33:19 hq-vpn pluto[443976]: "l2tp-psk"[59] #251: expire pending child #252 STATE_QUICK_R0 of connection "l2tp-psk"[59] - the parent is going away Oct 1 06:33:19 hq-vpn pluto[443976]: "l2tp-psk"[59] #252: deleting state (STATE_QUICK_R0) aged 9.983s and NOT sending notification Oct 1 06:33:19 hq-vpn pluto[443976]: "l2tp-psk"[59] #252: ERROR: netlink response for Del SA esp.c4d4285e@ included errno 3: No such process Oct 1 06:33:19 hq-vpn pluto[443976]: #252: deleting connection "l2tp-psk"[59] instance with peer {isakmp=#0/ipsec=#0}

- - Linux Client: `journalctl --no-hostname _SYSTEMD_UNIT=NetworkManager.service + SYSLOG_IDENTIFIER=pppd -xf`

Oct 01 14:33:00 NetworkManager[3301]: [1633069980.4792] audit: op="statistics" interface="enp4s0f3u1u2" ifindex=4 args="2000" pid=1293 uid=1000 result="success" Oct 01 14:33:00 NetworkManager[3301]: [1633069980.4948] audit: op="statistics" interface="wlp3s0" ifindex=3 args="2000" pid=1293 uid=1000 result="success" Oct 01 14:33:06 NetworkManager[3301]: [1633069986.7356] audit: op="connection-activate" uuid="c9bc3ec7-4541-4eba-93e7-f209455c12d8" name="new" pid=1293 uid=1000 result="success" Oct 01 14:33:06 NetworkManager[3301]: [1633069986.7410] vpn-connection[0x5561aaad2510,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",0]: Started the VPN service, PID 6828 Oct 01 14:33:06 NetworkManager[3301]: [1633069986.7518] vpn-connection[0x5561aaad2510,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",0]: Saw the service appear; activating connection Oct 01 14:33:06 NetworkManager[3301]: [1633069986.7641] vpn-connection[0x5561aaad2510,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",0]: VPN connection: (ConnectInteractive) reply received Oct 01 14:33:06 nm-l2tp-service[6828]: Check port 1701 Oct 01 14:33:06 NetworkManager[6841]: Stopping strongSwan IPsec failed: starter is not running Oct 01 14:33:07 NetworkManager[3301]: [1633069987.8862] audit: op="statistics" interface="enp4s0f3u1u2" ifindex=4 args="0" pid=1293 uid=1000 result="success" Oct 01 14:33:07 NetworkManager[3301]: [1633069987.8906] audit: op="statistics" interface="wlp3s0" ifindex=3 args="0" pid=1293 uid=1000 result="success" Oct 01 14:33:08 NetworkManager[6838]: Starting strongSwan 5.9.3 IPsec [starter]... Oct 01 14:33:08 NetworkManager[6838]: Loading config setup Oct 01 14:33:08 NetworkManager[6838]: Loading conn 'c9bc3ec7-4541-4eba-93e7-f209455c12d8' Oct 01 14:33:08 ipsec_starter[6838]: Starting strongSwan 5.9.3 IPsec [starter]... Oct 01 14:33:08 ipsec_starter[6838]: Loading config setup Oct 01 14:33:08 ipsec_starter[6838]: Loading conn 'c9bc3ec7-4541-4eba-93e7-f209455c12d8' Oct 01 14:33:08 ipsec_starter[6849]: Attempting to start charon... Oct 01 14:33:08 charon[6850]: 00[DMN] Starting IKE charon daemon (strongSwan 5.9.3, Linux 5.10.68-1-MANJARO, x86_64) Oct 01 14:33:08 charon[6850]: 00[CFG] PKCS11 module '' lacks library path Oct 01 14:33:08 charon[6850]: 00[LIB] plugin 'mysql' failed to load: libmariadb.so.3: cannot open shared object file: No such file or directory Oct 01 14:33:08 charon[6850]: 00[CFG] attr-sql plugin: database URI not set Oct 01 14:33:08 charon[6850]: 00[NET] using forecast interface wlp3s0 Oct 01 14:33:08 charon[6850]: 00[CFG] joining forecast multicast groups: 224.0.0.1,224.0.0.22,224.0.0.251,224.0.0.252,239.255.255.250 Oct 01 14:33:08 charon[6850]: 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts' Oct 01 14:33:08 charon[6850]: 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts' Oct 01 14:33:08 charon[6850]: 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts' Oct 01 14:33:08 charon[6850]: 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts' Oct 01 14:33:08 charon[6850]: 00[CFG] loading crls from '/etc/ipsec.d/crls' Oct 01 14:33:08 charon[6850]: 00[CFG] loading secrets from '/etc/ipsec.secrets' Oct 01 14:33:08 charon[6850]: 00[CFG] loading secrets from '/etc/ipsec.d/ipsec.nm-l2tp.secrets' Oct 01 14:33:08 charon[6850]: 00[CFG] loaded IKE secret for %any Oct 01 14:33:08 charon[6850]: 00[CFG] sql plugin: database URI not set Oct 01 14:33:08 charon[6850]: 00[CFG] opening triplet file /etc/ipsec.d/triplets.dat failed: No such file or directory Oct 01 14:33:08 charon[6850]: 00[CFG] loaded 0 RADIUS server configurations Oct 01 14:33:08 charon[6850]: 00[CFG] HA config misses local/remote address Oct 01 14:33:08 charon[6850]: 00[CFG] no script for ext-auth script defined, disabled Oct 01 14:33:08 charon[6850]: 00[LIB] loaded plugins: charon ldap pkcs11 aesni aes des rc2 sha2 sha3 sha1 md5 mgf1 random nonce x509 revocation constraints pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey sshkey pem openssl fips-prf gmp curve25519 agent chapoly xcbc cmac hmac ntru drbg newhope bliss curl sqlite attr kernel-netlink resolve socket-default bypass-lan connmark forecast farp stroke vici updown eap-identity eap-sim eap-aka eap-aka-3gpp2 eap-simaka-pseudonym eap-simaka-reauth eap-md5 eap-gtc eap-mschapv2 eap-dynamic eap-radius eap-tls eap-ttls eap-peap xauth-generic xauth-eap xauth-pam xauth-noauth dhcp radattr unity counters Oct 01 14:33:08 charon[6850]: 00[LIB] dropped capabilities, running as uid 0, gid 0 Oct 01 14:33:08 charon[6850]: 00[JOB] spawning 16 worker threads Oct 01 14:33:08 charon[6850]: 05[IKE] installed bypass policy for 192.168.0.0/24 Oct 01 14:33:08 charon[6850]: 05[IKE] installed bypass policy for ::1/128 Oct 01 14:33:08 charon[6850]: 05[IKE] installed bypass policy for fe80::/64 Oct 01 14:33:08 charon[6850]: 05[IKE] interface change for bypass policy for 192.168.0.0/24 (from enp4s0f3u1u2 to wlp3s0) Oct 01 14:33:08 charon[6850]: 05[IKE] interface change for bypass policy for fe80::/64 (from enp4s0f3u1u2 to wlp3s0) Oct 01 14:33:08 ipsec_starter[6849]: charon (6850) started after 20 ms Oct 01 14:33:08 charon[6850]: 13[CFG] received stroke: add connection 'c9bc3ec7-4541-4eba-93e7-f209455c12d8' Oct 01 14:33:08 charon[6850]: 13[CFG] added configuration 'c9bc3ec7-4541-4eba-93e7-f209455c12d8' Oct 01 14:33:09 charon[6850]: 13[CFG] rereading secrets Oct 01 14:33:09 charon[6850]: 13[CFG] loading secrets from '/etc/ipsec.secrets' Oct 01 14:33:09 charon[6850]: 13[CFG] loading secrets from '/etc/ipsec.d/ipsec.nm-l2tp.secrets' Oct 01 14:33:09 charon[6850]: 13[CFG] loaded IKE secret for %any Oct 01 14:33:09 charon[6850]: 01[CFG] received stroke: initiate 'c9bc3ec7-4541-4eba-93e7-f209455c12d8' Oct 01 14:33:09 charon[6850]: 06[IKE] initiating Main Mode IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] to Oct 01 14:33:09 charon[6850]: 06[IKE] initiating Main Mode IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] to Oct 01 14:33:09 charon[6850]: 06[ENC] generating ID_PROT request 0 [ SA V V V V V ] Oct 01 14:33:09 charon[6850]: 06[NET] sending packet: from 192.168.0.112[500] to [500] (240 bytes) Oct 01 14:33:09 charon[6850]: 07[NET] received packet: from [500] to 192.168.0.112[500] (144 bytes) Oct 01 14:33:09 charon[6850]: 07[ENC] parsed ID_PROT response 0 [ SA V V V ] Oct 01 14:33:09 charon[6850]: 07[IKE] received FRAGMENTATION vendor ID Oct 01 14:33:09 charon[6850]: 07[IKE] received DPD vendor ID Oct 01 14:33:09 charon[6850]: 07[IKE] received NAT-T (RFC 3947) vendor ID Oct 01 14:33:09 charon[6850]: 07[CFG] selected proposal: IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048 Oct 01 14:33:09 charon[6850]: 07[ENC] generating ID_PROT request 0 [ KE No NAT-D NAT-D ] Oct 01 14:33:09 charon[6850]: 07[NET] sending packet: from 192.168.0.112[500] to [500] (372 bytes) Oct 01 14:33:09 charon[6850]: 08[NET] received packet: from [500] to 192.168.0.112[500] (372 bytes) Oct 01 14:33:09 charon[6850]: 08[ENC] parsed ID_PROT response 0 [ KE No NAT-D NAT-D ] Oct 01 14:33:09 charon[6850]: 08[IKE] local host is behind NAT, sending keep alives Oct 01 14:33:09 charon[6850]: 08[IKE] remote host is behind NAT Oct 01 14:33:09 charon[6850]: 08[ENC] generating ID_PROT request 0 [ ID HASH ] Oct 01 14:33:09 charon[6850]: 08[NET] sending packet: from 192.168.0.112[4500] to [4500] (76 bytes) Oct 01 14:33:09 charon[6850]: 09[NET] received packet: from [4500] to 192.168.0.112[4500] (76 bytes) Oct 01 14:33:09 charon[6850]: 09[ENC] parsed ID_PROT response 0 [ ID HASH ] Oct 01 14:33:09 charon[6850]: 09[IKE] IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] established between 192.168.0.112[192.168.0.112]...[] Oct 01 14:33:09 charon[6850]: 09[IKE] IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] established between 192.168.0.112[192.168.0.112]...[] Oct 01 14:33:09 charon[6850]: 09[IKE] scheduling reauthentication in 10212s Oct 01 14:33:09 charon[6850]: 09[IKE] maximum IKE_SA lifetime 10752s Oct 01 14:33:09 charon[6850]: 09[ENC] generating QUICK_MODE request 4011356965 [ HASH SA No ID ID NAT-OA NAT-OA ] Oct 01 14:33:09 charon[6850]: 09[NET] sending packet: from 192.168.0.112[4500] to [4500] (252 bytes) Oct 01 14:33:13 charon[6850]: 10[IKE] sending retransmit 1 of request message ID 4011356965, seq 4 Oct 01 14:33:13 charon[6850]: 10[NET] sending packet: from 192.168.0.112[4500] to [4500] (252 bytes) Oct 01 14:33:19 NetworkManager[6878]: Stopping strongSwan IPsec... Oct 01 14:33:19 charon[6850]: 00[DMN] SIGINT received, shutting down Oct 01 14:33:19 NetworkManager[6877]: initiating Main Mode IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] to Oct 01 14:33:19 NetworkManager[6877]: generating ID_PROT request 0 [ SA V V V V V ] Oct 01 14:33:19 NetworkManager[6877]: sending packet: from 192.168.0.112[500] to [500] (240 bytes) Oct 01 14:33:19 NetworkManager[6877]: received packet: from [500] to 192.168.0.112[500] (144 bytes) Oct 01 14:33:19 NetworkManager[6877]: parsed ID_PROT response 0 [ SA V V V ] Oct 01 14:33:19 NetworkManager[6877]: received FRAGMENTATION vendor ID Oct 01 14:33:19 NetworkManager[6877]: received DPD vendor ID Oct 01 14:33:19 NetworkManager[6877]: received NAT-T (RFC 3947) vendor ID Oct 01 14:33:19 NetworkManager[6877]: selected proposal: IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048 Oct 01 14:33:19 NetworkManager[6877]: generating ID_PROT request 0 [ KE No NAT-D NAT-D ] Oct 01 14:33:19 NetworkManager[6877]: sending packet: from 192.168.0.112[500] to [500] (372 bytes) Oct 01 14:33:19 NetworkManager[6877]: received packet: from [500] to 192.168.0.112[500] (372 bytes) Oct 01 14:33:19 NetworkManager[6877]: parsed ID_PROT response 0 [ KE No NAT-D NAT-D ] Oct 01 14:33:19 NetworkManager[6877]: local host is behind NAT, sending keep alives Oct 01 14:33:19 NetworkManager[6877]: remote host is behind NAT Oct 01 14:33:19 NetworkManager[6877]: generating ID_PROT request 0 [ ID HASH ] Oct 01 14:33:19 NetworkManager[6877]: sending packet: from 192.168.0.112[4500] to [4500] (76 bytes) Oct 01 14:33:19 NetworkManager[6877]: received packet: from [4500] to 192.168.0.112[4500] (76 bytes) Oct 01 14:33:19 NetworkManager[6877]: parsed ID_PROT response 0 [ ID HASH ] Oct 01 14:33:19 NetworkManager[6877]: IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] established between 192.168.0.112[192.168.0.112]...[] Oct 01 14:33:19 NetworkManager[6877]: scheduling reauthentication in 10212s Oct 01 14:33:19 NetworkManager[6877]: maximum IKE_SA lifetime 10752s Oct 01 14:33:19 NetworkManager[6877]: generating QUICK_MODE request 4011356965 [ HASH SA No ID ID NAT-OA NAT-OA ] Oct 01 14:33:19 NetworkManager[6877]: sending packet: from 192.168.0.112[4500] to [4500] (252 bytes) Oct 01 14:33:19 NetworkManager[6877]: sending retransmit 1 of request message ID 4011356965, seq 4 Oct 01 14:33:19 NetworkManager[6877]: sending packet: from 192.168.0.112[4500] to [4500] (252 bytes) Oct 01 14:33:19 NetworkManager[6877]: establishing connection 'c9bc3ec7-4541-4eba-93e7-f209455c12d8' failed Oct 01 14:33:19 charon[6850]: 00[IKE] deleting IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] between 192.168.0.112[192.168.0.112]...[] Oct 01 14:33:19 charon[6850]: 00[IKE] deleting IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] between 192.168.0.112[192.168.0.112]...[] Oct 01 14:33:19 charon[6850]: 00[IKE] sending DELETE for IKE_SA c9bc3ec7-4541-4eba-93e7-f209455c12d8[1] Oct 01 14:33:19 charon[6850]: 00[ENC] generating INFORMATIONAL_V1 request 3226531393 [ HASH D ] Oct 01 14:33:19 charon[6850]: 00[NET] sending packet: from 192.168.0.112[4500] to [4500] (92 bytes) Oct 01 14:33:19 charon[6850]: 00[IKE] uninstalling bypass policy for 192.168.0.0/24 Oct 01 14:33:19 charon[6850]: 00[IKE] uninstalling bypass policy for ::1/128 Oct 01 14:33:19 charon[6850]: 00[IKE] uninstalling bypass policy for fe80::/64 Oct 01 14:33:19 ipsec_starter[6849]: child 6850 (charon) has quit (exit code 0) Oct 01 14:33:19 ipsec_starter[6849]: Oct 01 14:33:19 ipsec_starter[6849]: charon stopped after 200 ms Oct 01 14:33:19 ipsec_starter[6849]: ipsec starter stopped Oct 01 14:33:19 nm-l2tp-service[6828]: g_dbus_method_invocation_take_error: assertion 'error != NULL' failed Oct 01 14:33:19 NetworkManager[3301]: [1633069999.9754] vpn-connection[0x5561aaad2510,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",0]: VPN service disappeared Oct 01 14:33:19 NetworkManager[3301]: [1633069999.9758] vpn-connection[0x5561aaad2510,c9bc3ec7-4541-4eba-93e7-f209455c12d8,"new",0]: VPN connection: failed to connect: 'Message recipient disconnected from message bus without replying'

dkosovic commented 3 years ago

From the README.md file, NetworkManager-l2tp starts its own instance of xl2tpd and if the system xl2tpd service is running, its own xl2tpd instance will not be able to use UDP port 1701, so will use an ephemeral port (i.e. random high port).

You can enable and start the system xl2tpd with :

sudo systemctl start xl2tpd.service
sudo systemctl enable xl2tpd.service

Coincidentally I'm working on a new release where you can click a check box to explicitly use an ephemeral port, it might be released this weekend.

dkosovic commented 3 years ago

Forgot to mention, changing rightprotoport=udp/l2tp to rightprotoport=udp/%any would not be correct for the client.

The issue on the NATed client end is with leftprotoport=udp/l2tp , fortunately NetworkManager-l2tp only uses leftprotoport=udp/l2tp if port 1701 is free (and starting the system xl2tpd as mentioned in the previous message no longer makes it free) :

https://github.com/nm-l2tp/NetworkManager-l2tp/blob/1.8.6/src/nm-l2tp-service.c#L905

akshatd commented 3 years ago

Thanks a lot for your help! I tried to start the process like you suggested, but it ended up using port 0 and someone else on the NAT is already using port 0 so the connection failed again. If the release with the option of an ephemeral port is imminent, ill gladly wait till the release to test it out.

dkosovic commented 3 years ago

Commit# https://github.com/nm-l2tp/NetworkManager-l2tp/commit/c61828af8e941fe8a878a31021085cb127e0bd49 has the commit for the ephemeral source port GUI checkbox.

I suspect the recent commit will not help you as the xl2tpd instance that it starts up is still using a bind to port 0 which causes the kernel to select an unused port from the ephemeral port range.

On the client side when system xl2tpd is not running, port 1701 as source port (and destination port) is used for the L2TP connection as can be confirmed with netstat :

$ sudo netstat -u -n
Proto Recv-Q Send-Q Local Address           Foreign Address         State      
udp        0      0 192.168.0.74:1701      120.103.71.66:1701      ESTABLISHED

When system xl2tpd is running, an ephemeral port (random) source port is used :

$ sudo netstat -u -n
Proto Recv-Q Send-Q Local Address           Foreign Address         State      
udp        0      0 192.168.0.74:45575      120.103.71.66:1701      ESTABLISHED

The current issue you are having is with the IPsec server not allowing leftprotoport=udp/%any (which is the same as leftprotoport=udp/0).

Usually left is the client and right is the server, but some docs have swapped them around. For example, the following libreswan page :

https://libreswan.org/man/ipsec.conf.5.html

Some clients, notably older Windows XP and some macOS clients, use a random high port as source port. In those cases rightprotoport=17/%any can be used to allow all UDP traffic on the connection.

is incorrect, because like with netstat in the above examples, the source port is on the left and the destination port on the right. I believe the IPsec server probably should be using leftprotoport=udp/%any and righprotoport=udp/l2tp (instead of leftprotoport=udp/l2tp and righprotoport=udp/%any).

Are you able to change the IPsec server settings to leftprotoport=udp/%any and righprotoport=udp/l2tp ?

dkosovic commented 3 years ago

I've just tested with iOS and macOS, both use an ephemeral port for the L2TP connection. The following is from the macOS command-line :

% sudo netstat -n            
Active Internet connections
Proto Recv-Q Send-Q  Local Address          Foreign Address        (state)    
udp4       0      0  10.184.42.84.52589     120.103.71.66.1701

So just like with the Linux case above, leftprotoport=udp/%any and righprotoport=udp/l2tp would be required on the server side to support iOS and macOS.

dkosovic commented 3 years ago

NetworkManager-l2tp version 1.20.0 with the ephemeral port checkbox has been released. But as mentioned it is the leftprotoport and righprotoport configuration on the server side that needs to be fixed.

dkosovic commented 2 years ago

I assume it is now working for you based on your silence. I will close this issue, if you ever need it re-opened reply and I will re-open.

nm-l2tp / NetworkManager-l2tp