[Swan] Possibly dropped/missed SA init response messages

Tielong Su tielongs at gmail.com
Sat Oct 8 08:03:18 EEST 2022 

Seems the issue persists. One interesting observation was that the
connection works for a while on the new instance before the same issue
finally kicks in.

The issue occurs after around 3 - 7 rekeys, each rekey is default to 480
seconds for iOS clients, which means the connection works for about 20 - 60
minutes before running into this issue. To be more precise, the internet
got lost for the connection after 3 - 7 rekeys and upon manual reconnection
attempts, this issue occurs.

Below are the full log paste (I've tried the connection on both mac and
iphone), I've also restarted the instance / ipsec daemon and that doesn't
seem to help either

Swan version: 4.7
Instance: aws ec2 t4g.nano / arm64 / debian 11

*Full log*
https://gist.githubusercontent.com/tielong/648f67315701c90312e35ed7d11162ac/raw/254abea3e87d9853bea69e7e1ad476899d5e0e1b/gistfile1.txt

*Snippet*
*Oct  8 04:31:20.205442: "ikev2"[7] 124.77.25.186 #42: proposal
1:IKE=AES_CBC_256-HMAC_SHA2_256-HMAC_SHA2_256_128-MODP2048 chosen from
remote proposals
1:IKE:ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=MODP2048[first-match]
2:IKE:ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=ECP_256
3:IKE:ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=MODP1536
4:IKE:ENCR=AES_CBC_128;PRF=HMAC_SHA1;INTEG=HMAC_SHA1_96;DH=MODP1024
5:IKE:ENCR=3DES;PRF=HMAC_SHA1;INTEG=HMAC_SHA1_96;DH=MODP1024*

*Oct  8 04:31:20.212818: "ikev2"[7] 124.77.25.186 #42: sent IKE_SA_INIT
reply {cipher=AES_CBC_256 integ=HMAC_SHA2_256_128 prf=HMAC_SHA2_256
group=MODP2048}*

*Oct  8 04:31:20.436610: "ikev2"[7] 124.77.25.186 #42: processing decrypted
IKE_AUTH request:
SK{IDi,N(INITIAL_CONTACT),IDr,AUTH,CP,N(ESP_TFC_PADDING_NOT_SUPPORTED),N(NON_FIRST_FRAGMENTS_ALSO),SA,TSi,TSr,N(MOBIKE_SUPPORTED)}*

*Oct  8 04:31:20.436671: "ikev2"[7] 124.77.25.186 #42: switched to
"ikev2"[8] 124.77.25.186*

*Oct  8 04:31:20.436683: "ikev2"[7] 124.77.25.186 <http://124.77.25.186>:
deleting connection instance with peer 124.77.25.186 {isakmp=#0/ipsec=#0}*

*Oct  8 04:31:20.436707: "ikev2"[8] 124.77.25.186 #42: WARNING:
'@sequoia_us_west' PSK length of 6 bytes is too short for PRF HMAC_SHA2_256
in FIPS mode (16 bytes required)*

*Oct  8 04:31:20.436755: "ikev2"[8] 124.77.25.186 #42: responder
established IKE SA; authenticated using authby=secret and peer ID_IPV4_ADDR
'192.168.3.72'*

*Oct  8 04:31:20.436785: "ikev2"[8] 124.77.25.186 #42: WARNING:
'@sequoia_us_west' PSK length of 6 bytes is too short for PRF HMAC_SHA2_256
in FIPS mode (16 bytes required)*

*Oct  8 04:31:20.436871: "ikev2"[8] 124.77.25.186 #43: proposal
1:ESP=AES_CBC_256-HMAC_SHA2_256_128-DISABLED SPI=0c9eea7a chosen from
remote proposals
1:ESP:ENCR=AES_CBC_256;INTEG=HMAC_SHA2_256_128;ESN=DISABLED[first-match]
2:ESP:ENCR=AES_CBC_256;INTEG=HMAC_SHA2_256_128;ESN=DISABLED
3:ESP:ENCR=AES_CBC_256;INTEG=HMAC_SHA2_256_128;ESN=DISABLED
4:ESP:ENCR=AES_CBC_128;INTEG=HMAC_SHA1_96;ESN=DISABLED
5:ESP:ENCR=3DES;INTEG=HMAC_SHA1_96;ESN=DISABLED*

*Oct  8 04:31:20.451777: "ikev2"[8] 124.77.25.186 #43: responder
established Child SA using #42; IPsec tunnel
[0.0.0.0-255.255.255.255:0-65535 0] -> [192.168.1.1-192.168.1.1:0-65535 0]
{ESPinUDP=>0x0c9eea7a <0x85554587 xfrm=AES_CBC_256-HMAC_SHA2_256_128
NATD=124.77.25.186:4500 <http://124.77.25.186:4500> DPD=active}*

*Oct  8 04:31:21.437871: "ikev2"[8] 124.77.25.186 #42: IKE_AUTH request has
duplicate Message ID 1; retransmitting response*

*Oct  8 04:31:23.443425: "ikev2"[8] 124.77.25.186 #42: IKE_AUTH request has
duplicate Message ID 1; retransmitting response*

*Oct  8 04:31:27.449169: "ikev2"[8] 124.77.25.186 #42: IKE_AUTH request has
duplicate Message ID 1; retransmitting response*

*Oct  8 04:31:35.460039: "ikev2"[8] 124.77.25.186 #42: IKE_AUTH request has
duplicate Message ID 1; retransmitting response*

*Oct  8 04:31:50.956168: "ikev2"[8] 124.77.25.186 #42:
STATE_V2_ESTABLISHED_IKE_SA: retransmission; will wait 0.5 seconds for
response*

*Oct  8 04:31:51.461096: "ikev2"[8] 124.77.25.186 #42:
STATE_V2_ESTABLISHED_IKE_SA: retransmission; will wait 1 seconds for
response*

*Oct  8 04:31:51.518355: "ikev2"[8] 124.77.25.186 #44: proposal
1:IKE=AES_CBC_256-HMAC_SHA2_256-HMAC_SHA2_256_128-MODP2048 chosen from
remote proposals
1:IKE:ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=MODP2048[first-match]
2:IKE:ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=ECP_256
3:IKE:ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=MODP1536
4:IKE:ENCR=AES_CBC_128;PRF=HMAC_SHA1;INTEG=HMAC_SHA1_96;DH=MODP1024
5:IKE:ENCR=3DES;PRF=HMAC_SHA1;INTEG=HMAC_SHA1_96;DH=MODP1024*

*Oct  8 04:31:51.526114: "ikev2"[8] 124.77.25.186 #44: sent IKE_SA_INIT
reply {cipher=AES_CBC_256 integ=HMAC_SHA2_256_128 prf=HMAC_SHA2_256
group=MODP2048}*

*Oct  8 04:31:51.812549: "ikev2"[8] 124.77.25.186 #44: processing decrypted
IKE_AUTH request:
SK{IDi,N(INITIAL_CONTACT),IDr,AUTH,CP,N(ESP_TFC_PADDING_NOT_SUPPORTED),N(NON_FIRST_FRAGMENTS_ALSO),SA,TSi,TSr,N(MOBIKE_SUPPORTED)}*

*Oct  8 04:31:51.812611: "ikev2"[8] 124.77.25.186 #44: WARNING:
'@sequoia_us_west' PSK length of 6 bytes is too short for PRF HMAC_SHA2_256
in FIPS mode (16 bytes required)*

*Oct  8 04:31:51.812658: "ikev2"[8] 124.77.25.186 #44: responder
established IKE SA; authenticated using authby=secret and peer ID_IPV4_ADDR
'192.168.3.72'*

*Oct  8 04:31:51.812696: "ikev2"[8] 124.77.25.186 #44: WARNING:
'@sequoia_us_west' PSK length of 6 bytes is too short for PRF HMAC_SHA2_256
in FIPS mode (16 bytes required)*

*Oct  8 04:31:51.812760: "ikev2"[8] 124.77.25.186 #45: proposal
1:ESP=AES_CBC_256-HMAC_SHA2_256_128-DISABLED SPI=0d721dc3 chosen from
remote proposals
1:ESP:ENCR=AES_CBC_256;INTEG=HMAC_SHA2_256_128;ESN=DISABLED[first-match]
2:ESP:ENCR=AES_CBC_256;INTEG=HMAC_SHA2_256_128;ESN=DISABLED
3:ESP:ENCR=AES_CBC_256;INTEG=HMAC_SHA2_256_128;ESN=DISABLED
4:ESP:ENCR=AES_CBC_128;INTEG=HMAC_SHA1_96;ESN=DISABLED
5:ESP:ENCR=3DES;INTEG=HMAC_SHA1_96;ESN=DISABLED*

*Oct  8 04:31:51.812955: "ikev2"[8] 124.77.25.186 #45: responder
established Child SA using #44; IPsec tunnel
[0.0.0.0-255.255.255.255:0-65535 0] -> [192.168.1.1-192.168.1.1:0-65535 0]
{ESPinUDP=>0x0d721dc3 <0x3449e59e xfrm=AES_CBC_256-HMAC_SHA2_256_128
NATD=124.77.25.186:4500 <http://124.77.25.186:4500> DPD=active}*

*Oct  8 04:31:51.813069: "ikev2"[8] 124.77.25.186 #43: ESP traffic
information: in=0B out=5KB*

*Oct  8 04:31:52.464975: "ikev2"[8] 124.77.25.186 #42:
STATE_V2_ESTABLISHED_IKE_SA: retransmission; will wait 2 seconds for
response*

*Oct  8 04:31:52.821406: "ikev2"[8] 124.77.25.186 #44: IKE_AUTH request has
duplicate Message ID 1; retransmitting response*

*Oct  8 04:31:54.468208: "ikev2"[8] 124.77.25.186 #42:
STATE_V2_ESTABLISHED_IKE_SA: retransmission; will wait 4 seconds for
response*

*Oct  8 04:31:54.823805: "ikev2"[8] 124.77.25.186 #44: IKE_AUTH request has
duplicate Message ID 1; retransmitting response*

*Oct  8 04:31:58.472738: "ikev2"[8] 124.77.25.186 #42:
STATE_V2_ESTABLISHED_IKE_SA: retransmission; will wait 8 seconds for
response*

*Oct  8 04:31:58.831139: "ikev2"[8] 124.77.25.186 #44: IKE_AUTH request has
duplicate Message ID 1; retransmitting response*

*Oct  8 04:32:06.483938: "ikev2"[8] 124.77.25.186 #42:
STATE_V2_ESTABLISHED_IKE_SA: retransmission; will wait 16 seconds for
response*

*Oct  8 04:32:06.844260: "ikev2"[8] 124.77.25.186 #44: IKE_AUTH request has
duplicate Message ID 1; retransmitting response*

On Sat, Oct 8, 2022 at 8:48 AM Tielong Su <tielongs at gmail.com> wrote:

> Thanks Paul, will double check and circle back.
>
> On Sat, Oct 8, 2022 at 00:06 Paul Wouters <paul at nohats.ca> wrote:
>
>> On Fri, 7 Oct 2022, Tielong Su wrote:
>>
>> > Hello libreswan community,
>> > I am experiencing some SA retransmission issues for my IKEv2
>> connection. The connection had been stable and worked pretty well until
>> recently.
>> >
>> > From the pluto logs it seems the IPSec tunnel was successfully
>> established but at the same time the pluto daemon is re-transmitting the SA
>> response to the
>> > client / initiator due to receiving a duplicate SA init request. Below
>> is the log paste for the connection:
>>
>> > Full Gist -
>> https://gist.githubusercontent.com/tielong/5a5bffda4c224a853d98722260b0dc9f/raw/26215cde4911d049a7c74d3b41accce02758543c/gistfile1.txt
>>
>> That looks like a bug on oue end but:
>>
>> > Libreswan version: 4.3
>> > Linux Distro: Debian 11
>> > Cloud Premise/Fabric: AWS EC2 (t4g.nano on arm64, us-west-2)
>>
>> Please try 4.7 or 4.8 to see if the issue goes away? The liveness code
>> has seen some changes since 4.3.
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20221008/c7e4fe25/attachment-0001.htm>

More information about the Swan mailing list