Unable to connect - pppd not getting spawned?

bblough commented 1 year ago

Hi,

If there's a more proper place to ask for help with this, please let me know.

I'm trying to connect to an L2TP VPN using nm-l2tp, and I'm unable to establish a connection. I have connected successfully with other devices, so I'm under the impression that the server config is fine. The system in question is running Debian 11 (Bullseye), and kernel and package versions are listed below.

The logs below reflect an attempt using strongswan, though at one point I also tried libreswan (4.3-1+deb11u1) with no noticeable improvement.

As far as I can tell, it looks like the ipsec tunnel is getting created successfully, but I don't see any entries for pppd in syslog/journalctl. I've also looked for pppd in the process list during connection attempts, but didn't see it. So I'm thinking maybe pppd isn't getting started for some reason, but I haven't been able to figure out why.

Any help would be appreciated.

kernel/package info

root@narvi:~# uname -a
Linux narvi 5.10.0-9-amd64 #1 SMP Debian 5.10.70-1 (2021-09-30) x86_64 GNU/Linux

root@narvi:~# dpkg -l |grep -E -i "(l2tp|ppp|swan)" 
ii  libcharon-extauth-plugins             5.9.1-1+deb11u3                        amd64        strongSwan charon library (extended authentication plugins)
ii  libcharon-extra-plugins               5.9.1-1+deb11u3                        amd64        strongSwan charon library (extra plugins)
ii  libstrongswan                         5.9.1-1+deb11u3                        amd64        strongSwan utility and crypto library
ii  libstrongswan-standard-plugins        5.9.1-1+deb11u3                        amd64        strongSwan utility and crypto library (standard plugins)
ii  network-manager-l2tp                  1.2.18-1+b2                            amd64        network management framework (L2TP plugin core)
ii  network-manager-l2tp-gnome            1.2.18-1+b2                            amd64        network management framework (L2TP plugin GNOME GUI)
ii  ppp                                   2.4.9-1+1                              amd64        Point-to-Point Protocol (PPP) - daemon
ii  strongswan                            5.9.1-1+deb11u3                        all          IPsec VPN solution metapackage
ii  strongswan-charon                     5.9.1-1+deb11u3                        amd64        strongSwan Internet Key Exchange daemon
ii  strongswan-libcharon                  5.9.1-1+deb11u3                        amd64        strongSwan charon library
ii  strongswan-starter                    5.9.1-1+deb11u3                        amd64        strongSwan daemon starter and configuration file parser
ii  xl2tpd                                1.3.12-1.1                             amd64        layer 2 tunneling protocol implementation

modules

root@narvi:~# lsmod |grep l2tp
l2tp_ppp               24576  0
l2tp_netlink           24576  1 l2tp_ppp
l2tp_core              61440  2 l2tp_ppp,l2tp_netlink
ip6_udp_tunnel         16384  1 l2tp_core
udp_tunnel             20480  1 l2tp_core
pppox                  16384  1 l2tp_ppp
ppp_generic            49152  3 pppox,l2tp_ppp,ppp_async

nm-l2tp-service --debug

nm-l2tp[944179] <debug> nm-l2tp-service (version 1.2.18) starting...
nm-l2tp[944179] <debug>  uses default --bus-name "org.freedesktop.NetworkManager.l2tp"
nm-l2tp[944179] <info>  ipsec enable flag: yes
** Message: 10:48:54.911: Check port 1701
ipv6
    address-data : []
    dns : []
    dns-search : []
    method : 'auto'
    route-data : []

proxy

connection
    autoconnect : false
    id : 'VPN to Home'
    permissions : []
    type : 'vpn'
    uuid : 'c6205c9a-8eae-4f51-b873-24517e34a7de'

ipv4
    address-data : []
    dns : []
    dns-search : []
    method : 'auto'
    route-data : []

vpn
    data : {'gateway': '*********************', 'ipsec-enabled': 'yes', 'ipsec-psk': '**********************************************', 'lcp-echo-failure': '5', 'lcp-echo-interval': '30', 'mru': '1400', 'mtu': '1400', 'password-flags': '2', 'refuse-chap': 'yes', 'refuse-eap': 'yes', 'refuse-pap': 'yes', 'user': '*******'}
    secrets : {'password': '********************'}
    service-type : 'org.freedesktop.NetworkManager.l2tp'
    user-name : 'root'

