search

hwdsl2 / setup-ipsec-vpn

Scripts to build your own IPsec VPN server, with IPsec/L2TP, Cisco IPsec and IKEv2
Other
25.39k stars 6.34k forks source link

EXPECTATION FAILED: proposal->remote_spi.size <= sizeof(proposal->remote_spi.size) #1144

Closed johnlukeabe closed 2 years ago

johnlukeabe commented 2 years ago

Hi there,

I am using libreswan v3.29. I configured tunnel between two devices for test. device1 and device2 are wired directly. When I started the libreswan, it works. But when time passed, I saw the two kinds of EXPECTATION FAILED messages when rekeying happens.

_EXPECTATION FAILED: proposal->remote_spi.size <= sizeof(proposal->remote_spi.size) (in print_proposal() at ikev2_spdb_struct.c:351) EXPECTATION FAILED: not replacing stale IKE SA #2; as already got a newer #5 (in v2_event_sa_rekey() at ikev2parent.c:6373)

After the second error message, it was disconnected. So I did 'ipsec auto --up device1' and then the connection was restored. But I still saw the first EXPECTATION FAILED message after 'ipsec auto --up' command.

I reduced ikelifetime to see the error message quickly.

Is this due to misconfiguration? When do these error messages occur? How can I solve this issue and remove the expectation failed message?

Configuration(/etc/ipsec.conf)

Device 1:
conn device1
        hostaddrfamily=ipv4
        authby=secret
        auto=start
        phase2=esp
        phase2alg=aes256-sha2;dh21
        ike=aes256-sha2;dh21
        ikelifetime=60s
        keyingtries=%forever
        ikev2=yes
        left=192.168.100.149
        leftid=192.168.100.149
        leftnexthop=192.168.100.142
        leftsubnet=1.1.100.0/24
        leftupdown="ipsec _updown --route yes"
        dpddelay=30
        dpdtimeout=120
        dpdaction=restart
        right=192.168.100.142
        rightid=192.168.100.142
        rightnexthop=192.168.100.149
        rightsubnet=1.1.200.0/24
        type=tunnel
        rekeymargin=10s
        rekeyfuzz=0%
----------------------------------------------------

Device 2:
conn device2
        hostaddrfamily=ipv4
        authby=secret
        auto=start
        phase2=esp
        phase2alg=aes256-sha2;dh21
        ike=aes256-sha2;dh21
        ikelifetime=60s
        keyingtries=%forever
        ikev2=yes
        left=192.168.100.142
        leftid=192.168.100.142
        leftnexthop=192.168.100.149
        leftsubnet=1.1.200.0/24
        rightupdown="ipsec _updown --route yes"
        dpddelay=30
        dpdtimeout=120
        dpdaction=restart
        right=192.168.100.149
        rightid=192.168.100.149
        rightnexthop=192.168.100.142
        rightsubnet=1.1.100.0/24
        type=tunnel
        rekeymargin=10s
        rekeyfuzz=0%

Log - device1

