nm-l2tp / NetworkManager-l2tp

L2TP and L2TP/IPsec support for NetworkManager
GNU General Public License v2.0
486 stars 83 forks source link

charon-systemd issues on Arch Linux #195

Closed tukusejssirs closed 1 year ago

tukusejssirs commented 1 year ago

Related comments from #132: 1, 2, 3, 4


I cannot connect to the VPN on Arch Linux, however, some time ago I could. I didn’t change any configuration on the local machine (apart from package upgrades) nor the VPN server was changed. I can connect to the server on MS Windows 10.

Here are some logs (replaced the VPN server IP with $vpn_server_ip:

sudo journalctl --no-hostname _SYSTEMD_UNIT=NetworkManager.service + SYSLOG_IDENTIFIER=pppd ```python Oct 24 09:06:22 NetworkManager[806]: [1666595182.2506] agent-manager: agent[e6ce88a72d56b8a8,:1.476/nmcli-connect/1000]: agent registered Oct 24 09:06:22 NetworkManager[806]: [1666595182.2551] vpn[0x556f9cb6c4a0,4ecb50e8-337d-4123-9643-d98ee724343e,"vpn_connection_name"]: starting l2tp Oct 24 09:06:22 NetworkManager[806]: [1666595182.2553] audit: op="connection-activate" uuid="4ecb50e8-337d-4123-9643-d98ee724343e" name="vpn_connection_name" pid=12> Oct 24 09:06:22 nm-l2tp-service[123640]: Check port 1701 Oct 24 09:06:22 NetworkManager[123661]: Stopping strongSwan IPsec failed: starter is not running Oct 24 09:06:24 NetworkManager[123658]: Starting strongSwan 5.9.8 IPsec [starter]... Oct 24 09:06:24 ipsec_starter[123658]: Starting strongSwan 5.9.8 IPsec [starter]... Oct 24 09:06:24 NetworkManager[123658]: Loading config setup Oct 24 09:06:24 NetworkManager[123658]: Loading conn '4ecb50e8-337d-4123-9643-d98ee724343e' Oct 24 09:06:24 ipsec_starter[123658]: Loading config setup Oct 24 09:06:24 ipsec_starter[123658]: Loading conn '4ecb50e8-337d-4123-9643-d98ee724343e' Oct 24 09:06:24 ipsec_starter[123742]: Attempting to start charon... Oct 24 09:06:24 charon[123743]: 00[DMN] Starting IKE charon daemon (strongSwan 5.9.8, Linux 6.0.2-arch1-1, x86_64) Oct 24 09:06:24 charon[123743]: 00[CFG] PKCS11 module '' lacks library path Oct 24 09:06:24 charon[123743]: 00[NET] unable to bind socket: Address already in use Oct 24 09:06:24 charon[123743]: 00[NET] could not open IPv6 socket, IPv6 disabled Oct 24 09:06:24 charon[123743]: 00[NET] unable to bind socket: Address already in use Oct 24 09:06:24 charon[123743]: 00[NET] could not open IPv4 socket, IPv4 disabled Oct 24 09:06:24 charon[123743]: 00[NET] could not create any sockets Oct 24 09:06:24 charon[123743]: 00[CFG] attr-sql plugin: database URI not set Oct 24 09:06:24 charon[123743]: 00[NET] using forecast interface enp44s0u1u1 Oct 24 09:06:24 charon[123743]: 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 24 09:06:24 charon[123743]: 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts' Oct 24 09:06:24 charon[123743]: 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts' Oct 24 09:06:24 charon[123743]: 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts' Oct 24 09:06:24 charon[123743]: 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts' Oct 24 09:06:24 charon[123743]: 00[CFG] loading crls from '/etc/ipsec.d/crls' Oct 24 09:06:24 charon[123743]: 00[CFG] loading secrets from '/etc/ipsec.secrets' Oct 24 09:06:24 charon[123743]: 00[CFG] loading secrets from '/etc/ipsec.d/ipsec.nm-l2tp.secrets' Oct 24 09:06:24 charon[123743]: 00[CFG] loaded IKE secret for %any Oct 24 09:06:24 charon[123743]: 00[CFG] sql plugin: database URI not set Oct 24 09:06:24 charon[123743]: 00[CFG] opening triplet file /etc/ipsec.d/triplets.dat failed: No such file or directory Oct 24 09:06:24 charon[123743]: 00[CFG] loaded 0 RADIUS server configurations Oct 24 09:06:24 charon[123743]: 00[CFG] HA config misses local/remote address Oct 24 09:06:24 charon[123743]: 00[CFG] no script for ext-auth script defined, disabled Oct 24 09:06:24 charon[123743]: 00[LIB] loaded plugins: charon ldap pkcs11 aesni aes des rc2 sha2 sha3 sha1 md5 mgf1 random nonce x509 revocation constraints pubkey pkcs1 pk> Oct 24 09:06:24 charon[123743]: 00[LIB] dropped capabilities, running as uid 0, gid 0 Oct 24 09:06:24 charon[123743]: 00[JOB] spawning 16 worker threads Oct 24 09:06:24 charon[123743]: 03[NET] no socket implementation registered, receiving failed Oct 24 09:06:24 charon[123743]: 05[IKE] installed bypass policy for 172.17.0.0/16 Oct 24 09:06:24 charon[123743]: 05[IKE] installed bypass policy for 172.26.0.0/16 Oct 24 09:06:24 charon[123743]: 05[IKE] installed bypass policy for 172.27.0.0/16 Oct 24 09:06:24 charon[123743]: 05[IKE] installed bypass policy for 172.28.0.0/16 Oct 24 09:06:24 charon[123743]: 05[IKE] installed bypass policy for 172.29.0.0/16 Oct 24 09:06:24 charon[123743]: 05[IKE] installed bypass policy for 172.30.0.0/16 Oct 24 09:06:24 charon[123743]: 05[IKE] installed bypass policy for 172.31.0.0/16 Oct 24 09:06:24 charon[123743]: 05[IKE] installed bypass policy for 192.168.0.0/24 Oct 24 09:06:24 charon[123743]: 05[IKE] installed bypass policy for 192.168.1.0/24 Oct 24 09:06:24 charon[123743]: 05[IKE] installed bypass policy for 192.168.16.0/20 Oct 24 09:06:24 charon[123743]: 05[IKE] installed bypass policy for 192.168.32.0/20 Oct 24 09:06:24 charon[123743]: 05[IKE] installed bypass policy for ::1/128 Oct 24 09:06:24 charon[123743]: 05[IKE] installed bypass policy for fe80::/64 Oct 24 09:06:24 charon[123743]: 05[IKE] interface change for bypass policy for 192.168.1.0/24 (from wlan0 to enp0s31f6) Oct 24 09:06:24 charon[123743]: 05[IKE] interface change for bypass policy for fe80::/64 (from br-a75bb185b39c to wlan0) Oct 24 09:06:24 ipsec_starter[123742]: charon (123743) started after 20 ms Oct 24 09:06:24 charon[123743]: 11[CFG] received stroke: add connection '4ecb50e8-337d-4123-9643-d98ee724343e' Oct 24 09:06:24 charon[123743]: 11[CFG] added configuration '4ecb50e8-337d-4123-9643-d98ee724343e' Oct 24 09:06:25 charon[123743]: 13[CFG] rereading secrets Oct 24 09:06:25 charon[123743]: 13[CFG] loading secrets from '/etc/ipsec.secrets' Oct 24 09:06:25 charon[123743]: 13[CFG] loading secrets from '/etc/ipsec.d/ipsec.nm-l2tp.secrets' Oct 24 09:06:25 charon[123743]: 13[CFG] loaded IKE secret for %any Oct 24 09:06:25 charon[123743]: 15[CFG] received stroke: initiate '4ecb50e8-337d-4123-9643-d98ee724343e' Oct 24 09:06:25 charon[123743]: 03[IKE] initiating Main Mode IKE_SA 4ecb50e8-337d-4123-9643-d98ee724343e[1] to $vpn_server_ip Oct 24 09:06:25 charon[123743]: 03[IKE] initiating Main Mode IKE_SA 4ecb50e8-337d-4123-9643-d98ee724343e[1] to $vpn_server_ip Oct 24 09:06:25 charon[123743]: 03[ENC] generating ID_PROT request 0 [ SA V V V V V ] Oct 24 09:06:25 charon[123743]: 03[NET] sending packet: from 192.168.1.31 to $vpn_server_ip[500] (532 bytes) Oct 24 09:06:25 charon[123743]: 04[NET] no socket implementation registered, sending failed Oct 24 09:06:29 charon[123743]: 06[IKE] sending retransmit 1 of request message ID 0, seq 1 Oct 24 09:06:29 charon[123743]: 06[NET] sending packet: from 192.168.1.31 to $vpn_server_ip[500] (532 bytes) Oct 24 09:06:29 charon[123743]: 04[NET] no socket implementation registered, sending failed Oct 24 09:06:32 NetworkManager[806]: [1666595192.2679] vpn[0x556f9cb6c4a0,4ecb50e8-337d-4123-9643-d98ee724343e,"vpn_connection_name"]: failed to connect: 'Timeout w> Oct 24 09:06:35 NetworkManager[124215]: Stopping strongSwan IPsec... Oct 24 09:06:35 charon[123743]: 00[DMN] SIGINT received, shutting down Oct 24 09:06:35 charon[123743]: 00[IKE] destroying IKE_SA in state CONNECTING without notification Oct 24 09:06:35 NetworkManager[123800]: initiating Main Mode IKE_SA 4ecb50e8-337d-4123-9643-d98ee724343e[1] to $vpn_server_ip Oct 24 09:06:35 NetworkManager[123800]: generating ID_PROT request 0 [ SA V V V V V ] Oct 24 09:06:35 NetworkManager[123800]: sending packet: from 192.168.1.31 to $vpn_server_ip[500] (532 bytes) Oct 24 09:06:35 NetworkManager[123800]: sending retransmit 1 of request message ID 0, seq 1 Oct 24 09:06:35 NetworkManager[123800]: sending packet: from 192.168.1.31 to $vpn_server_ip[500] (532 bytes) Oct 24 09:06:35 NetworkManager[123800]: destroying IKE_SA in state CONNECTING without notification Oct 24 09:06:35 NetworkManager[123800]: establishing connection '4ecb50e8-337d-4123-9643-d98ee724343e' failed Oct 24 09:06:35 charon[123743]: 00[IKE] uninstalling bypass policy for 172.17.0.0/16 Oct 24 09:06:35 charon[123743]: 00[IKE] uninstalling bypass policy for 172.26.0.0/16 Oct 24 09:06:35 charon[123743]: 00[IKE] uninstalling bypass policy for 172.27.0.0/16 Oct 24 09:06:35 charon[123743]: 00[IKE] uninstalling bypass policy for 172.28.0.0/16 Oct 24 09:06:35 charon[123743]: 00[IKE] uninstalling bypass policy for 172.29.0.0/16 Oct 24 09:06:35 charon[123743]: 00[IKE] uninstalling bypass policy for 172.30.0.0/16 Oct 24 09:06:35 charon[123743]: 00[IKE] uninstalling bypass policy for 172.31.0.0/16 Oct 24 09:06:35 charon[123743]: 00[IKE] uninstalling bypass policy for 192.168.0.0/24 Oct 24 09:06:35 charon[123743]: 00[IKE] uninstalling bypass policy for 192.168.1.0/24 Oct 24 09:06:35 charon[123743]: 00[IKE] uninstalling bypass policy for 192.168.16.0/20 Oct 24 09:06:35 charon[123743]: 00[IKE] uninstalling bypass policy for 192.168.32.0/20 Oct 24 09:06:35 charon[123743]: 00[IKE] uninstalling bypass policy for ::1/128 Oct 24 09:06:35 charon[123743]: 00[IKE] uninstalling bypass policy for fe80::/64 Oct 24 09:06:35 ipsec_starter[123742]: child 123743 (charon) has quit (exit code 0) Oct 24 09:06:35 ipsec_starter[123742]: Oct 24 09:06:35 ipsec_starter[123742]: charon stopped after 200 ms Oct 24 09:06:35 ipsec_starter[123742]: ipsec starter stopped Oct 24 09:06:35 nm-l2tp-service[123640]: Could not establish IPsec connection. Oct 24 09:06:35 nm-l2tp-service[123640]: g_dbus_method_invocation_take_error: assertion 'error != NULL' failed Oct 24 09:06:36 NetworkManager[806]: [1666595196.5428] manager: (vethe0b3c91): new Veth device (/org/freedesktop/NetworkManager/Devices/526) Oct 24 09:06:36 NetworkManager[806]: [1666595196.5462] manager: (veth7391e85): new Veth device (/org/freedesktop/NetworkManager/Devices/527) Oct 24 09:06:36 NetworkManager[806]: [1666595196.5739] manager: (vetheeb8117): new Veth device (/org/freedesktop/NetworkManager/Devices/528) Oct 24 09:06:36 NetworkManager[806]: [1666595196.5749] manager: (veth40ce739): new Veth device (/org/freedesktop/NetworkManager/Devices/529) Oct 24 09:06:36 NetworkManager[806]: [1666595196.6031] manager: (veth8ddccf9): new Veth device (/org/freedesktop/NetworkManager/Devices/530) Oct 24 09:06:36 NetworkManager[806]: [1666595196.6040] manager: (veth3490f13): new Veth device (/org/freedesktop/NetworkManager/Devices/531) Oct 24 09:06:36 NetworkManager[806]: [1666595196.8555] device (veth40ce739): carrier: link connected Oct 24 09:06:36 NetworkManager[806]: [1666595196.9837] device (veth3490f13): carrier: link connected Oct 24 09:06:36 NetworkManager[806]: [1666595196.9853] device (veth7391e85): carrier: link connected Oct 24 09:06:37 NetworkManager[806]: [1666595197.2296] manager: (vetheeb8117): new Veth device (/org/freedesktop/NetworkManager/Devices/532) Oct 24 09:06:37 NetworkManager[806]: [1666595197.4248] manager: (veth8ddccf9): new Veth device (/org/freedesktop/NetworkManager/Devices/533) ```

I get the same result after disabling experimental strongswan plugins (disabling them and rebooting the system, like you, @dkosovic, suggested in here).

dkosovic commented 1 year ago

Sorry to hear that disabling the experimental strongswan plugins didn't solve the issue.

When I get home, I'll try and update an Arch Linux VM to the latest packages and try to reproduce the issue.

I haven't tested yet with Linux Kernel 6.0 or later, you seem to be using kernel 6.0.2. It's not the first time that a major kernel update has broken IPsec.

tukusejssirs commented 1 year ago

Thanks! :pray:

Indeed, I am using linux@6.0.2.arch1-1. I could make a test with linux-lts@5.15.74-1.

It's not the first time that a major kernel update has broken IPsec.

Could you expand on why does it happen? Isn’t IPsec sort of a standard (or whatever you call it) that should not be broken? What causes (usually) the breaks?

tukusejssirs commented 1 year ago

I have tested it on LTS kernel (with the experimental strongswan extensions disabled), but it fails the same way as described in the OP.

dkosovic commented 1 year ago

Actually, I didn't read the logs properly, I believe the issue is the following in the logs:

charon[123743]: 00[NET] could not open IPv4 socket, IPv4 disabled

As strongswan's charon couldn't open a socket, it subsequently fails.

Check if there is something else listening on UDP port 500 other than charon, e.g. :

$ sudo ss -tunlp | grep :500
udp   UNCONN 0      0                       0.0.0.0:500        0.0.0.0:*    users:(("charon",pid=12238,fd=12))                                                                             
udp   UNCONN 0      0                             *:500              *:*    users:(("charon",pid=12238,fd=10))                                                                             
$ sudo netstat -tunlp | grep :500
udp        0      0 0.0.0.0:500             0.0.0.0:*                           12238/charon        
udp6       0      0 :::500                  :::*                                12238/charon     
tukusejssirs commented 1 year ago

I call it a progress! Thanks! :pray:

Well, something is using it, however, no program/PID is listed with it.

udp   UNCONN 0      0            0.0.0.0:500        0.0.0.0:*
udp   UNCONN 0      0               [::]:500           [::]:*

Now the question is what uses it.


Update

Okay, that was quite easy. Port 500 is used by strongswan service. When I disabled ut (sudo systemctl stop --now strongswan), the port was not used, when I re-enabled the service, the port is used again.

The strongswan service logs this at its startup:

Oct 24 14:44:02 charon-systemd[124566]: PKCS11 module '<name>' lacks library path
Oct 24 14:44:02 charon-systemd[124566]: attr-sql plugin: database URI not set
Oct 24 14:44:02 charon-systemd[124566]: loading ca certificates from '/etc/ipsec.d/cacerts'
Oct 24 14:44:02 charon-systemd[124566]: loading aa certificates from '/etc/ipsec.d/aacerts'
Oct 24 14:44:02 charon-systemd[124566]: loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts'
Oct 24 14:44:02 charon-systemd[124566]: loading attribute certificates from '/etc/ipsec.d/acerts'
Oct 24 14:44:02 charon-systemd[124566]: loading crls from '/etc/ipsec.d/crls'
Oct 24 14:44:02 charon-systemd[124566]: loading secrets from '/etc/ipsec.secrets'
Oct 24 14:44:02 charon-systemd[124566]: loading secrets from '/etc/ipsec.d/ipsec.nm-l2tp.secrets'
Oct 24 14:44:02 charon-systemd[124566]:   loaded IKE secret for %any
Oct 24 14:44:02 charon-systemd[124566]: sql plugin: database URI not set
Oct 24 14:44:02 charon-systemd[124566]: opening triplet file /etc/ipsec.d/triplets.dat failed: No such file or directory
Oct 24 14:44:02 charon-systemd[124566]: loaded 0 RADIUS server configurations
Oct 24 14:44:02 charon-systemd[124566]: HA config misses local/remote address
Oct 24 14:44:02 charon-systemd[124566]: no script for ext-auth script defined, disabled
Oct 24 14:44:02 charon-systemd[124566]: loaded plugins: charon-systemd ldap pkcs11 aesni aes des rc2 sha2 sha1 md5 mgf1 random nonce x509 revocation constraints pubkey pkcs1>
Oct 24 14:44:02 charon-systemd[124566]: dropped capabilities, running as uid 0, gid 0
Oct 24 14:44:02 charon-systemd[124566]: spawning 16 worker threads
Oct 24 14:44:02 swanctl[124583]: no files found matching '/etc/swanctl/conf.d/*.conf'
Oct 24 14:44:02 swanctl[124583]: no authorities found, 0 unloaded
Oct 24 14:44:02 swanctl[124583]: no pools found, 0 unloaded
Oct 24 14:44:02 swanctl[124583]: no connections found, 0 unloaded

Is it correct?

dkosovic commented 1 year ago

strongswan I believe comes with 3 different IPsec daemons, charon, charon-systemd and charon-nm.

NetworkManager-l2tp starts its own instance of charon by issuing ipsec restart which stops any instance of charon and then starts charon and points it to a custom ipsec.conf file. I would have thought ipsec restart would stop charon-systemd, but guess it doesn't on Arch Linux.

If you make sure nothing is using UDP port 500 before NetworkManager-l2tp network connection is started, that should be okay.

tukusejssirs commented 1 year ago

You’re right. When I disable strongswan service, I can enable the VPN (via nmcli). I still need to remove the extra route (see #132), however, it is usable now.

I would have thought ipsec restart would stop charon-systemd, but guess it doesn't on Arch Linux.

I am not sure if I manually enabled the strongswan service during my debugging of this issue (some time ago) or not, thus I suggest to to test if your assumption is correct.

Anyway, you helped me a lot! Thank you very much! :pray:

dkosovic commented 1 year ago

For Arch Linux users that search and find this issue, the old strongswan systemd service (which starts the charon daemon) was renamed from strongswan.service to strongswan-starter.service according to the Arch Linux strongswan wiki:

NetworkManager-l2tp is compatible with strongswan-starter.service, but not strongswan.service. Regardless, there is no need to start either service as NetworkManager-l2tp will start its own instance of the charon daemon.