Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

NetworkManager[pid]: xl2tpd[pid]: Maximum retries exceeded for tunnel [number]. Closing. #189

Closed
Oberonc opened this issue Jun 14, 2022 · 8 comments
Assignees

Comments

@Oberonc
Copy link

Oberonc commented Jun 14, 2022

Connection is lost after about 20 seconds after being up and working.

When I bring up the connection with "nmcli c up vpn":

Jun 14 15:58:11 intel-x86-64 NetworkManager[225]: <info>  [1655222291.9231] agent-manager: agent[167a60cbf2b2bdba,:1.24/nmcli-connect/0]: agent registered
Jun 14 15:58:11 intel-x86-64 NetworkManager[225]: <info>  [1655222291.9285] audit: op="connection-activate" uuid="b5569b9d-e133-41c0-892b-720dec9706b6" name="vpn" pid=496 uid=0 result="success"
Jun 14 15:58:11 intel-x86-64 NetworkManager[225]: <info>  [1655222291.9346] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",0]: Started the VPN service, PID 502
Jun 14 15:58:11 intel-x86-64 NetworkManager[225]: <info>  [1655222291.9522] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",0]: Saw the service appear; activating connection
Jun 14 15:58:11 intel-x86-64 NetworkManager[225]: <info>  [1655222291.9634] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",0]: VPN connection: (ConnectInteractive) reply received
Jun 14 15:58:11 intel-x86-64 nm-l2tp-service[502]: Check port 1701
Jun 14 15:58:12 intel-x86-64 NetworkManager[515]: Stopping strongSwan IPsec failed: starter is not running
Jun 14 15:58:14 intel-x86-64 NetworkManager[512]: Starting strongSwan 5.9.2 IPsec [starter]...
Jun 14 15:58:14 intel-x86-64 NetworkManager[512]: Loading config setup
Jun 14 15:58:14 intel-x86-64 NetworkManager[512]: Loading conn 'b5569b9d-e133-41c0-892b-720dec9706b6'
Jun 14 15:58:14 intel-x86-64 ipsec_starter[512]: Starting strongSwan 5.9.2 IPsec [starter]...
Jun 14 15:58:14 intel-x86-64 ipsec_starter[512]: Loading config setup
Jun 14 15:58:14 intel-x86-64 ipsec_starter[512]: Loading conn 'b5569b9d-e133-41c0-892b-720dec9706b6'
Jun 14 15:58:14 intel-x86-64 ipsec_starter[523]: Attempting to start charon...
Jun 14 15:58:14 intel-x86-64 charon[525]: 00[DMN] Starting IKE charon daemon (strongSwan 5.9.2, Linux 5.10.104-yocto-standard, x86_64)
Jun 14 15:58:14 intel-x86-64 charon[525]: 00[KNL] received netlink error: Address family not supported by protocol (97)
Jun 14 15:58:14 intel-x86-64 charon[525]: 00[KNL] unable to create IPv6 routing table rule
Jun 14 15:58:14 intel-x86-64 charon[525]: 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts'
Jun 14 15:58:14 intel-x86-64 charon[525]: 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts'
Jun 14 15:58:14 intel-x86-64 charon[525]: 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts'
Jun 14 15:58:14 intel-x86-64 charon[525]: 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts'
Jun 14 15:58:14 intel-x86-64 charon[525]: 00[CFG] loading crls from '/etc/ipsec.d/crls'
Jun 14 15:58:14 intel-x86-64 charon[525]: 00[CFG] loading secrets from '/etc/ipsec.secrets'
Jun 14 15:58:14 intel-x86-64 charon[525]: 00[CFG] loading secrets from '/etc/ipsec.d/ipsec.nm-l2tp.secrets'
Jun 14 15:58:14 intel-x86-64 charon[525]: 00[CFG]   loaded IKE secret for %any
Jun 14 15:58:14 intel-x86-64 charon[525]: 00[LIB] loaded plugins: charon aes des rc2 sha2 sha1 md5 random nonce x509 revocation constraints pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey sshkey pem openssl gmp curve25519 xcbc cmac hmac curl sqlite attr kernel-netlink resolve socket-default stroke vici updown xauth-generic
Jun 14 15:58:14 intel-x86-64 charon[525]: 00[JOB] spawning 16 worker threads
Jun 14 15:58:14 intel-x86-64 ipsec_starter[523]: charon (525) started after 40 ms
Jun 14 15:58:14 intel-x86-64 charon[525]: 05[CFG] received stroke: add connection 'b5569b9d-e133-41c0-892b-720dec9706b6'
Jun 14 15:58:14 intel-x86-64 charon[525]: 05[CFG] added configuration 'b5569b9d-e133-41c0-892b-720dec9706b6'
Jun 14 15:58:15 intel-x86-64 charon[525]: 07[CFG] rereading secrets
Jun 14 15:58:15 intel-x86-64 charon[525]: 07[CFG] loading secrets from '/etc/ipsec.secrets'
Jun 14 15:58:15 intel-x86-64 charon[525]: 07[CFG] loading secrets from '/etc/ipsec.d/ipsec.nm-l2tp.secrets'
Jun 14 15:58:15 intel-x86-64 charon[525]: 07[CFG]   loaded IKE secret for %any
Jun 14 15:58:15 intel-x86-64 charon[525]: 09[CFG] received stroke: initiate 'b5569b9d-e133-41c0-892b-720dec9706b6'
Jun 14 15:58:15 intel-x86-64 charon[525]: 11[IKE] initiating Main Mode IKE_SA b5569b9d-e133-41c0-892b-720dec9706b6[1] to [server ip]
Jun 14 15:58:15 intel-x86-64 charon[525]: 11[IKE] initiating Main Mode IKE_SA b5569b9d-e133-41c0-892b-720dec9706b6[1] to [server ip]
Jun 14 15:58:15 intel-x86-64 charon[525]: 11[ENC] generating ID_PROT request 0 [ SA V V V V V ]
Jun 14 15:58:15 intel-x86-64 charon[525]: 11[NET] sending packet: from 10.100.102.8[500] to [server ip][500] (532 bytes)
Jun 14 15:58:15 intel-x86-64 charon[525]: 12[NET] received packet: from [server ip][500] to 10.100.102.8[500] (144 bytes)
Jun 14 15:58:15 intel-x86-64 charon[525]: 12[ENC] parsed ID_PROT response 0 [ SA V V V ]
Jun 14 15:58:15 intel-x86-64 charon[525]: 12[IKE] received FRAGMENTATION vendor ID
Jun 14 15:58:15 intel-x86-64 charon[525]: 12[IKE] received DPD vendor ID
Jun 14 15:58:15 intel-x86-64 charon[525]: 12[IKE] received NAT-T (RFC 3947) vendor ID
Jun 14 15:58:15 intel-x86-64 charon[525]: 12[CFG] selected proposal: IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_2048
Jun 14 15:58:15 intel-x86-64 charon[525]: 12[ENC] generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
Jun 14 15:58:15 intel-x86-64 charon[525]: 12[NET] sending packet: from 10.100.102.8[500] to [server ip][500] (396 bytes)
Jun 14 15:58:15 intel-x86-64 charon[525]: 13[NET] received packet: from [server ip][500] to 10.100.102.8[500] (396 bytes)
Jun 14 15:58:15 intel-x86-64 charon[525]: 13[ENC] parsed ID_PROT response 0 [ KE No NAT-D NAT-D ]
Jun 14 15:58:15 intel-x86-64 charon[525]: 13[IKE] local host is behind NAT, sending keep alives
Jun 14 15:58:15 intel-x86-64 charon[525]: 13[IKE] remote host is behind NAT
Jun 14 15:58:15 intel-x86-64 charon[525]: 13[ENC] generating ID_PROT request 0 [ ID HASH ]
Jun 14 15:58:15 intel-x86-64 charon[525]: 13[NET] sending packet: from 10.100.102.8[4500] to [server ip][4500] (92 bytes)
Jun 14 15:58:15 intel-x86-64 charon[525]: 14[NET] received packet: from [server ip][4500] to 10.100.102.8[4500] (76 bytes)
Jun 14 15:58:15 intel-x86-64 charon[525]: 14[ENC] parsed ID_PROT response 0 [ ID HASH ]
Jun 14 15:58:15 intel-x86-64 charon[525]: 14[IKE] IKE_SA b5569b9d-e133-41c0-892b-720dec9706b6[1] established between 10.100.102.8[10.100.102.8]...[server ip][[server ip]]
Jun 14 15:58:15 intel-x86-64 charon[525]: 14[IKE] IKE_SA b5569b9d-e133-41c0-892b-720dec9706b6[1] established between 10.100.102.8[10.100.102.8]...[server ip][[server ip]]
Jun 14 15:58:15 intel-x86-64 charon[525]: 14[IKE] scheduling reauthentication in 10039s
Jun 14 15:58:15 intel-x86-64 charon[525]: 14[IKE] maximum IKE_SA lifetime 10579s
Jun 14 15:58:15 intel-x86-64 charon[525]: 14[ENC] generating QUICK_MODE request 2270805260 [ HASH SA No ID ID NAT-OA NAT-OA ]
Jun 14 15:58:15 intel-x86-64 charon[525]: 14[NET] sending packet: from 10.100.102.8[4500] to [server ip][4500] (268 bytes)
Jun 14 15:58:15 intel-x86-64 charon[525]: 15[NET] received packet: from [server ip][4500] to 10.100.102.8[4500] (188 bytes)
Jun 14 15:58:15 intel-x86-64 charon[525]: 15[ENC] parsed QUICK_MODE response 2270805260 [ HASH SA No ID ID ]
Jun 14 15:58:15 intel-x86-64 charon[525]: 15[CFG] selected proposal: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ
Jun 14 15:58:15 intel-x86-64 charon[525]: 15[IKE] CHILD_SA b5569b9d-e133-41c0-892b-720dec9706b6{1} established with SPIs c2008f26_i 3a812005_o and TS 10.100.102.8/32[udp/l2f] === [server ip]/32[udp/l2f]
Jun 14 15:58:15 intel-x86-64 charon[525]: 15[IKE] CHILD_SA b5569b9d-e133-41c0-892b-720dec9706b6{1} established with SPIs c2008f26_i 3a812005_o and TS 10.100.102.8/32[udp/l2f] === [server ip]/32[udp/l2f]
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: initiating Main Mode IKE_SA b5569b9d-e133-41c0-892b-720dec9706b6[1] to [server ip]
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: generating ID_PROT request 0 [ SA V V V V V ]
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: sending packet: from 10.100.102.8[500] to [server ip][500] (532 bytes)
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: received packet: from [server ip][500] to 10.100.102.8[500] (144 bytes)
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: parsed ID_PROT response 0 [ SA V V V ]
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: received FRAGMENTATION vendor ID
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: received DPD vendor ID
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: received NAT-T (RFC 3947) vendor ID
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: selected proposal: IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_2048
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: sending packet: from 10.100.102.8[500] to [server ip][500] (396 bytes)
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: received packet: from [server ip][500] to 10.100.102.8[500] (396 bytes)
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: parsed ID_PROT response 0 [ KE No NAT-D NAT-D ]
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: local host is behind NAT, sending keep alives
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: remote host is behind NAT
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: generating ID_PROT request 0 [ ID HASH ]
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: sending packet: from 10.100.102.8[4500] to [server ip][4500] (92 bytes)
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: received packet: from [server ip][4500] to 10.100.102.8[4500] (76 bytes)
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: parsed ID_PROT response 0 [ ID HASH ]
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: IKE_SA b5569b9d-e133-41c0-892b-720dec9706b6[1] established between 10.100.102.8[10.100.102.8]...[server ip][[server ip]]
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: scheduling reauthentication in 10039s
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: maximum IKE_SA lifetime 10579s
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: generating QUICK_MODE request 2270805260 [ HASH SA No ID ID NAT-OA NAT-OA ]
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: sending packet: from 10.100.102.8[4500] to [server ip][4500] (268 bytes)
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: received packet: from [server ip][4500] to 10.100.102.8[4500] (188 bytes)
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: parsed QUICK_MODE response 2270805260 [ HASH SA No ID ID ]
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: selected proposal: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: CHILD_SA b5569b9d-e133-41c0-892b-720dec9706b6{1} established with SPIs c2008f26_i 3a812005_o and TS 10.100.102.8/32[udp/l2f] === [server ip]/32[udp/l2f]
Jun 14 15:58:15 intel-x86-64 NetworkManager[551]: connection 'b5569b9d-e133-41c0-892b-720dec9706b6' established successfully
Jun 14 15:58:15 intel-x86-64 charon[525]: 15[ENC] generating QUICK_MODE request 2270805260 [ HASH ]
Jun 14 15:58:15 intel-x86-64 charon[525]: 15[NET] sending packet: from 10.100.102.8[4500] to [server ip][4500] (76 bytes)
Jun 14 15:58:15 intel-x86-64 nm-l2tp-service[502]: strongSwan IPsec connection is up.
Jun 14 15:58:15 intel-x86-64 NetworkManager[557]: xl2tpd[557]: Not looking for kernel SAref support.
Jun 14 15:58:15 intel-x86-64 NetworkManager[557]: xl2tpd[557]: This binary does not support kernel L2TP.
Jun 14 15:58:15 intel-x86-64 NetworkManager[557]: xl2tpd[557]: xl2tpd version xl2tpd-1.3.14 started on intel-x86-64 PID:557
Jun 14 15:58:15 intel-x86-64 NetworkManager[557]: xl2tpd[557]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc.
Jun 14 15:58:15 intel-x86-64 NetworkManager[557]: xl2tpd[557]: Forked by Scott Balmos and David Stipp, (C) 2001
Jun 14 15:58:15 intel-x86-64 NetworkManager[557]: xl2tpd[557]: Inherited by Jeff McAdams, (C) 2002
Jun 14 15:58:15 intel-x86-64 NetworkManager[557]: xl2tpd[557]: Forked again by Xelerance (www.xelerance.com) (C) 2006-2016
Jun 14 15:58:15 intel-x86-64 NetworkManager[557]: xl2tpd[557]: Listening on IP address 0.0.0.0, port 1701
Jun 14 15:58:15 intel-x86-64 NetworkManager[557]: xl2tpd[557]: Connecting to host [server ip], port 1701
Jun 14 15:58:15 intel-x86-64 nm-l2tp-service[502]: xl2tpd started with pid 557
Jun 14 15:58:15 intel-x86-64 NetworkManager[225]: <info>  [1655222295.4030] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",0]: VPN plugin: state changed: starting (3)
Jun 14 15:58:15 intel-x86-64 NetworkManager[557]: xl2tpd[557]: Connection established to [server ip], 1701.  Local: 21163, Remote: 59003 (ref=0/0).
Jun 14 15:58:15 intel-x86-64 NetworkManager[557]: xl2tpd[557]: Calling on tunnel 21163
Jun 14 15:58:15 intel-x86-64 NetworkManager[557]: xl2tpd[557]: Call established with [server ip], Local: 37301, Remote: 26940, Serial: 1 (ref=0/0)
Jun 14 15:58:15 intel-x86-64 pppd[558]: Plugin /usr/lib64/pppd/2.4.9/nm-l2tp-pppd-plugin.so loaded.
Jun 14 15:58:15 intel-x86-64 pppd[558]: pppd 2.4.9 started by root, uid 0
Jun 14 15:58:15 intel-x86-64 NetworkManager[225]: <info>  [1655222295.4631] manager: (ppp0): new Ppp device (/org/freedesktop/NetworkManager/Devices/6)
Jun 14 15:58:15 intel-x86-64 pppd[558]: Using interface ppp0
Jun 14 15:58:15 intel-x86-64 pppd[558]: Connect: ppp0 <--> /dev/pts/2
Jun 14 15:58:18 intel-x86-64 pppd[558]: CHAP authentication succeeded: Access granted
Jun 14 15:58:18 intel-x86-64 pppd[558]: CHAP authentication succeeded
Jun 14 15:58:18 intel-x86-64 charon[525]: 07[KNL] 192.168.42.10 appeared on ppp0
Jun 14 15:58:18 intel-x86-64 charon-systemd[273]: 192.168.42.10 appeared on ppp0
Jun 14 15:58:18 intel-x86-64 pppd[558]: local  IP address 192.168.42.10
Jun 14 15:58:18 intel-x86-64 pppd[558]: remote IP address 192.168.42.1
Jun 14 15:58:18 intel-x86-64 charon-systemd[273]: 192.168.42.10 disappeared from ppp0
Jun 14 15:58:18 intel-x86-64 pppd[558]: primary   DNS address 8.8.8.8
Jun 14 15:58:18 intel-x86-64 charon-systemd[273]: 192.168.42.10 appeared on ppp0
Jun 14 15:58:18 intel-x86-64 pppd[558]: secondary DNS address 8.8.4.4
Jun 14 15:58:18 intel-x86-64 charon-systemd[273]: interface ppp0 activated
Jun 14 15:58:18 intel-x86-64 charon[525]: 11[KNL] 192.168.42.10 disappeared from ppp0
Jun 14 15:58:18 intel-x86-64 charon[525]: 13[KNL] 192.168.42.10 appeared on ppp0
Jun 14 15:58:18 intel-x86-64 charon[525]: 09[KNL] interface ppp0 activated
Jun 14 15:58:18 intel-x86-64 systemd-networkd[226]: ppp0: Link UP
Jun 14 15:58:18 intel-x86-64 systemd-networkd[226]: ppp0: Gained carrier
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.5980] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",0]: VPN connection: (IP4 Config Get) reply received from old-style plugin
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6070] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",6:(ppp0)]: Data: VPN Gateway: [server ip]
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6072] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",6:(ppp0)]: Data: Tunnel Device: "ppp0"
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6074] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",6:(ppp0)]: Data: IPv4 configuration:
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6075] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",6:(ppp0)]: Data:   Internal Address: 192.168.42.10
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6076] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",6:(ppp0)]: Data:   Internal Prefix: 32
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6078] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",6:(ppp0)]: Data:   Internal Point-to-Point Address: 192.168.42.1
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6084] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",6:(ppp0)]: Data:   Static Route: 0.0.0.0/0   Next Hop: 0.0.0.0
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6085] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",6:(ppp0)]: Data:   Static Route: 192.168.42.1/32   Next Hop: 0.0.0.0
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6086] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",6:(ppp0)]: Data:   Internal DNS: 8.8.8.8
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6091] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",6:(ppp0)]: Data:   Internal DNS: 8.8.4.4
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6093] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",6:(ppp0)]: Data:   DNS Domain: '(none)'
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6094] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",6:(ppp0)]: Data: No IPv6 configuration
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6099] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",6:(ppp0)]: VPN plugin: state changed: started (4)
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6150] device (ppp0): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6448] vpn-connection[0x559158c96360,b5569b9d-e133-41c0-892b-720dec9706b6,"vpn",6:(ppp0)]: VPN connection: (IP Config Get) complete
Jun 14 15:58:18 intel-x86-64 dbus-daemon[209]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.5' (uid=0 pid=225 comm="/usr/sbin/NetworkManager --no-daemon ")
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6493] device (ppp0): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'external')
Jun 14 15:58:18 intel-x86-64 systemd[1]: Starting Network Manager Script Dispatcher Service...
Jun 14 15:58:18 intel-x86-64 dbus-daemon[209]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Jun 14 15:58:18 intel-x86-64 systemd[1]: Started Network Manager Script Dispatcher Service.
Jun 14 15:58:18 intel-x86-64 NetworkManager[225]: <info>  [1655222298.6852] policy: set 'vpn' (ppp0) as default for IPv4 routing and DNS
Jun 14 15:58:28 intel-x86-64 systemd[1]: NetworkManager-dispatcher.service: Succeeded.

