IPSec broken after update from 2.3.1 to 2.4.4 - unable to install inbound IPsec SA (SAD) in kernel
-
Hi,
Last week, our pfSense instance (on a Netgate XG-2758) somehow stopped working. A reboot only fixed it partly, there was weird behaviour (connections were unreliable). I decided to upgrade from the 2.3.1 version that was installed at that time to the most current version, 2.4.4
However, after the upgrade, at least one of our 5 site-to-site VPNs - using IPSec - is not working anymore. I can see from the IPSec logging that something is going wrong, but I'm unable to understand it well. I really don't know what to do, as everything I found regarding the error message is really old.
I have masked the IP addresses: 212.999.206.249 is the incoming (customer) connection and 95.999.89.170 is our pfSense instance.
This is what caught my attention: unable to install inbound IPsec SA (SAD) in kernel
Anyone over here who knows how to proceed with this?
Thanks, Mark
Oct 16 10:13:46 charon 13[IKE] <con3000|263276> IKE_SA con3000[263276] state change: DELETING => DESTROYING Oct 16 10:13:46 charon 13[IKE] <con3000|263276> IKE_SA con3000[263276] state change: DELETING => DELETING Oct 16 10:13:46 charon 13[IKE] <con3000|263276> IKE_SA con3000[263276] state change: ESTABLISHED => DELETING Oct 16 10:13:46 charon 13[IKE] <con3000|263276> deleting IKE_SA con3000[263276] between 95.999.89.170[95.999.89.170]...212.999.206.249[212.999.206.249] Oct 16 10:13:46 charon 13[IKE] <con3000|263276> received DELETE for IKE_SA con3000[263276] Oct 16 10:13:46 charon 13[ENC] <con3000|263276> parsed INFORMATIONAL_V1 request 1182243030 [ HASH D ] Oct 16 10:13:46 charon 13[NET] <con3000|263276> received packet: from 212.999.206.249[500] to 95.999.89.170[500] (92 bytes) Oct 16 10:13:46 charon 12[IKE] <con3000|263276> nothing to initiate Oct 16 10:13:46 charon 12[IKE] <con3000|263276> activating new tasks Oct 16 10:13:46 charon 12[NET] <con3000|263276> sending packet: from 95.999.89.170[500] to 212.999.206.249[500] (76 bytes) Oct 16 10:13:46 charon 12[ENC] <con3000|263276> generating INFORMATIONAL_V1 request 1410711545 [ HASH D ] Oct 16 10:13:46 charon 12[IKE] <con3000|263276> sending DELETE for ESP CHILD_SA with SPI 1d780c77 Oct 16 10:13:46 charon 12[IKE] <con3000|263276> activating QUICK_DELETE task Oct 16 10:13:46 charon 12[IKE] <con3000|263276> activating new tasks Oct 16 10:13:46 charon 12[IKE] <con3000|263276> queueing QUICK_DELETE task Oct 16 10:13:46 charon 12[KNL] <con3000|263276> unable to delete SAD entry with SPI c59375d7: No such file or directory (2) Oct 16 10:13:46 charon 12[CHD] <con3000|263276> CHILD_SA con3002{271405} state change: INSTALLING => DESTROYING Oct 16 10:13:46 charon 12[IKE] <con3000|263276> unable to install inbound IPsec SA (SAD) in kernel Oct 16 10:13:46 charon 12[CHD] <con3000|263276> SPI 0x1d780c77, src 95.999.89.170 dst 212.999.206.249 Oct 16 10:13:46 charon 12[CHD] <con3000|263276> adding outbound ESP SA Oct 16 10:13:46 charon 12[KNL] <con3000|263276> unable to add SAD entry with SPI c59375d7 Oct 16 10:13:46 charon 12[KNL] <con3000|263276> error sending to PF_KEY socket: Invalid argument Oct 16 10:13:46 charon 12[CHD] <con3000|263276> SPI 0xc59375d7, src 212.999.206.249 dst 95.999.89.170 Oct 16 10:13:46 charon 12[CHD] <con3000|263276> adding inbound ESP SA Oct 16 10:13:46 charon 12[CHD] <con3000|263276> using HMAC_MD5_96 for integrity Oct 16 10:13:46 charon 12[CHD] <con3000|263276> using AES_CBC for encryption Oct 16 10:13:46 charon 12[CHD] <con3000|263276> CHILD_SA con3002{271405} state change: CREATED => INSTALLING Oct 16 10:13:46 charon 12[ENC] <con3000|263276> parsed QUICK_MODE request 852041380 [ HASH ] Oct 16 10:13:46 charon 12[NET] <con3000|263276> received packet: from 212.999.206.249[500] to 95.999.89.170[500] (76 bytes) Oct 16 10:13:46 charon 12[NET] <con3000|263276> sending packet: from 95.999.89.170[500] to 212.999.206.249[500] (380 bytes) Oct 16 10:13:46 charon 12[ENC] <con3000|263276> generating QUICK_MODE response 852041380 [ HASH SA No KE ID ID ] Oct 16 10:13:46 charon 12[IKE] <con3000|263276> received 4608000000 lifebytes, configured 0 Oct 16 10:13:46 charon 12[CFG] <con3000|263276> selected proposal: ESP:AES_CBC_256/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ Oct 16 10:13:46 charon 12[CFG] <con3000|263276> configured proposals: ESP:AES_CBC_256/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ Oct 16 10:13:46 charon 12[CFG] <con3000|263276> received proposals: ESP:AES_CBC_256/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ Oct 16 10:13:46 charon 12[CFG] <con3000|263276> proposal matches Oct 16 10:13:46 charon 12[CFG] <con3000|263276> selecting proposal: Oct 16 10:13:46 charon 12[CFG] <con3000|263276> config: 172.21.245.157/32|172.16.3.2/32, received: 172.21.245.157/32|/0 => match: 172.21.245.157/32|172.16.3.2/32 Oct 16 10:13:46 charon 12[CFG] <con3000|263276> selecting traffic selectors for us: Oct 16 10:13:46 charon 12[CFG] <con3000|263276> config: 172.20.57.87/32|/0, received: 172.20.57.87/32|/0 => match: 172.20.57.87/32|/0 Oct 16 10:13:46 charon 12[CFG] <con3000|263276> selecting traffic selectors for other: Oct 16 10:13:46 charon 12[CFG] <con3000|263276> found matching child config "con3002" with prio 10 Oct 16 10:13:46 charon 12[CFG] <con3000|263276> 172.20.128.103/32|/0 Oct 16 10:13:46 charon 12[CFG] <con3000|263276> proposing traffic selectors for other: Oct 16 10:13:46 charon 12[CFG] <con3000|263276> 172.21.245.157/32|172.16.3.2/32 Oct 16 10:13:46 charon 12[CFG] <con3000|263276> proposing traffic selectors for us: Oct 16 10:13:46 charon 12[CFG] <con3000|263276> candidate "con3002" with prio 5+5 Oct 16 10:13:46 charon 12[CFG] <con3000|263276> 172.20.57.87/32|/0 Oct 16 10:13:46 charon 12[CFG] <con3000|263276> proposing traffic selectors for other: Oct 16 10:13:46 charon 12[CFG] <con3000|263276> 172.21.245.157/32|172.16.3.2/32 Oct 16 10:13:46 charon 12[CFG] <con3000|263276> proposing traffic selectors for us: Oct 16 10:13:46 charon 12[CFG] <con3000|263276> 172.20.57.87/32|/0 Oct 16 10:13:46 charon 12[CFG] <con3000|263276> proposing traffic selectors for other: Oct 16 10:13:46 charon 12[CFG] <con3000|263276> 172.21.245.156/32|172.16.3.3/32 Oct 16 10:13:46 charon 12[CFG] <con3000|263276> proposing traffic selectors for us: Oct 16 10:13:46 charon 12[CFG] <con3000|263276> 172.20.128.103/32|/0 Oct 16 10:13:46 charon 12[CFG] <con3000|263276> proposing traffic selectors for other: Oct 16 10:13:46 charon 12[CFG] <con3000|263276> 172.21.245.156/32|172.16.3.3/32 Oct 16 10:13:46 charon 12[CFG] <con3000|263276> proposing traffic selectors for us: Oct 16 10:13:46 charon 12[CFG] <con3000|263276> looking for a child config for 172.21.245.157/32|/0 === 172.20.57.87/32|/0 Oct 16 10:13:46 charon 12[ENC] <con3000|263276> parsed QUICK_MODE request 852041380 [ HASH SA No KE ID ID N(INITIAL_CONTACT) ] Oct 16 10:13:46 charon 12[NET] <con3000|263276> received packet: from 212.999.206.249[500] to 95.999.89.170[500] (396 bytes) Oct 16 10:13:46 charon 13[NET] <con3000|263276> sending packet: from 95.999.89.170[500] to 212.999.206.249[500] (76 bytes) Oct 16 10:13:46 charon 13[ENC] <con3000|263276> generating ID_PROT response 0 [ ID HASH ] Oct 16 10:13:46 charon 13[IKE] <con3000|263276> maximum IKE_SA lifetime 86279s Oct 16 10:13:46 charon 13[IKE] <con3000|263276> scheduling reauthentication in 85739s Oct 16 10:13:46 charon 13[IKE] <con3000|263276> IKE_SA con3000[263276] state change: CONNECTING => ESTABLISHED Oct 16 10:13:46 charon 13[IKE] <con3000|263276> IKE_SA con3000[263276] established between 95.999.89.170[95.999.89.170]...212.999.206.249[212.999.206.249] Oct 16 10:13:46 charon 13[CFG] <263276> selected peer config "con3000" Oct 16 10:13:46 charon 13[CFG] <263276> candidate "con3000", match: 1/20/3100 (me/other/ike) Oct 16 10:13:46 charon 13[CFG] <263276> looking for pre-shared key peer configs matching 95.999.89.170...212.999.206.249[212.999.206.249] Oct 16 10:13:46 charon 13[IKE] <263276> received DPD vendor ID Oct 16 10:13:46 charon 13[ENC] <263276> parsed ID_PROT request 0 [ ID HASH V ] Oct 16 10:13:46 charon 13[NET] <263276> received packet: from 212.999.206.249[500] to 95.999.89.170[500] (92 bytes) Oct 16 10:13:46 charon 13[NET] <263276> sending packet: from 95.999.89.170[500] to 212.999.206.249[500] (308 bytes) Oct 16 10:13:46 charon 13[ENC] <263276> generating ID_PROT response 0 [ KE No NAT-D NAT-D ] Oct 16 10:13:46 charon 13[CFG] <263276> candidate "con3000", match: 1/1/3100 (me/other/ike) Oct 16 10:13:46 charon 13[ENC] <263276> received unknown vendor ID: 1f:07:f7:0e:aa:65:14:d3:b0:fa:96:54:2a:50:01:00 Oct 16 10:13:46 charon 13[ENC] <263276> received unknown vendor ID: 75:4f:7a:7c:5a:23:67:67:34:b5:c5:20:5a:96:e6:1d Oct 16 10:13:46 charon 13[IKE] <263276> received XAuth vendor ID Oct 16 10:13:46 charon 13[IKE] <263276> received Cisco Unity vendor ID Oct 16 10:13:46 charon 13[ENC] <263276> parsed ID_PROT request 0 [ KE No V V V V NAT-D NAT-D ] Oct 16 10:13:46 charon 13[NET] <263276> received packet: from 212.999.206.249[500] to 95.999.89.170[500] (368 bytes) Oct 16 10:13:46 charon 13[NET] <263276> sending packet: from 95.999.89.170[500] to 212.999.206.249[500] (184 bytes) Oct 16 10:13:46 charon 13[ENC] <263276> generating ID_PROT response 0 [ SA V V V V V ] Oct 16 10:13:46 charon 13[IKE] <263276> sending NAT-T (RFC 3947) vendor ID Oct 16 10:13:46 charon 13[IKE] <263276> sending FRAGMENTATION vendor ID Oct 16 10:13:46 charon 13[IKE] <263276> sending Cisco Unity vendor ID Oct 16 10:13:46 charon 13[IKE] <263276> sending DPD vendor ID Oct 16 10:13:46 charon 13[IKE] <263276> sending XAuth vendor ID Oct 16 10:13:46 charon 13[CFG] <263276> selected proposal: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1536 Oct 16 10:13:46 charon 13[CFG] <263276> configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1536 Oct 16 10:13:46 charon 13[CFG] <263276> received proposals: IKE:DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024, IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024, 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/MODP_1536, IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1536 Oct 16 10:13:46 charon 13[CFG] <263276> proposal matches Oct 16 10:13:46 charon 13[CFG] <263276> selecting proposal: Oct 16 10:13:46 charon 13[CFG] <263276> no acceptable ENCRYPTION_ALGORITHM found Oct 16 10:13:46 charon 13[CFG] <263276> selecting proposal: Oct 16 10:13:46 charon 13[CFG] <263276> no acceptable ENCRYPTION_ALGORITHM found Oct 16 10:13:46 charon 13[CFG] <263276> selecting proposal: Oct 16 10:13:46 charon 13[IKE] <263276> IKE_SA (unnamed)[263276] state change: CREATED => CONNECTING Oct 16 10:13:46 charon 13[IKE] <263276> 212.999.206.249 is initiating a Main Mode IKE_SA Oct 16 10:13:46 charon 13[IKE] <263276> received FRAGMENTATION vendor ID Oct 16 10:13:46 charon 13[IKE] <263276> received NAT-T (RFC 3947) vendor ID Oct 16 10:13:46 charon 13[IKE] <263276> received draft-ietf-ipsec-nat-t-ike-03 vendor ID Oct 16 10:13:46 charon 13[IKE] <263276> received draft-ietf-ipsec-nat-t-ike-02\n vendor ID Oct 16 10:13:46 charon 13[CFG] <263276> found matching ike config: 95.999.89.170...212.999.206.249 with prio 3100 Oct 16 10:13:46 charon 13[CFG] <263276> candidate: 95.999.89.170...212.999.206.249, prio 3100 Oct 16 10:13:46 charon 13[CFG] <263276> looking for an IKEv1 config for 95.999.89.170...212.999.206.249 Oct 16 10:13:46 charon 13[ENC] <263276> parsed ID_PROT request 0 [ SA V V V V ] Oct 16 10:13:46 charon 13[NET] <263276> received packet: from 212.999.206.249[500] to 95.999.89.170[500] (360 bytes) Oct 16 10:13:45 charon 13[IKE] <con3000|263275> IKE_SA con3000[263275] state change: DELETING => DESTROYING Oct 16 10:13:45 charon 13[IKE] <con3000|263275> IKE_SA con3000[263275] state change: DELETING => DELETING Oct 16 10:13:45 charon 13[IKE] <con3000|263275> IKE_SA con3000[263275] state change: ESTABLISHED => DELETING Oct 16 10:13:45 charon 13[IKE] <con3000|263275> deleting IKE_SA con3000[263275] between 95.999.89.170[95.999.89.170]...212.999.206.249[212.999.206.249] Oct 16 10:13:45 charon 13[IKE] <con3000|263275> received DELETE for IKE_SA con3000[263275] Oct 16 10:13:45 charon 13[ENC] <con3000|263275> parsed INFORMATIONAL_V1 request 2890542684 [ HASH D ] Oct 16 10:13:45 charon 13[NET] <con3000|263275> received packet: from 212.999.206.249[500] to 95.999.89.170[500] (92 bytes) Oct 16 10:13:45 charon 13[IKE] <con3000|263275> nothing to initiate Oct 16 10:13:45 charon 13[IKE] <con3000|263275> activating new tasks
-
maybe some algorithms have been removed in the meantime
sometimes something stop working for me on 2.5.0 devel after an upgrade, when this happen i click save to the page (ipsec/openvpn etc) to regenerate the configuration, usually stuff start working again after this
-
It is a Strongswan error that the number of bytes written to the PF_KEY socket is less than the message length ( when Strongswan adds SA with SPI 0xc59375d7 to the SADB ). But here is why such message appeared, me it is unclear.
len = send(socket, in, in_len, 0); if (len != in_len) { if (errno == EINTR) { /* interrupted, try again */ continue; } this->mutex_pfkey->unlock(this->mutex_pfkey); DBG1(DBG_KNL, "error sending to PF_KEY socket: %s", strerror(errno)); return FAILED;
-
@kiokoman Thank you for your suggestion. I have saved every settings page of the IPSec connections again. It seems some things have changed; for the specific connection I was testing, it looks like there is something happening in phase 2, as I see errors appearing containing:
generating INFORMATIONAL_V1 request 1 [ HASH N(INVAL_ID)
and
no matching CHILD_SA config found
I have now asked the connecting customer to provide me the configuration they are using, to see i.e. if they are using values that do not exist anymore in this version of pfSense.@Konstanti Thank you for finding that. Although it is unclear to me as well, maybe this helps other people to indicate the right direction to go forward with this.
-
Maybe it's some kind of internal system failure, because I have not met with such an error yet. And I don't think that Strongswan is not able to count the length of the message (sadb_msg).