4. IPSec broken after update from 2.3.1 to 2.4.4 - unable to install inbound IPsec SA (SAD) in kernel

IPSec broken after update from 2.3.1 to 2.4.4 - unable to install inbound IPsec SA (SAD) in kernel

  • M

    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
    0
    K
     1 Reply
  • LAYER 8

    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

    0
    M
     1 Reply
  • K

    @markvanderhurk

    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;
    0
  • M

    @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.

    0
    K
     1 Reply
  • K

    @markvanderhurk

    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).

    0
Log in to reply
 

Products

Services

Support

News

Resources

Company

Our Mission

We provide leading-edge network security at a fair price - regardless of organizational size or network sophistication. We believe that an open-source security model offers disruptive pricing along with the agility required to quickly address emerging threats.

Subscribe to our Newsletter

Product information, software announcements, and special offers. See our newsletter archive for past announcements.

© Copyright 2019 Rubicon Communications, LLC | Privacy Policy