At this point the connection is working just fine, but after about 20 seconds I get this:

Jun 14 15:58:38 intel-x86-64 charon[525]: 10[IKE] sending keep alive to [server ip][4500]
Jun 14 15:58:45 intel-x86-64 charon[525]: 11[NET] received packet: from [server ip][4500] to 10.100.102.8[4500] (108 bytes)
Jun 14 15:58:45 intel-x86-64 charon[525]: 11[ENC] parsed INFORMATIONAL_V1 request 1930972206 [ HASH N(DPD) ]
Jun 14 15:58:45 intel-x86-64 charon[525]: 11[ENC] generating INFORMATIONAL_V1 request 682963533 [ HASH N(DPD_ACK) ]
Jun 14 15:58:45 intel-x86-64 charon[525]: 11[NET] sending packet: from 10.100.102.8[4500] to [server ip][4500] (108 bytes)
Jun 14 15:58:46 intel-x86-64 NetworkManager[557]: xl2tpd[557]: Maximum retries exceeded for tunnel 21163.  Closing.
Jun 14 15:58:46 intel-x86-64 NetworkManager[557]: xl2tpd[557]: Connection 59003 closed to [server ip], port 1701 (Timeout)
Jun 14 15:58:46 intel-x86-64 charon[525]: 12[KNL] interface ppp0 deactivated
Jun 14 15:58:46 intel-x86-64 charon-systemd[273]: interface ppp0 deactivated
Jun 14 15:58:46 intel-x86-64 charon[525]: 13[KNL] 192.168.42.10 disappeared from ppp0
Jun 14 15:58:46 intel-x86-64 systemd-networkd[226]: ppp0: Link DOWN
Jun 14 15:58:46 intel-x86-64 charon[525]: 09[KNL] interface ppp0 deleted
Jun 14 15:58:46 intel-x86-64 systemd-networkd[226]: ppp0: Lost carrier
Jun 14 15:58:46 intel-x86-64 charon-systemd[273]: 192.168.42.10 disappeared from ppp0
Jun 14 15:58:46 intel-x86-64 charon-systemd[273]: interface ppp0 deleted
Jun 14 15:58:46 intel-x86-64 NetworkManager[225]: <info>  [1655222326.4476] device (ppp0): state change: disconnected -> unmanaged (reason 'unmanaged', sys-iface-state: 'removed')