Apr 01 16:18:30 test pluto[12744]: "device1" #2: received duplicate IKE_AUTH message request (Message ID 1, fragment 1); retransmitting response
Apr 01 16:18:30 test pluto[12744]: "device1" #1: ISAKMP_v2_IKE_AUTH message response with Message ID 1 has no matching SA
Apr 01 16:18:30 test pluto[12744]: "device1" #1: ISAKMP_v2_IKE_AUTH message response with Message ID 1 has no matching SA
Apr 01 16:18:30 test pluto[12744]: "device1" #1: ISAKMP_v2_IKE_AUTH message response with Message ID 1 has no matching SA
Apr 01 16:18:30 test pluto[12744]: "device1" #1: ISAKMP_v2_IKE_AUTH message response with Message ID 1 has no matching SA
Apr 01 16:18:30 test pluto[12744]: "device1" #1: ISAKMP_v2_IKE_AUTH message response with Message ID 1 has no matching SA
**Apr 01 16:18:59 test pluto[12744]: "device1" #1: EXPECTATION FAILED: proposal->remote_spi.size <= sizeof(proposal->remote_spi.size) (in print_proposal() at ikev2_spdb_struct.c:351)**
Apr 01 16:18:59 test pluto[12744]: "device1" #1: proposal 1:IKE:SPI=1d12beb9;ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=ECP_521 chosen from remote proposals 1:IKE:ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=ECP_521[first-match]
Apr 01 16:18:59 test pluto[12744]: "device1" #5: STATE_PARENT_R2: received v2I2, PARENT SA established
Apr 01 16:19:00 test pluto[12744]: "device1" #1: deleting state (STATE_IKESA_DEL) aged 33.281s and NOT sending notification
**Apr 01 16:19:24 test pluto[12744]: "device1" #2: EXPECTATION FAILED: not replacing stale IKE SA #2; as already got a newer #5 (in v2_event_sa_rekey() at ikev2_parent.c:6373)**
Apr 01 16:19:24 test pluto[12744]: "device1" #4: deleting other state #4 (STATE_V2_IPSEC_R) aged 54.895s and sending notification
Apr 01 16:19:24 test pluto[12744]: "device1" #4: ESP traffic information: in=0B out=0B
Apr 01 16:19:24 test pluto[12744]: "device1" #2: deleting state (STATE_PARENT_R2) aged 55.937s and sending notification
Apr 01 16:19:24 test pluto[12744]: packet from 192.168.100.142:500: ISAKMP_v2_INFORMATIONAL message response has no matching IKE SA
Apr 01 16:19:24 test pluto[12744]: packet from 192.168.100.142:500: ISAKMP_v2_INFORMATIONAL message response has no matching IKE SA
Apr 01 16:19:54 test pluto[12744]: "device1" #5: initiate rekey of IKEv2 CREATE_CHILD_SA IKE Rekey
Apr 01 16:19:54 test pluto[12744]: "device1" #6: STATE_V2_REKEY_IKE_I: STATE_V2_REKEY_IKE_I
Apr 01 16:19:54 test pluto[12744]: "device1" #6: rekeyed #5 STATE_V2_REKEY_IKE_I and expire it remaining life 4s
Apr 01 16:19:54 test pluto[12744]: "device1" #6: STATE_PARENT_I3: PARENT SA established
Apr 01 16:19:55 test pluto[12744]: "device1" #5: deleting state (STATE_PARENT_R2) aged 56.455s and sending notification
Apr 01 16:19:55 test pluto[12744]: packet from 192.168.100.142:500: ISAKMP_v2_INFORMATIONAL message response has no matching IKE SA
**Apr 01 16:20:24 test pluto[12744]: "device1" #6: EXPECTATION FAILED: proposal->remote_spi.size <= sizeof(proposal->remote_spi.size) (in print_proposal() at ikev2_spdb_struct.c:351)**
Apr 01 16:20:24 test pluto[12744]: "device1" #6: proposal 1:IKE:SPI=23ebc903;ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=ECP_521 chosen from remote proposals 1:IKE:ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=ECP_521[first-match]
Apr 01 16:20:24 test pluto[12744]: "device1" #7: STATE_PARENT_R2: received v2I2, PARENT SA established
Apr 01 16:20:25 test pluto[12744]: "device1" #6: deleting state (STATE_IKESA_DEL) aged 31.431s and NOT sending notification
Apr 01 16:21:19 test pluto[12744]: "device1" #7: initiate rekey of IKEv2 CREATE_CHILD_SA IKE Rekey
Apr 01 16:21:19 test pluto[12744]: "device1" #8: STATE_V2_REKEY_IKE_I: STATE_V2_REKEY_IKE_I
Apr 01 16:21:20 test pluto[12744]: "device1" #8: rekeyed #7 STATE_V2_REKEY_IKE_I and expire it remaining life 4s
Apr 01 16:21:20 test pluto[12744]: "device1" #8: STATE_PARENT_I3: PARENT SA established
Apr 01 16:21:21 test pluto[12744]: "device1" #7: deleting state (STATE_PARENT_R2) aged 56.486s and sending notification
Apr 01 16:21:21 test pluto[12744]: packet from 192.168.100.142:500: ISAKMP_v2_INFORMATIONAL message response has no matching IKE SA
**Apr 01 16:21:50 test pluto[12744]: "device1" #8: EXPECTATION FAILED: proposal->remote_spi.size <= sizeof(proposal->remote_spi.size) (in print_proposal() at ikev2_spdb_struct.c:351)**
Apr 01 16:21:50 test pluto[12744]: "device1" #8: proposal 1:IKE:SPI=3ed4a705;ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=ECP_521 chosen from remote proposals 1:IKE:ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=ECP_521[first-match]
Apr 01 16:21:50 test pluto[12744]: "device1" #9: STATE_PARENT_R2: received v2I2, PARENT SA established
Apr 01 16:21:51 test pluto[12744]: "device1" #8: deleting state (STATE_IKESA_DEL) aged 31.577s and NOT sending notification
Apr 01 16:22:45 test pluto[12744]: "device1" #9: initiate rekey of IKEv2 CREATE_CHILD_SA IKE Rekey
Apr 01 16:22:45 test pluto[12744]: "device1" #10: STATE_V2_REKEY_IKE_I: STATE_V2_REKEY_IKE_I
Apr 01 16:22:45 test pluto[12744]: "device1" #10: rekeyed #9 STATE_V2_REKEY_IKE_I and expire it remaining life 4s
Apr 01 16:22:45 test pluto[12744]: "device1" #10: STATE_PARENT_I3: PARENT SA established
Apr 01 16:22:46 test pluto[12744]: "device1" #9: deleting state (STATE_PARENT_R2) aged 56.475s and sending notification
Apr 01 16:22:46 test pluto[12744]: packet from 192.168.100.142:500: ISAKMP_v2_INFORMATIONAL message response has no matching IKE SA
**Apr 01 16:23:15 test pluto[12744]: "device1" #10: EXPECTATION FAILED: proposal->remote_spi.size <= sizeof(proposal->remote_spi.size) (in print_proposal() at ikev2_spdb_struct.c:351)**
Apr 01 16:23:15 test pluto[12744]: "device1" #10: proposal 1:IKE:SPI=2313ddb5;ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=ECP_521 chosen from remote proposals 1:IKE:ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=ECP_521[first-match]
Apr 01 16:23:15 test pluto[12744]: "device1" #11: STATE_PARENT_R2: received v2I2, PARENT SA established
Apr 01 16:23:16 test pluto[12744]: "device1" #10: deleting state (STATE_IKESA_DEL) aged 31.411s and NOT sending notification
Apr 01 16:23:30 test pluto[12744]: destroying root certificate cache

