Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

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

    Scheduled Pinned Locked Moved IPsec
    5 Posts 3 Posters 871 Views
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • M
      markvanderhurk
      last edited by

      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
      K 1 Reply Last reply Reply Quote 0
      • kiokomanK
        kiokoman LAYER 8
        last edited by

        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

        ̿' ̿'\̵͇̿̿\з=(◕_◕)=ε/̵͇̿̿/'̿'̿ ̿
        Please do not use chat/PM to ask for help
        we must focus on silencing this @guest character. we must make up lies and alter the copyrights !
        Don't forget to Upvote with the 👍 button for any post you find to be helpful.

        M 1 Reply Last reply Reply Quote 0
        • K
          Konstanti @markvanderhurk
          last edited by Konstanti

          @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;
          1 Reply Last reply Reply Quote 0
          • M
            markvanderhurk @kiokoman
            last edited by

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

            K 1 Reply Last reply Reply Quote 0
            • K
              Konstanti @markvanderhurk
              last edited by

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

              1 Reply Last reply Reply Quote 0
              • First post
                Last post
              Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.