nm-l2tp[944179] <info>  starting ipsec
Stopping strongSwan IPsec failed: starter is not running
Starting strongSwan 5.9.1 IPsec [starter]...
Loading config setup
Loading conn 'c6205c9a-8eae-4f51-b873-24517e34a7de'
nm-l2tp[944179] <info>  Spawned ipsec up script with PID 944238.
initiating Main Mode IKE_SA c6205c9a-8eae-4f51-b873-24517e34a7de[1] to ***.***.***.***
generating ID_PROT request 0 [ SA V V V V V ]
sending packet: from 192.168.0.167[500] to ***.***.***.***[500] (532 bytes)
received packet: from ***.***.***.***[500] to 192.168.0.167[500] (136 bytes)
parsed ID_PROT response 0 [ SA V V V ]
received XAuth vendor ID
received DPD vendor ID
received NAT-T (RFC 3947) vendor ID
selected proposal: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048
generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
sending packet: from 192.168.0.167[500] to ***.***.***.***[500] (372 bytes)
received packet: from ***.***.***.***[500] to 192.168.0.167[500] (372 bytes)
parsed ID_PROT response 0 [ KE No NAT-D NAT-D ]
local host is behind NAT, sending keep alives
generating ID_PROT request 0 [ ID HASH ]
sending packet: from 192.168.0.167[4500] to ***.***.***.***[4500] (76 bytes)
received packet: from ***.***.***.***[4500] to 192.168.0.167[4500] (76 bytes)
parsed ID_PROT response 0 [ ID HASH ]
IKE_SA c6205c9a-8eae-4f51-b873-24517e34a7de[1] established between 192.168.0.167[192.168.0.167]...***.***.***.***[***.***.***.***]
scheduling reauthentication in 10173s
maximum IKE_SA lifetime 10713s
generating QUICK_MODE request 4241729600 [ HASH SA No ID ID NAT-OA NAT-OA ]
sending packet: from 192.168.0.167[4500] to ***.***.***.***[4500] (252 bytes)
received packet: from ***.***.***.***[4500] to 192.168.0.167[4500] (204 bytes)
parsed QUICK_MODE response 4241729600 [ HASH SA No ID ID NAT-OA NAT-OA ]
selected proposal: ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ
CHILD_SA c6205c9a-8eae-4f51-b873-24517e34a7de{1} established with SPIs cc9cf886_i c3572935_o and TS 192.168.0.167/32[udp/l2f] === ***.***.***.***/32[udp/l2f]
generating QUICK_MODE request 4241729600 [ HASH ]
sending packet: from 192.168.0.167[4500] to ***.***.***.***[4500] (60 bytes)
connection 'c6205c9a-8eae-4f51-b873-24517e34a7de' established successfully
nm-l2tp[944179] <info>  strongSwan IPsec tunnel is up.
** Message: 10:48:58.943: xl2tpd started with pid 944248
xl2tpd[944248]: Not looking for kernel SAref support.
xl2tpd[944248]: Using l2tp kernel support.
xl2tpd[944248]: xl2tpd version xl2tpd-1.3.12 started on narvi PID:944248
xl2tpd[944248]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc.
xl2tpd[944248]: Forked by Scott Balmos and David Stipp, (C) 2001
xl2tpd[944248]: Inherited by Jeff McAdams, (C) 2002
xl2tpd[944248]: Forked again by Xelerance (www.xelerance.com) (C) 2006-2016
xl2tpd[944248]: Listening on IP address 0.0.0.0, port 1701
xl2tpd[944248]: get_call: allocating new tunnel for host ***.***.***.***, port 1701.
xl2tpd[944248]: Connecting to host ***.***.***.***, port 1701
xl2tpd[944248]: control_finish: message type is (null)(0).  Tunnel is 0, call is 0.
xl2tpd[944248]: control_finish: sending SCCRQ
nm-l2tp[944179] <warn>  Looks like pppd didn't initialize our dbus module
nm-l2tp[944179] <info>  Terminated xl2tpd daemon with PID 944248.
xl2tpd[944248]: death_handler: Fatal signal 15 received
xl2tpd[944248]: Connection 0 closed to ***.***.***.***, port 1701 (Server closing)
Stopping strongSwan IPsec...
** Message: 10:49:13.061: ipsec shut down
nm-l2tp[944179] <warn>  xl2tpd exited with error code 1
Stopping strongSwan IPsec failed: starter is not running
** Message: 10:49:13.070: ipsec shut down