Log - device2

Apr 01 16:18:30 test2 pluto[22988]: "device2" #2: received duplicate IKE_AUTH message request (Message ID 1, fragment 1); retransmitting response
Apr 01 16:18:30 test2 pluto[22988]: "device2" #1: ISAKMP_v2_IKE_AUTH message response with Message ID 1 has no matching SA                                                                                                                                                                                                                                                   
Apr 01 16:18:30 test2 pluto[22988]: "device2" #1: ISAKMP_v2_IKE_AUTH message response with Message ID 1 has no matching SA                                                                                                                                                                                                                                                   
Apr 01 16:18:30 test2 pluto[22988]: "device2" #1: ISAKMP_v2_IKE_AUTH message response with Message ID 1 has no matching SA
Apr 01 16:18:30 test2 pluto[22988]: "device2" #1: ISAKMP_v2_IKE_AUTH message response with Message ID 1 has no matching SA  
Apr 01 16:18:30 test2 pluto[22988]: "device2" #1: ISAKMP_v2_IKE_AUTH message response with Message ID 1 has no matching SA
Apr 01 16:18:58 test2 pluto[22988]: "device2" #2: initiate rekey of IKEv2 CREATE_CHILD_SA IKE Rekey
Apr 01 16:18:59 test2 pluto[22988]: "device2" #5: STATE_V2_REKEY_IKE_I: STATE_V2_REKEY_IKE_I
Apr 01 16:18:59 test2 pluto[22988]: "device2" #5: rekeyed #2 STATE_V2_REKEY_IKE_I and expire it remaining life 269s
Apr 01 16:18:59 test2 pluto[22988]: "device2" #5: STATE_PARENT_I3: PARENT SA established
Apr 01 16:19:00 test2 pluto[22988]: "device2" #2: deleting state (STATE_PARENT_R2) aged 32.200s and sending notification
Apr 01 16:19:00 test2 pluto[22988]: packet from 192.168.100.149:500: ISAKMP_v2_INFORMATIONAL message response has no matching IKE SA
Apr 01 16:19:23 test2 pluto[22988]: "device2" #1: received Delete SA payload: replace IPsec State #3 now
Apr 01 16:19:23 test2 pluto[22988]: "device2" #1: STATE_PARENT_I3: PARENT SA established
Apr 01 16:19:23 test2 pluto[22988]: "device2" #3: deleting other state #3 (STATE_CHILDSA_DEL) aged 55.497s and NOT sending notification
Apr 01 16:19:23 test2 pluto[22988]: "device2" #1: deleting state (STATE_IKESA_DEL) aged 56.355s and NOT sending notification
**Apr 01 16:19:54 test2 pluto[22988]: "device2" #5: EXPECTATION FAILED: proposal->remote_spi.size <= sizeof(proposal->remote_spi.size) (in print_proposal() at ikev2_spdb_struct.c:351)**
Apr 01 16:19:54 test2 pluto[22988]: "device2" #5: proposal 1:IKE:SPI=fd8ab83f;ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=ECP_521 chosen from remote proposals 1:IKE:ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=ECP_521[first-match]
Apr 01 16:19:54 test2 pluto[22988]: "device2" #6: STATE_PARENT_R2: received v2I2, PARENT SA established
Apr 01 16:19:55 test2 pluto[22988]: "device2" #5: deleting state (STATE_IKESA_DEL) aged 56.607s and NOT sending notification
Apr 01 16:20:24 test2 pluto[22988]: "device2" #6: initiate rekey of IKEv2 CREATE_CHILD_SA IKE Rekey                      
Apr 01 16:20:24 test2 pluto[22988]: "device2" #7: STATE_V2_REKEY_IKE_I: STATE_V2_REKEY_IKE_I                                        
Apr 01 16:20:24 test2 pluto[22988]: "device2" #7: rekeyed #6 STATE_V2_REKEY_IKE_I and expire it remaining life 269s
Apr 01 16:20:24 test2 pluto[22988]: "device2" #7: STATE_PARENT_I3: PARENT SA established
Apr 01 16:20:25 test2 pluto[22988]: "device2" #6: deleting state (STATE_PARENT_R2) aged 31.409s and sending notification
Apr 01 16:20:25 test2 pluto[22988]: packet from 192.168.100.149:500: ISAKMP_v2_INFORMATIONAL message response has no matching IKE SA
**Apr 01 16:21:19 test2 pluto[22988]: "device2" #7: EXPECTATION FAILED: proposal->remote_spi.size <= sizeof(proposal->remote_spi.size) (in print_proposal() at ikev2_spdb_struct.c:351)**
Apr 01 16:21:19 test2 pluto[22988]: "device2" #7: proposal 1:IKE:SPI=a902ccad;ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=ECP_521 chosen from remote proposals 1:IKE:ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=ECP_521[first-match]
Apr 01 16:21:19 test2 pluto[22988]: "device2" #8: STATE_PARENT_R2: received v2I2, PARENT SA established
Apr 01 16:21:20 test2 pluto[22988]: "device2" #7: deleting state (STATE_IKESA_DEL) aged 56.645s and NOT sending notification
Apr 01 16:21:49 test2 pluto[22988]: "device2" #8: initiate rekey of IKEv2 CREATE_CHILD_SA IKE Rekey
Apr 01 16:21:49 test2 pluto[22988]: "device2" #9: STATE_V2_REKEY_IKE_I: STATE_V2_REKEY_IKE_I
Apr 01 16:21:50 test2 pluto[22988]: "device2" #9: rekeyed #8 STATE_V2_REKEY_IKE_I and expire it remaining life 269s
Apr 01 16:21:50 test2 pluto[22988]: "device2" #9: STATE_PARENT_I3: PARENT SA established
Apr 01 16:21:50 test2 pluto[22988]: "device2" #8: deleting state (STATE_PARENT_R2) aged 31.548s and sending notification
Apr 01 16:21:50 test2 pluto[22988]: packet from 192.168.100.149:500: ISAKMP_v2_INFORMATIONAL message response has no matching IKE SA
hwdsl2 commented 2 years ago

@johnlukeabe Hello! Your use case is unrelated to the VPN setup scripts and is outside the scope of this repository. Please instead open an issue in libreswan/libreswan [1], or ask on the Libreswan users mailing list [2].

[1] https://github.com/libreswan/libreswan/issues [2] https://lists.libreswan.org/mailman/listinfo/swan