problem with networkmanager 1.36

[jakob-bebop]

I've been using the same vpn settings for years, on Arch linux. Since Arch released networkmanager-1.36, it stopped working. I eventually figured out that I could get it working by downgrading networkmanager to 1.34.

Before downgrading, the connection seemed ok for a few seconds, but would then fail. The output with --debug enabled, was

connection
       id : 'Swann vpn'
       permissions : ['user:jakob:']
       type : 'vpn'
       uuid : 'e1eaa068-8d2d-4629-8b0b-3cdc58a2afa2'

vpn
       data : {'gateway': 'mail.avforlaget.dk', 'ipsec-enabled': 'yes', 'ipsec-psk': 'yyyy', 'password-flags': '1', 'refuse-chap': 'yes
', 'refuse-eap': 'yes', 'refuse-mschap': 'yes', 'refuse-pap': 'yes', 'require-mppe-128': 'yes', 'user': 'vpn-jl'}
       secrets : {'password': 'xxxxxx'}
       service-type : 'org.freedesktop.NetworkManager.l2tp'
       user-name : 'jakob'

ipv4
       address-data : []
       dns : [37202112]
       dns-search : ['avforlaget.local']
       method : 'auto'
       route-data : []

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

proxy

nm-l2tp[164189] <info>  starting ipsec
Stopping strongSwan IPsec failed: starter is not running
Starting strongSwan 5.9.5 IPsec [starter]...
Loading config setup
Loading conn 'e1eaa068-8d2d-4629-8b0b-3cdc58a2afa2'
nm-l2tp[164189] <info>  Spawned ipsec up script with PID 164235.
initiating Main Mode IKE_SA e1eaa068-8d2d-4629-8b0b-3cdc58a2afa2[1] to 80.208.2.58
generating ID_PROT request 0 [ SA V V V V V ]
sending packet: from 192.168.50.180[500] to 80.208.2.58[500] (532 bytes)
received packet: from 80.208.2.58[500] to 192.168.50.180[500] (406 bytes)
parsed ID_PROT response 0 [ SA V V V V V V V V V V V ]
received unknown vendor ID: f7:58:f2:26:68:75:0f:03:b0:8d:f6:eb:e1:d0:04:03
received draft-ietf-ipsec-nat-t-ike-02 vendor ID
received draft-ietf-ipsec-nat-t-ike-02\n vendor ID
received draft-ietf-ipsec-nat-t-ike-03 vendor ID
received NAT-T (RFC 3947) vendor ID
received XAuth vendor ID
received DPD vendor ID
received unknown vendor ID: af:ca:d7:13:68:a1:f1:c9:6b:86:96:fc:77:57
received unknown vendor ID: f9:19:6d:f8:6b:81:2f:b0:f6:80:26:d8:87:6d:cb:7b:00:04:32:00
received unknown vendor ID: ac:40:f8:c4:38:99:27:c6:e8:ac:24:53:1b:b7:8b:2b:fc:85:f7:13:1a:cf:e7:62:ed:38:ac:ee:f8:2e:4c:1d:14:0e:64:76:2f:4b
:58:7a:85:71:68:5f:93:84:44:ec:a0:be:92:06:1a:22:4b:1d:08:2f:1b:b5:ad:19:00:46:1c:6e:c4:d8:8a:50:5d:b2:29:85:87:e4:39:2e:36:30:3e:fe:1e:7c:3b
:ca:69:55:7d:13:e9:42:d3:ca:06:01:e1:aa:da:70:c5:c3:46:6b:e6:2d:c4:48:c7:23:5a:dc:a0:46:c7:8f:6f:b0:e8:11:49:bc:4f:a3:c6:f1:c8:ca
received unknown vendor ID: b6:c9:8c:ca:29:0a:eb:be:37:f1:9f:31:12:d2:d7:cb
selected proposal: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
sending packet: from 192.168.50.180[500] to 80.208.2.58[500] (244 bytes)
received packet: from 80.208.2.58[500] to 192.168.50.180[500] (228 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.50.180[4500] to 80.208.2.58[4500] (68 bytes)
received packet: from 80.208.2.58[4500] to 192.168.50.180[4500] (68 bytes)
parsed ID_PROT response 0 [ ID HASH ]
IKE_SA e1eaa068-8d2d-4629-8b0b-3cdc58a2afa2[1] established between 192.168.50.180[192.168.50.180]...80.208.2.58[80.208.2.58]
scheduling reauthentication in 9839s
maximum IKE_SA lifetime 10379s
generating QUICK_MODE request 1922545136 [ HASH SA No ID ID NAT-OA NAT-OA ]
sending packet: from 192.168.50.180[4500] to 80.208.2.58[4500] (244 bytes)
received packet: from 80.208.2.58[4500] to 192.168.50.180[4500] (172 bytes)
parsed QUICK_MODE response 1922545136 [ HASH SA No ID ID NAT-OA NAT-OA ]
selected proposal: ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ
CHILD_SA e1eaa068-8d2d-4629-8b0b-3cdc58a2afa2{1} established with SPIs c1f771a3_i b37c7771_o and TS 192.168.50.180/32[udp/l2f] === 80.208.2.5
8/32[udp/l2f]
connection 'e1eaa068-8d2d-4629-8b0b-3cdc58a2afa2' established successfully
nm-l2tp[164189] <info>  strongSwan IPsec tunnel is up.
** Message: 19:39:32.365: xl2tpd started with pid 164245
xl2tpd[164245]: Not looking for kernel SAref support.
xl2tpd[164245]: Using l2tp kernel support.
xl2tpd[164245]: xl2tpd version xl2tpd-1.3.17 started on goldilocks PID:164245
xl2tpd[164245]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc.
xl2tpd[164245]: Forked by Scott Balmos and David Stipp, (C) 2001
xl2tpd[164245]: Inherited by Jeff McAdams, (C) 2002
xl2tpd[164245]: Forked again by Xelerance (www.xelerance.com) (C) 2006-2016
xl2tpd[164245]: Listening on IP address 0.0.0.0, port 1701
xl2tpd[164245]: get_call: allocating new tunnel for host 80.208.2.58, port 1701.
xl2tpd[164245]: Connecting to host 80.208.2.58, port 1701
xl2tpd[164245]: control_finish: message type is (null)(0).  Tunnel is 0, call is 0.
xl2tpd[164245]: control_finish: sending SCCRQ
xl2tpd[164245]: message_type_avp: message type 2 (Start-Control-Connection-Reply)
xl2tpd[164245]: protocol_version_avp: peer is using version 1, revision 0.
xl2tpd[164245]: framing_caps_avp: supported peer frames: sync
xl2tpd[164245]: hostname_avp: peer reports hostname '(none)'
xl2tpd[164245]: assigned_tunnel_avp: using peer's tunnel 45856
xl2tpd[164245]: bearer_caps_avp: supported peer bearers:
xl2tpd[164245]: firmware_rev_avp: peer reports firmware version 1025 (0x0401)
xl2tpd[164245]: vendor_avp: peer reports vendor 'SafeNet Inc.'
xl2tpd[164245]: receive_window_size_avp: peer wants RWS of 16.  Will use flow control.
xl2tpd[164245]: control_finish: message type is Start-Control-Connection-Reply(2).  Tunnel is 45856, call is 0.
xl2tpd[164245]: control_finish: sending SCCCN
xl2tpd[164245]: Connection established to 80.208.2.58, 1701.  Local: 50593, Remote: 45856 (ref=0/0).
xl2tpd[164245]: Calling on tunnel 50593
xl2tpd[164245]: control_finish: message type is (null)(0).  Tunnel is 45856, call is 0.
xl2tpd[164245]: control_finish: sending ICRQ
xl2tpd[164245]: message_type_avp: message type 11 (Incoming-Call-Reply)
xl2tpd[164245]: assigned_call_avp: using peer's call 32207
xl2tpd[164245]: control_finish: message type is Incoming-Call-Reply(11).  Tunnel is 45856, call is 32207.
xl2tpd[164245]: control_finish: Sending ICCN
xl2tpd[164245]: Call established with 80.208.2.58, Local: 30491, Remote: 32207, Serial: 1 (ref=0/0)
xl2tpd[164245]: start_pppd: I'm running:  
xl2tpd[164245]: "/usr/sbin/pppd"  
xl2tpd[164245]: "plugin"  
xl2tpd[164245]: "pppol2tp.so"  
xl2tpd[164245]: "pppol2tp"  
xl2tpd[164245]: "7"  
xl2tpd[164245]: "passive"  
xl2tpd[164245]: "nodetach"  
xl2tpd[164245]: ":"  
xl2tpd[164245]: "debug"  
xl2tpd[164245]: "file"  
xl2tpd[164245]: "/var/run/nm-l2tp-e1eaa068-8d2d-4629-8b0b-3cdc58a2afa2/ppp-options"  
xl2tpd[164245]: message_type_avp: message type 16 (Set-Link-Info)
xl2tpd[164245]: ignore_avp : Ignoring AVP
xl2tpd[164245]: control_finish: message type is Set-Link-Info(16).  Tunnel is 45856, call is 32207.
xl2tpd[164245]: message_type_avp: message type 6 (Hello)
xl2tpd[164245]: control_finish: message type is Hello(6).  Tunnel is 45856, call is 0.
xl2tpd[164245]: check_control: Received out of order control packet on tunnel 45856 (got 3, expected 4)
xl2tpd[164245]: handle_control: bad control packet!
xl2tpd[164245]: network_thread: bad packet
xl2tpd[164245]: check_control: Received out of order control packet on tunnel 45856 (got 3, expected 4)
xl2tpd[164245]: handle_control: bad control packet!
xl2tpd[164245]: network_thread: bad packet
xl2tpd[164245]: check_control: Received out of order control packet on tunnel 45856 (got 3, expected 4)
xl2tpd[164245]: handle_control: bad control packet!
xl2tpd[164245]: network_thread: bad packet
xl2tpd[164245]: check_control: Received out of order control packet on tunnel 45856 (got 3, expected 4)
xl2tpd[164245]: handle_control: bad control packet!
xl2tpd[164245]: network_thread: bad packet
xl2tpd[164245]: Maximum retries exceeded for tunnel 50593.  Closing.
xl2tpd[164245]: Terminating pppd: sending TERM signal to pid 164246
xl2tpd[164245]: Connection 45856 closed to 80.208.2.58, port 1701 (Timeout)
nm-l2tp[164189] <info>  Terminated xl2tpd daemon with PID 164245.
xl2tpd[164245]: death_handler: Fatal signal 15 received
Stopping strongSwan IPsec...
** Message: 19:41:04.579: ipsec shut down
nm-l2tp[164189] <warn>  xl2tpd exited with error code 1
Stopping strongSwan IPsec failed: starter is not running
** Message: 19:41:04.599: ipsec shut down

[dkosovic]

I tried to reproduce the issue with network-manager-1.36.2-1 on Debian Sid and NetworkManager-1.36.0-2.el9 on CentOS Stream 9, but I'm not able to reproduce the issue.

I suspect Arch Linux's networkmanager-1.36 package introduced some routing issue, as version 1.36 changed the way routing is handled.

But as there appears to be some xl2tpd error messages and as NetworkManager-l2tp 1.20.0 supports kl2tpd from Katalix's go-l2tp project, you could try kl2tpd as an alternative. It will fallback to xl2tpd if kl2tpd is not installed. To install kl2tpd (assuming the go package is installed), issue:

go get github.com/katalix/go-l2tp/...
sudo mkdir /usr/local/sbin
sudo cp go/bin/kl2tpd /usr/local/sbin

Katalix are the authors of the L2TP kernel modules that xl2tpd also uses.

[dkosovic]

Forgot to mention, it is probably better to use journalctl to see the log output as it is missing the significant pppd, nm-l2tp pppd plug-in and NetworkManager logs in regards to this issue, e.g. :

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

if using go-l2tp's kl2tpd, it is recommended to issue the following :

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

[jakob-bebop]

Thanks for the suggestions.

I tried kl2tpd but I wasn't able to start the connection with either networkmanager version.

Upstream issue:

https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/issues/946

[dkosovic]

Yeah, that upstream L2TP not working with NetworkManager 1.36 issue has the missing pppd logs. It seems to be a routing issue and traffic isn't going over ppp0.

Upstream has released NetworkManager 1.37, hopefully that might fix the issue for you.

[dkosovic]

I've added responses to that upstream bug report :

• https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/issues/946

I managed to reproduce the issue if the "Use this connection only for resources on its network" IPv4 setting is enabled. It appears to be a routing issue.

[dkosovic]

I ended up setting up a VM with Arch Linux. As mentioned in the upstream bug report, the Arch Linux networkmanager 1.36 issue is due to a bug with the Arch Linux strongswan package as I wasn't able to reproduce the issue when I switched to the AUR libreswan package nor when I used Fedora 36 and strongswan. Fedora 36 has disabled a number of strongswan features that are too broken to enable, while the Arch Linux strongswan package still has them enabled.

That routing issue I mentioned was for network-manager 1.36.2 on Debian Sid, so may or may not be applicable to Arch Linux, but 1.36.4 definitely doesn't have the routing issue.

[dkosovic]

I can confirm the following modifications to the Arch Linux strongswan PKGBUILD file fixes the Arch linux strongswan issue with networkmanager 1.36.4 and networkmanager-l2tp :

--- PKGBUILD.orig   2022-02-19 23:00:00 +1000
+++ PKGBUILD    2022-03-30 20:00:00 +1000
@@ -87,8 +87,6 @@
     --enable-mysql \
     --enable-ldap \
     --enable-cmd \
-    --enable-forecast \
-    --enable-connmark \
     --enable-aesni \
     --enable-eap-ttls \
     --enable-radattr \
@@ -103,12 +101,10 @@
     --enable-newhope \
     --enable-ntru \
     --enable-mgf1 \
-    --enable-sha3 \
     --enable-bliss \
     --enable-dnscert \
     --enable-nm \
     --enable-agent \
-    --enable-bypass-lan \
     --enable-ruby-gems \
     --enable-python-eggs
   make

But not sure which one(s) in particular fixes the issue.

I'll close this issue as it seems to be more a strongswan issue.