StrongSwan 5.9.2
nm-l2tp 1.20.4
xl2tpd 1.3.14

Connection configuration file:

[connection]
id=vpn
uuid=b5569b9d-e133-41c0-892b-720dec9706b6
type=vpn
permissions=user:[username]:;

[vpn]
gateway=[server ip]
ipsec-enabled=yes
ipsec-psk=[psk]
user=[user name]
service-type=org.freedesktop.NetworkManager.l2tp

[vpn-secrets]
password=[password]

[ipv4]
dns-search=
method=auto

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

[proxy]
@dkosovic dkosovic self-assigned this Jun 15, 2022
@dkosovic
Copy link
Member

I'm not sure which version of NetworkManager you are using, but if it is >= 1.36 you might be experiencing one of the routing bugs introduced with the newer NetworkManager. e.g. spurious route with no metric (i.e. metric 0) and/or spurious IP address. See:

@Oberonc
Copy link
Author

Oberonc commented Jun 15, 2022

NetworkManager --version
1.30.4

I tried setting "ipv4.ignore-auto-routes" to yes / no
I created the script file "/etc/ppp/ip-up.d/0001routes"

Still behaves exactly the same.

Routing table before bringing up the connection:

default via 10.100.102.1 dev eth0 proto dhcp src 10.100.102.8 metric 1003 
10.100.102.0/24 dev eth0 proto dhcp scope link src 10.100.102.8 metric 1003 

