search

nm-l2tp / NetworkManager-l2tp

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

"Connection established succesfully" followed by "stopping strongSwan IPsec..." #145

Closed ChristopherRabotin closed 4 years ago

ChristopherRabotin commented 4 years ago

This is a bit of an infuriating situation. I'm trying to connect to a SonicWall VPN using strongswan (coworkers who use libreswan from Ubuntu can connect no problem). From journalctl, the connection is established, but then NM stops strongswan. I cannot seem to understand why it does that.

Here are the last few lines of the log (copied from journalctl):

juil. 08 11:47:39 localhost.localdomain NetworkManager[23384]: selected proposal: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ
juil. 08 11:47:39 localhost.localdomain NetworkManager[23384]: CHILD_SA 36a270cb-0850-381b-f848-1c8ae3a31fd0{1} established with SPIs cdc34831_i dc483de2_o and TS 10.0.0.43/32[udp/l2f] === MY_VPN_IP/32[udp/l2f]
juil. 08 11:47:39 localhost.localdomain NetworkManager[23384]: generating QUICK_MODE request 326539277 [ HASH ]
juil. 08 11:47:39 localhost.localdomain NetworkManager[23384]: connection '36a270cb-0850-381b-f848-1c8ae3a31fd0' established successfully
juil. 08 11:47:39 localhost.localdomain charon[23355]: 15[NET] received packet: from MY_VPN_IP[4500] to 10.0.0.43[4500] (92 bytes)
juil. 08 11:47:39 localhost.localdomain charon[23355]: 15[ENC] parsed INFORMATIONAL_V1 request 3247818471 [ HASH D ]
juil. 08 11:47:39 localhost.localdomain charon[23355]: 15[IKE] received DELETE for IKE_SA 36a270cb-0850-381b-f848-1c8ae3a31fd0[1]
juil. 08 11:47:39 localhost.localdomain charon[23355]: 15[IKE] deleting IKE_SA 36a270cb-0850-381b-f848-1c8ae3a31fd0[1] between 10.0.0.43[10.0.0.43]...MY_VPN_IP[MY_VPN_IP]
juil. 08 11:47:39 localhost.localdomain charon[23355]: 15[IKE] deleting IKE_SA 36a270cb-0850-381b-f848-1c8ae3a31fd0[1] between 10.0.0.43[10.0.0.43]...MY_VPN_IP[MY_VPN_IP]
juil. 08 11:47:39 localhost.localdomain NetworkManager[23402]: Stopping strongSwan IPsec...
juil. 08 11:47:39 localhost.localdomain charon[23355]: 00[DMN] signal of type SIGINT received. Shutting down
juil. 08 11:47:39 localhost.localdomain ipsec_starter[23354]: child 23355 (charon) has quit (exit code 0)

Any idea what could be happening? I've attached the full log to this post.

vpn.log

dkosovic commented 4 years ago

Phase 1 (main mode) and phase 2 (quick mode) were successful which should have been enough to establish a successful IPsec connection, then for some reason the SonicWall sends a DELETE payload (which is a regular protocol feature). You will have to check the logs on the SonicWall end as to why the delete was sent from there.

ChristopherRabotin commented 4 years ago

Okay, thanks. I've reached out to the folks who have access to the logs.

Weirdly, I have another issue whereby sometimes repeating the same login attempts without any configuration change has the connection fail. Is that a known issue? Here is what I think is the relevant part of the log:

juil. 08 18:49:53 localhost.localdomain NetworkManager[25381]: generating QUICK_MODE request 449371497 [ HASH SA No ID ID NAT-OA NAT-OA ]
juil. 08 18:49:53 localhost.localdomain NetworkManager[25381]: sending packet: from 10.0.0.43[4500] to MY_VPN_IP[4500] (204 bytes)
juil. 08 18:49:53 localhost.localdomain NetworkManager[25381]: received packet: from MY_VPN_IP[4500] to 10.0.0.43[4500] (92 bytes)
juil. 08 18:49:53 localhost.localdomain NetworkManager[25381]: parsed INFORMATIONAL_V1 request 3769144750 [ HASH D ]
juil. 08 18:49:53 localhost.localdomain NetworkManager[25381]: received DELETE for IKE_SA 36a270cb-0850-381b-f848-1c8ae3a31fd0[1]
juil. 08 18:49:53 localhost.localdomain NetworkManager[25381]: deleting IKE_SA 36a270cb-0850-381b-f848-1c8ae3a31fd0[1] between 10.0.0.43[10.0.0.43]...MY_VPN_IP[MY_VPN_IP]
juil. 08 18:49:53 localhost.localdomain NetworkManager[25381]: establishing connection '36a270cb-0850-381b-f848-1c8ae3a31fd0' failed
juil. 08 18:49:53 localhost.localdomain charon[25353]: 07[NET] received packet: from MY_VPN_IP[500] to 10.0.0.43[500] (116 bytes)
juil. 08 18:49:53 localhost.localdomain charon[25353]: 07[ENC] parsed ID_PROT response 0 [ SA V V ]
juil. 08 18:49:53 localhost.localdomain charon[25353]: 07[ENC] received unknown vendor ID: 5b:36:2b:c8:20:f6:00:07
juil. 08 18:49:53 localhost.localdomain charon[25353]: 07[IKE] received NAT-T (RFC 3947) vendor ID
juil. 08 18:49:53 localhost.localdomain charon[25353]: 07[CFG] selected proposal: IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_2048