syslog

Jan  3 10:48:52 narvi NetworkManager[943611]: <info>  [1672771732.0990] agent-manager: agent[6ef6467b51e58fef,:1.34123/nmcli-connect/0]: agent registered
Jan  3 10:48:52 narvi NetworkManager[943611]: <info>  [1672771732.1008] audit: op="connection-activate" uuid="c6205c9a-8eae-4f51-b873-24517e34a7de" name="VPN to Home" pid=944183 uid=0 result="success"
Jan  3 10:48:52 narvi NetworkManager[943611]: <info>  [1672771732.1054] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: Saw the service appear; activating connection
Jan  3 10:48:54 narvi NetworkManager[943611]: <info>  [1672771734.8481] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: VPN connection: (ConnectInteractive) reply received
Jan  3 10:48:56 narvi charon: 00[DMN] Starting IKE charon daemon (strongSwan 5.9.1, Linux 5.10.0-9-amd64, x86_64)
Jan  3 10:48:56 narvi charon: 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts'
Jan  3 10:48:56 narvi charon: 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts'
Jan  3 10:48:56 narvi charon: 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts'
Jan  3 10:48:56 narvi charon: 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts'
Jan  3 10:48:56 narvi charon: 00[CFG] loading crls from '/etc/ipsec.d/crls'
Jan  3 10:48:56 narvi charon: 00[CFG] loading secrets from '/etc/ipsec.secrets'
Jan  3 10:48:56 narvi charon: 00[CFG] loading secrets from '/etc/ipsec.d/ipsec.nm-l2tp.secrets'
Jan  3 10:48:56 narvi charon: 00[CFG]   loaded IKE secret for %any
Jan  3 10:48:56 narvi charon: 00[CFG] loaded 0 RADIUS server configurations
Jan  3 10:48:56 narvi charon: 00[CFG] HA config misses local/remote address
Jan  3 10:48:56 narvi charon: 00[LIB] loaded plugins: charon aesni aes rc2 sha2 sha1 md5 mgf1 random nonce x509 revocation constraints pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey sshkey pem openssl fips-prf gmp agent xcbc hmac gcm drbg attr kernel-netlink resolve socket-default connmark farp stroke updown eap-identity eap-aka eap-md5 eap-gtc eap-mschapv2 eap-radius eap-tls eap-ttls eap-tnc xauth-generic xauth-eap xauth-pam tnc-tnccs dhcp lookip error-notify certexpire led addrblock unity counters
Jan  3 10:48:56 narvi charon: 00[LIB] dropped capabilities, running as uid 0, gid 0
Jan  3 10:48:56 narvi charon: 00[JOB] spawning 16 worker threads
Jan  3 10:48:56 narvi charon: 12[CFG] received stroke: add connection 'c6205c9a-8eae-4f51-b873-24517e34a7de'
Jan  3 10:48:56 narvi charon: 12[CFG] conn c6205c9a-8eae-4f51-b873-24517e34a7de
Jan  3 10:48:56 narvi charon: 12[CFG]   left=%any
Jan  3 10:48:56 narvi charon: 12[CFG]   leftauth=psk
Jan  3 10:48:56 narvi charon: 12[CFG]   right=***.***.***.***
Jan  3 10:48:56 narvi charon: 12[CFG]   rightauth=psk
Jan  3 10:48:56 narvi charon: 12[CFG]   rightid=%any
Jan  3 10:48:56 narvi charon: 12[CFG]   ike=aes256-sha2_256-modp2048,aes256-sha2_256-modp1536,aes256-sha2_256-modp1024,aes256-sha1-modp2048,aes256-sha1-modp1536,aes256-sha1-modp1024,aes256-sha1-ecp384,aes128-sha1-modp1024,aes128-sha1-ecp256,3des-sha1-modp2048,3des-sha1-modp1024!
Jan  3 10:48:56 narvi charon: 12[CFG]   esp=aes256-sha1,aes128-sha1,3des-sha1!
Jan  3 10:48:56 narvi charon: 12[CFG]   dpddelay=30
Jan  3 10:48:56 narvi charon: 12[CFG]   dpdtimeout=150
Jan  3 10:48:56 narvi charon: 12[CFG]   sha256_96=no
Jan  3 10:48:56 narvi charon: 12[CFG]   mediation=no
Jan  3 10:48:56 narvi charon: 12[CFG]   keyexchange=ikev1
Jan  3 10:48:56 narvi charon: 12[CFG] added configuration 'c6205c9a-8eae-4f51-b873-24517e34a7de'
Jan  3 10:48:57 narvi charon: 04[CFG] rereading secrets
Jan  3 10:48:57 narvi charon: 04[CFG] loading secrets from '/etc/ipsec.secrets'
Jan  3 10:48:57 narvi charon: 04[CFG] loading secrets from '/etc/ipsec.d/ipsec.nm-l2tp.secrets'
Jan  3 10:48:57 narvi charon: 04[CFG]   loaded IKE secret for %any
Jan  3 10:48:57 narvi charon: 06[CFG] received stroke: initiate 'c6205c9a-8eae-4f51-b873-24517e34a7de'
Jan  3 10:48:57 narvi charon: 16[IKE] queueing ISAKMP_VENDOR task
Jan  3 10:48:57 narvi charon: 16[IKE] queueing ISAKMP_CERT_PRE task
Jan  3 10:48:57 narvi charon: 16[IKE] queueing MAIN_MODE task
Jan  3 10:48:57 narvi charon: 16[IKE] queueing ISAKMP_CERT_POST task
Jan  3 10:48:57 narvi charon: 16[IKE] queueing ISAKMP_NATD task
Jan  3 10:48:57 narvi charon: 16[IKE] queueing QUICK_MODE task
Jan  3 10:48:57 narvi charon: 16[IKE] activating new tasks
Jan  3 10:48:57 narvi charon: 16[IKE]   activating ISAKMP_VENDOR task
Jan  3 10:48:57 narvi charon: 16[IKE]   activating ISAKMP_CERT_PRE task
Jan  3 10:48:57 narvi charon: 16[IKE]   activating MAIN_MODE task
Jan  3 10:48:57 narvi charon: 16[IKE]   activating ISAKMP_CERT_POST task
Jan  3 10:48:57 narvi charon: 16[IKE]   activating ISAKMP_NATD task
Jan  3 10:48:57 narvi charon: 16[IKE] sending XAuth vendor ID
Jan  3 10:48:57 narvi charon: 16[IKE] sending DPD vendor ID
Jan  3 10:48:57 narvi charon: 16[IKE] sending FRAGMENTATION vendor ID
Jan  3 10:48:57 narvi charon: 16[IKE] sending NAT-T (RFC 3947) vendor ID
Jan  3 10:48:57 narvi charon: 16[IKE] sending draft-ietf-ipsec-nat-t-ike-02\n vendor ID
Jan  3 10:48:57 narvi charon: 16[IKE] initiating Main Mode IKE_SA c6205c9a-8eae-4f51-b873-24517e34a7de[1] to ***.***.***.***
Jan  3 10:48:57 narvi charon: 16[IKE] IKE_SA c6205c9a-8eae-4f51-b873-24517e34a7de[1] state change: CREATED => CONNECTING
Jan  3 10:48:57 narvi charon: 16[CFG] configured proposals: IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_2048, IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_1536, IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_1024, IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048, IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1536, IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024, IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/ECP_384, IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024, IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/ECP_256, IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048, IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
Jan  3 10:48:57 narvi charon: 16[ENC] generating ID_PROT request 0 [ SA V V V V V ]
Jan  3 10:48:57 narvi charon: 16[NET] sending packet: from 192.168.0.167[500] to ***.***.***.***[500] (532 bytes)
Jan  3 10:48:58 narvi charon: 07[NET] received packet: from ***.***.***.***[500] to 192.168.0.167[500] (136 bytes)
Jan  3 10:48:58 narvi charon: 07[ENC] parsed ID_PROT response 0 [ SA V V V ]
Jan  3 10:48:58 narvi charon: 07[IKE] received XAuth vendor ID
Jan  3 10:48:58 narvi charon: 07[IKE] received DPD vendor ID
Jan  3 10:48:58 narvi charon: 07[IKE] received NAT-T (RFC 3947) vendor ID
Jan  3 10:48:58 narvi charon: 07[CFG] selecting proposal:
Jan  3 10:48:58 narvi charon: 07[CFG]   no acceptable INTEGRITY_ALGORITHM found
Jan  3 10:48:58 narvi charon: 07[CFG] selecting proposal:
Jan  3 10:48:58 narvi charon: 07[CFG]   no acceptable INTEGRITY_ALGORITHM found
Jan  3 10:48:58 narvi charon: 07[CFG] selecting proposal:
Jan  3 10:48:58 narvi charon: 07[CFG]   no acceptable INTEGRITY_ALGORITHM found
Jan  3 10:48:58 narvi charon: 07[CFG] selecting proposal:
Jan  3 10:48:58 narvi charon: 07[CFG]   proposal matches
Jan  3 10:48:58 narvi charon: 07[CFG] received proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048
Jan  3 10:48:58 narvi charon: 07[CFG] configured proposals: IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_2048, IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_1536, IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_1024, IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048, IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1536, IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024, IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/ECP_384, IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024, IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/ECP_256, IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048, IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
Jan  3 10:48:58 narvi charon: 07[CFG] selected proposal: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048
Jan  3 10:48:58 narvi charon: 07[IKE] reinitiating already active tasks
Jan  3 10:48:58 narvi charon: 07[IKE]   ISAKMP_VENDOR task
Jan  3 10:48:58 narvi charon: 07[IKE]   MAIN_MODE task
Jan  3 10:48:58 narvi charon: 07[ENC] generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
Jan  3 10:48:58 narvi charon: 07[NET] sending packet: from 192.168.0.167[500] to ***.***.***.***[500] (372 bytes)
Jan  3 10:48:58 narvi charon: 08[NET] received packet: from ***.***.***.***[500] to 192.168.0.167[500] (372 bytes)
Jan  3 10:48:58 narvi charon: 08[ENC] parsed ID_PROT response 0 [ KE No NAT-D NAT-D ]
Jan  3 10:48:58 narvi charon: 08[IKE] local host is behind NAT, sending keep alives
Jan  3 10:48:58 narvi charon: 08[IKE] reinitiating already active tasks
Jan  3 10:48:58 narvi charon: 08[IKE]   ISAKMP_VENDOR task
Jan  3 10:48:58 narvi charon: 08[IKE]   MAIN_MODE task
Jan  3 10:48:58 narvi charon: 08[ENC] generating ID_PROT request 0 [ ID HASH ]
Jan  3 10:48:58 narvi charon: 08[NET] sending packet: from 192.168.0.167[4500] to ***.***.***.***[4500] (76 bytes)
Jan  3 10:48:58 narvi charon: 10[NET] received packet: from ***.***.***.***[4500] to 192.168.0.167[4500] (76 bytes)
Jan  3 10:48:58 narvi charon: 10[ENC] parsed ID_PROT response 0 [ ID HASH ]
Jan  3 10:48:58 narvi charon: 10[IKE] IKE_SA c6205c9a-8eae-4f51-b873-24517e34a7de[1] established between 192.168.0.167[192.168.0.167]...***.***.***.***[***.***.***.***]
Jan  3 10:48:58 narvi charon: 10[IKE] IKE_SA c6205c9a-8eae-4f51-b873-24517e34a7de[1] state change: CONNECTING => ESTABLISHED
Jan  3 10:48:58 narvi charon: 10[IKE] scheduling reauthentication in 10173s
Jan  3 10:48:58 narvi charon: 10[IKE] maximum IKE_SA lifetime 10713s
Jan  3 10:48:58 narvi charon: 10[IKE] activating new tasks
Jan  3 10:48:58 narvi charon: 10[IKE]   activating QUICK_MODE task
Jan  3 10:48:58 narvi charon: 10[CFG] configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ, ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ
Jan  3 10:48:58 narvi charon: 10[CFG] configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ, ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ
Jan  3 10:48:58 narvi charon: 10[CFG] proposing traffic selectors for us:
Jan  3 10:48:58 narvi charon: 10[CFG]  192.168.0.167/32[udp/l2f]
Jan  3 10:48:58 narvi charon: 10[CFG] proposing traffic selectors for other:
Jan  3 10:48:58 narvi charon: 10[CFG]  ***.***.***.***/32[udp/l2f]
Jan  3 10:48:58 narvi charon: 10[ENC] generating QUICK_MODE request 4241729600 [ HASH SA No ID ID NAT-OA NAT-OA ]
Jan  3 10:48:58 narvi charon: 10[NET] sending packet: from 192.168.0.167[4500] to ***.***.***.***[4500] (252 bytes)
Jan  3 10:48:58 narvi charon: 01[NET] received packet: from ***.***.***.***[4500] to 192.168.0.167[4500] (204 bytes)
Jan  3 10:48:58 narvi charon: 01[ENC] parsed QUICK_MODE response 4241729600 [ HASH SA No ID ID NAT-OA NAT-OA ]
Jan  3 10:48:58 narvi charon: 01[CFG] selecting proposal:
Jan  3 10:48:58 narvi charon: 01[CFG]   no acceptable ENCRYPTION_ALGORITHM found
Jan  3 10:48:58 narvi charon: 01[CFG] selecting proposal:
Jan  3 10:48:58 narvi charon: 01[CFG]   proposal matches
Jan  3 10:48:58 narvi charon: 01[CFG] received proposals: ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ
Jan  3 10:48:58 narvi charon: 01[CFG] configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ, ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ
Jan  3 10:48:58 narvi charon: 01[CFG] selected proposal: ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ
Jan  3 10:48:58 narvi charon: 01[IKE] changing received traffic selectors 35.141.96.60/32[udp/l2f]=== ***.***.***.***/32[udp/l2f] due to NAT
Jan  3 10:48:58 narvi charon: 01[IKE] CHILD_SA c6205c9a-8eae-4f51-b873-24517e34a7de{1} established with SPIs cc9cf886_i c3572935_o and TS 192.168.0.167/32[udp/l2f] === ***.***.***.***/32[udp/l2f]
Jan  3 10:48:58 narvi charon: 01[IKE] reinitiating already active tasks
Jan  3 10:48:58 narvi charon: 01[IKE]   QUICK_MODE task
Jan  3 10:48:58 narvi charon: 01[ENC] generating QUICK_MODE request 4241729600 [ HASH ]
Jan  3 10:48:58 narvi charon: 01[NET] sending packet: from 192.168.0.167[4500] to ***.***.***.***[4500] (60 bytes)
Jan  3 10:48:58 narvi charon: 01[IKE] activating new tasks
Jan  3 10:48:58 narvi charon: 01[IKE] nothing to initiate
Jan  3 10:48:58 narvi NetworkManager[943611]: <info>  [1672771738.9448] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: VPN plugin: state changed: starting (3)
Jan  3 10:49:12 narvi NetworkManager[943611]: <warn>  [1672771752.9563] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: VPN plugin: failed: connect-failed (1)
Jan  3 10:49:12 narvi NetworkManager[943611]: <warn>  [1672771752.9563] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: VPN plugin: failed: connect-failed (1)
Jan  3 10:49:12 narvi NetworkManager[943611]: <info>  [1672771752.9564] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: VPN plugin: state changed: stopping (5)
Jan  3 10:49:12 narvi charon: 00[DMN] SIGINT received, shutting down
Jan  3 10:49:12 narvi charon: 00[IKE] queueing QUICK_DELETE task
Jan  3 10:49:12 narvi charon: 00[IKE] queueing ISAKMP_DELETE task
Jan  3 10:49:12 narvi charon: 00[IKE] activating new tasks
Jan  3 10:49:12 narvi charon: 00[IKE]   activating QUICK_DELETE task
Jan  3 10:49:12 narvi charon: 00[IKE] closing CHILD_SA c6205c9a-8eae-4f51-b873-24517e34a7de{1} with SPIs cc9cf886_i (0 bytes) c3572935_o (500 bytes) and TS 192.168.0.167/32[udp/l2f] === ***.***.***.***/32[udp/l2f]
Jan  3 10:49:12 narvi charon: 00[IKE] sending DELETE for ESP CHILD_SA with SPI cc9cf886
Jan  3 10:49:12 narvi charon: 00[ENC] generating INFORMATIONAL_V1 request 1143695266 [ HASH D ]
Jan  3 10:49:12 narvi charon: 00[NET] sending packet: from 192.168.0.167[4500] to ***.***.***.***[4500] (76 bytes)
Jan  3 10:49:12 narvi charon: 00[IKE] activating new tasks
Jan  3 10:49:12 narvi charon: 00[IKE]   activating ISAKMP_DELETE task
Jan  3 10:49:12 narvi charon: 00[IKE] deleting IKE_SA c6205c9a-8eae-4f51-b873-24517e34a7de[1] between 192.168.0.167[192.168.0.167]...***.***.***.***[***.***.***.***]
Jan  3 10:49:12 narvi charon: 00[IKE] sending DELETE for IKE_SA c6205c9a-8eae-4f51-b873-24517e34a7de[1]
Jan  3 10:49:12 narvi charon: 00[IKE] IKE_SA c6205c9a-8eae-4f51-b873-24517e34a7de[1] state change: ESTABLISHED => DELETING
Jan  3 10:49:12 narvi charon: 00[ENC] generating INFORMATIONAL_V1 request 2216329122 [ HASH D ]
Jan  3 10:49:12 narvi charon: 00[NET] sending packet: from 192.168.0.167[4500] to ***.***.***.***[4500] (92 bytes)
Jan  3 10:49:12 narvi charon: 00[IKE] IKE_SA c6205c9a-8eae-4f51-b873-24517e34a7de[1] state change: DELETING => DESTROYING
Jan  3 10:49:13 narvi NetworkManager[943611]: <info>  [1672771753.0619] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: VPN plugin: state changed: stopped (6)
Jan  3 10:49:13 narvi NetworkManager[943611]: <warn>  [1672771753.0723] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: VPN plugin: failed: connect-failed (1)

dkosovic commented 1 year ago

nm-l2tp-service --debug is more useful for debugging IPsec Main Mode (phase 1) and Quick Mode (phase 2) issues. Both Main Mode and Quick Mode seem successful from the logs. In this case, I would recommend using the following for debugging so everything is in one place:

sudo journalctl --no-hostname _SYSTEMD_UNIT=NetworkManager.service + SYSLOG_IDENTIFIER=pppd

Do you have other L2TP devices behind the same NAT connected to the VPN server at the same time? Generally NAT-Traversal does not work for multiple L2TP clients behind the same NAT if the clients are all using UDP source port 1701, as the server is unable to differentiate between multiple L2TP connections coming from the same NAT. See "Unable to establish L2TP connection with UDP source port 1701" section for a workaround :

https://github.com/nm-l2tp/NetworkManager-l2tp#l2tp-connection-issues-with-udp-source-port-1701

bblough commented 1 year ago

journalctl --no-hostname _SYSTEMD_UNIT=NetworkManager.service + SYSLOG_IDENTIFIER=pppd from that time period unfortunately doesn't seem any more helpful:

Jan 03 10:48:52 NetworkManager[943611]: <info>  [1672771732.1008] audit: op="connection-activate" uuid="c6205c9a-8eae-4f51-b873-24517e34a7de" name="VPN to Home" pid=944183 uid=0 result="success"
Jan 03 10:48:52 NetworkManager[943611]: <info>  [1672771732.1054] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: Saw the service appear; activating connection
Jan 03 10:48:54 NetworkManager[943611]: <info>  [1672771734.8481] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: VPN connection: (ConnectInteractive) reply received
Jan 03 10:48:58 NetworkManager[943611]: <info>  [1672771738.9448] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: VPN plugin: state changed: starting (3)
Jan 03 10:49:12 NetworkManager[943611]: <warn>  [1672771752.9563] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: VPN plugin: failed: connect-failed (1)
Jan 03 10:49:12 NetworkManager[943611]: <warn>  [1672771752.9563] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: VPN plugin: failed: connect-failed (1)
Jan 03 10:49:12 NetworkManager[943611]: <info>  [1672771752.9564] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: VPN plugin: state changed: stopping (5)
Jan 03 10:49:13 NetworkManager[943611]: <info>  [1672771753.0619] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: VPN plugin: state changed: stopped (6)
Jan 03 10:49:13 NetworkManager[943611]: <warn>  [1672771753.0723] vpn-connection[0x559987d864c0,c6205c9a-8eae-4f51-b873-24517e34a7de,"VPN to Home",0]: VPN plugin: failed: connect-failed (1)

Regarding the other devices - I have previously connected to the server with other devices (leading me to believe the server config is OK), but there are currently no other L2TP devices here on this network (connected or otherwise).

dkosovic commented 1 year ago

Something really weird happening with that xl2tpd version. I've never seen the control_finish: message type is (null)(0) error before. Some claim changing to a different version of xl2tpd solves the issue, e.g.:

https://serverfault.com/questions/1091705/how-to-fix-these-xl2tpd-errors

If you were running network-manager-l2tp >= 1.20.0, it's pretty simple to switch from xl2tpd to Katalix go-l2tp's kl2tpd. Unfortunately you seem to be running network-manager-l2tp 1.2.18.

It's pretty easy to build and install the latest network-manager-l2tp 1.20.8 from the Debian Sid source package with the following :

mkdir nm-l2tp
cd nm-l2tp
dget https://deb.debian.org/debian/pool/main/n/network-manager-l2tp/network-manager-l2tp_1.20.8-1.dsc
cd network-manager-l2tp-1.20.8
debuild -us -uc
cd ..
sudo dpkg -i network-manager-l2tp_1.20.8-1_amd64.deb network-manager-l2tp-gnome_1.20.8-1_amd64.deb

You might need to install some or all of the following dependencies to build xl2tpd:

sudo apt install \
  build-essential \
  devscripts \
  libtool \
  network-manager-dev \
  libnm-dev \
  libnma-dev \
  ppp-dev \
  libdbus-glib-1-dev \
  libsecret-1-dev \
  libgtk-3-dev \
  libglib2.0-dev \
  libssl-dev \
  libnss3-dev \
  libxml2-utils

NetworkManager-l2tp >= 1.20.0 will use kl2tpd as the default L2TP daemon and fall back to xl2tpd if it can't find it, kl2tpd can readily be installed with :

sudo apt install golang-go

go install "github.com/katalix/go-l2tp/...@latest"
sudo mkdir /usr/local/sbin
sudo cp go/bin/kl2tpd /usr/local/sbin

bblough commented 1 year ago

I did see that serverfault post and the releated ubuntu thread. Based on my reading of it, the version of xl2tpd that I'm running (1.3.12) is the version that works, with 1.3.16 being the one with issues.

That said, I built/installed xl2tpd 1.3.18 from testing/unstable, but that doesn't seem to have had any effect good or bad.

I started to build nm-l2tp 1.20.8 from unstable, but the build-deps aren't immediately satisfiable on bullseye due to lack of gtk4. So to make that work I'm either going to have to compile all of the gtk4 dependencies (there are only a few direct deps, but I'm not sure how long the recursive dependency list is), or upgrade the system to bookworm ahead of its release. Either way, it might be a few days before I can get the time to do either of those.

dkosovic commented 1 year ago

I was skeptical about the "exact same problem" answer to that serverfault post as the Ubuntu LTO issue, manifests in totally different xl2tpd error messages.

Sorry I forgot that Debian 11 wouldn't come with a gtk4 based GNOME Control Center. The unstable network-manager-l2tp 1.20.8 source package builds both the gtk3 and gtk4 VPN plugin. Last week I back ported to Ubuntu 22.04 and 20.04 and had to remove the following gtk4 related stuff from the package source, you'll be able to do the same modifications:

debian/control
remove the 3 lines that contain gtk4 in the Build-Depends section.
debian/network-manager-l2tp-gnome.install
remove the usr/lib/*/NetworkManager/libnm-gtk4-vpn-plugin-l2tp-editor.so line.
debian/rules :
remove the --with-gtk4 line.

You might also need to change the debian/changelog file and replace unstable in the first line to be bullseye. You may or may not need to change the Standards-Version in the debian/control file to an older version if you get an error, I had to with Ubuntu 20.04, but not 22.04.

bblough commented 1 year ago

Thanks for the info. That will make things a lot easier.

bblough commented 1 year ago

OK, so this is now working. Unfortunately, I don't know why exactly.

A few weeks ago, I was able to connect with another, "good" device, but was not able to connect with the "bad" device I've been trying to troubleshoot recently. So there definitely was a client-related issue with this particular device. I promise, I'm not imagining it :-)

I had been working under the assumption that the server was still operating fine, but it turns out that it was not. So even with a perfectly working client, connections would not have been successful.

When I found/fixed the server issue, the "bad" device was able to connect, even though it couldn't previously. So something I changed during the troubleshooting process (config changes, library upgrades, etc.) fixed the client issue, only I didn't realize it at the time because it was masked by the server issue.

It's not a satisfying resolution (I really would have liked to have found a root cause - I dislike "accidental" fixes), but it does seem to be resolved.

Thanks for taking the time to help me work through this. Sorry I don't have an actual answer as to what the client-related problem was.

nm-l2tp / NetworkManager-l2tp

Unable to connect - pppd not getting spawned? #200