After bringing up the connection:

default dev ppp0 proto static scope link metric 50 
default via 10.100.102.1 dev eth0 proto dhcp src 10.100.102.8 metric 1003 
10.100.102.0/24 dev eth0 proto dhcp scope link src 10.100.102.8 metric 1003 
10.100.102.1 dev eth0 proto static scope link metric 100 
[server ip] via 10.100.102.1 dev eth0 proto static metric 100 
192.168.42.1 dev ppp0 proto kernel scope link src 192.168.42.10 metric 50 

@dkosovic
Copy link
Member

dkosovic commented Jun 15, 2022

Regarding the This binary does not support kernel L2TP message, could you try removing the blacklisting of the L2TP kernel modules, the following should do it:

sudo sed -e '/blacklist l2tp_netlink/s/^b/#b/g' -i /etc/modprobe.d/l2tp_netlink-blacklist.conf
sudo sed -e '/blacklist l2tp_ppp/s/^b/#b/g' -i /etc/modprobe.d/l2tp_ppp-blacklist.conf

See the following for more details:

@Oberonc
Copy link
Author

Oberonc commented Jun 15, 2022

I dont have those files:

$ ls -l /etc/modprobe.d/
total 0

I dont have those modules (l2tp_ppp, l2tp_netlink) in Linux 5.10.104 kernel.
What I do have is:
PPP over L2TP - pppox.ko