One of the key differences I've noted from comparing both logs is that in the one which establishes a connection and then fails, the log has the following lines (what do those mean?):

juil. 08 11:47:39 localhost.localdomain charon[23355]: 14[NET] received packet: from MY_VPN_IP[4500] to 10.0.0.43[4500] (188 bytes)
juil. 08 11:47:39 localhost.localdomain charon[23355]: 14[ENC] parsed QUICK_MODE response 326539277 [ HASH SA No ID ID NAT-OA NAT-OA ]
juil. 08 11:47:39 localhost.localdomain charon[23355]: 14[CFG] selected proposal: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ
juil. 08 11:47:39 localhost.localdomain charon[23355]: 14[IKE] CHILD_SA 36a270cb-0850-381b-f848-1c8ae3a31fd0{1} established with SPIs cdc34831_i dc483de2_o and TS 10.0.0.43/32[udp/l2f] === MY_VPN_IP/32[udp/l2f]
juil. 08 11:47:39 localhost.localdomain charon[23355]: 14[IKE] CHILD_SA 36a270cb-0850-381b-f848-1c8ae3a31fd0{1} established with SPIs cdc34831_i dc483de2_o and TS 10.0.0.43/32[udp/l2f] === MY_VPN_IP/32[udp/l2f]

Whereas for the "failure to establish connection" log, those lines are instead the following:

juil. 08 18:49:53 localhost.localdomain charon[25353]: 15[NET] received packet: from MY_VPN_IP[4500] to 10.0.0.43[4500] (92 bytes)
juil. 08 18:49:53 localhost.localdomain charon[25353]: 15[ENC] parsed INFORMATIONAL_V1 request 3769144750 [ HASH D ]
juil. 08 18:49:53 localhost.localdomain charon[25353]: 15[IKE] received DELETE for IKE_SA 36a270cb-0850-381b-f848-1c8ae3a31fd0[1]
juil. 08 18:49:53 localhost.localdomain charon[25353]: 15[IKE] deleting IKE_SA 36a270cb-0850-381b-f848-1c8ae3a31fd0[1] between 10.0.0.43[10.0.0.43]...MY_VPN_IP[MY_VPN_IP]
juil. 08 18:49:53 localhost.localdomain charon[25353]: 15[IKE] deleting IKE_SA 36a270cb-0850-381b-f848-1c8ae3a31fd0[1] between 10.0.0.43[10.0.0.43]...MY_VPN_IP[MY_VPN_IP]
juil. 08 18:49:53 localhost.localdomain charon[25353]: 15[IKE] initiating Main Mode IKE_SA 36a270cb-0850-381b-f848-1c8ae3a31fd0[2] to MY_VPN_IP
juil. 08 18:49:53 localhost.localdomain charon[25353]: 15[IKE] initiating Main Mode IKE_SA 36a270cb-0850-381b-f848-1c8ae3a31fd0[2] to MY_VPN_IP

What would cause that issue if the configuration is identical? Thanks for your help

vpn.fail.log

dkosovic commented 4 years ago

Sorry I'm not that familiar with strongSwan, but I think Security Parameter Index (SPI) are local identifiers that get generated when a connection is established.

Are you using openSUSE Tumbleweed? I'll see if I'm able to establish a connection after I upgrade my openSUSE Tumbleweed VM.

ChristopherRabotin commented 4 years ago

Okay. That would be helpful. Yes, I'm using Tumbleweed, with version 5.2.8 of strongswan iirc.

dkosovic commented 4 years ago

I updated my Tumbleweed to the latest packages and was still successful with my existing VPN connections.

I was going to ask you to try libreswan RPM I built, unfortunately although the libreswan RPM built on my PC works fine, the one built on https://build.opensuse.org fails with the following assertion:

ABORT: ASSERTION FAILED: ptr != NULL (in pfree() at alloc.c:145)

Still looking into it, I'm guessing the compiler optimization or hardening is different, but not sure yet.

ChristopherRabotin commented 4 years ago

Okay, thanks for looking into this. I think it's a SonicWall configuration which Strongswan does not like. Some coworkers can connect with libreswan though, but as you saw, that package is not available on tumbleweed.

Christopher Rabotin.

dkosovic commented 4 years ago

Could you try installing libreswan with :

sudo rpm -e strongswan-ipsec strongswan-libs0
sudo rm -rf /etc/ipsec*

wget https://download.opensuse.org/repositories/home:/dkosovic/openSUSE_Tumbleweed/x86_64/libreswan-3.32-1.1.x86_64.rpm
sudo zypper install libreswan-3.32-1.1.x86_64.rpm
rm libreswan-3.32-1.1.x86_64.rpm

I noticed earlier this year that NetworkManager-libreswan (which needs libreswan) had been added to the openSUSE Tumbleweed official repository, yet no libreswan package got added, not sure how it got through.

ChristopherRabotin commented 4 years ago

@dkosovic DUDE! Using Libreswan worked! I've been struggling with this problem since February, gave up, and wanted to give it a try again to no avail. So I guess the problem was indeed, using strongswan instead of libreswan. Can I buy you a coffee?