I loaded that module and got same results

@dkosovic
Copy link
Member

On RedHat and Fedora the L2TP kernel modules are in the kernel-modules-extra package (PPPoX isn't specifically PPP over L2TP, but does provide support for the l2tp_ppp kernel module to do so). Not sure if there other Linux distros that don't package the L2TP kernel modules in the main kernel package.

Theses are the L2TP kernel modules I see after xl2tpd is run with NetworkManager-l2tp :

$ lsmod | grep l2tp
l2tp_ppp               28672  0
l2tp_netlink           28672  1 l2tp_ppp
l2tp_core              32768  2 l2tp_ppp,l2tp_netlink
pppox                  16384  1 l2tp_ppp
ppp_generic            45056  2 pppox,l2tp_ppp
ip6_udp_tunnel         16384  1 l2tp_core
udp_tunnel             16384  1 l2tp_core

I was also going to suggest trying kl2tpd instead of xl2tpd if you still have issues, but kl2tpd requires the l2tp_ppp and l2tp_netlink kernel modules. kl2tpd can be installed with the Go language by doing the following:

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

NetworkManager-l2tp will use kl2tpd by default and fall back to xl2tpd if it can't find kl2tpd.

@Oberonc
Copy link
Author

Oberonc commented Jun 15, 2022

Thing is that once the connection is made it works perfectly fine .. for 20 seconds.
I can even ssh from one side to the other (server to client or client to server).
If some needed kernel module wasn't loaded I believe the connection wouldn't be created or be usable.
It makes sense the problem has something to do with configuration files or transient state (routing table, etc).

Question is - how do I debug this and figure the cause ? log doesn't seem to provide any information.

@Oberonc
Copy link
Author

Oberonc commented Jun 15, 2022

Well, I got the connection to last much longer with this disgusting hack (not my finest work ever):

diff -uarN git.orig/src/nm-l2tp-service.c git/src/nm-l2tp-service.c
--- git.orig/src/nm-l2tp-service.c	2022-06-15 16:56:15.502164195 +0300
+++ git/src/nm-l2tp-service.c	2022-06-15 17:04:15.516262857 +0300
@@ -1120,6 +1120,7 @@
         write_config_option(fd, "access control = yes\n");
 
         write_config_option(fd, "port = %d\n", port);
+	write_config_option(fd, "max retries = 20000\n");
         if (_LOGD_enabled()) {
             /* write_config_option (fd, "debug network = yes\n"); */
             write_config_option(fd, "debug state = yes\n");

I hope this helps somebody
Maybe you can add this to the nm configuration

@dkosovic
Copy link
Member

Thanks for the bug report. I've added an NM_L2TP_XL2TPD_MAX_RETRIES env variable which allows settings `max retries in commit# 2e5a163

Will look into adding a GUI option in the future.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants