[Swan] Possibly dropped/missed SA init response messages

Andrew Cagney andrew.cagney at gmail.com
Fri Oct 14 05:56:13 EEST 2022


This is interesting:

Oct  8 04:01:39.330238: "ikev2"[2] 124.77.25.186 #17: 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:01:39.337963: "ikev2"[2] 124.77.25.186 #17: sent IKE_SA_INIT
reply {cipher=AES_CBC_256 integ=HMAC_SHA2_256_128 prf=HMAC_SHA2_256
group=MODP2048}
Oct  8 04:01:39.549322: "ikev2"[2] 124.77.25.186 #17: 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:01:39.549383: "ikev2"[2] 124.77.25.186 #17: switched to
"ikev2"[4] 124.77.25.186
Oct  8 04:01:39.549452: "ikev2"[4] 124.77.25.186 #17: responder
established IKE SA; authenticated using authby=secret and peer ID_FQDN
'@mac'
Oct  8 04:01:39.549584: "ikev2"[4] 124.77.25.186 #18: proposal
1:ESP=AES_CBC_256-HMAC_SHA2_256_128-DISABLED SPI=089d6040 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:01:39.565636: "ikev2"[4] 124.77.25.186 #18: responder
established Child SA using #17; IPsec tunnel
[0.0.0.0-255.255.255.255:0-65535 0] ->
[192.168.1.2-192.168.1.2:0-65535 0]

I suspect the CREATE_CHILD_SA, below, was for a rekey, but for some
reason it wasn't and its proposal which matches #18 was rejected:

Oct  8 04:09:39.766488: "ikev2"[4] 124.77.25.186 #22: proposal
1:IKE=AES_CBC_256-HMAC_SHA2_256-HMAC_SHA2_256_128-MODP2048
SPI=bc5e298212753dbe chosen from remote proposals
1:IKE:ENCR=AES_CBC_256;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128;DH=MODP2048[first-match]
Oct  8 04:09:39.777737: "ikev2"[4] 124.77.25.186 #22: responder
rekeyed IKE SA #17 {cipher=AES_CBC_256 integ=HMAC_SHA2_256_128
prf=HMAC_SHA2_256 group=MODP2048}
Oct  8 04:09:39.956311: "ikev2"[4] 124.77.25.186 #17: deleting state
(STATE_V2_ESTABLISHED_IKE_SA) aged 480.626083s and NOT sending
notification
Oct  8 04:09:40.762533: "ikev2"[4] 124.77.25.186 #23: no local
proposal matches remote proposals
1:ESP:ENCR=AES_CBC_256;INTEG=HMAC_SHA2_256_128;ESN=DISABLED
Oct  8 04:09:40.762582: "ikev2"[4] 124.77.25.186 #23: CREATE_CHILD_SA
request failed, responder SA processing returned NO_PROPOSAL_CHOSEN
Oct  8 04:09:40.762600: "ikev2"[4] 124.77.25.186 #22: responding to
CREATE_CHILD_SA message (ID 0) from 124.77.25.186:1024 with encrypted
notification NO_PROPOSAL_CHOSEN
Oct  8 04:09:40.928294: "ikev2"[4] 124.77.25.186 #18: ESP traffic
information: in=2MB out=11MB
Oct  8 04:09:41.098449: "ikev2"[4] 124.77.25.186 #22: deleting state
(STATE_V2_ESTABLISHED_IKE_SA) aged 1.331974s and NOT sending
notification
Oct  8 04:09:41.098506: "ikev2"[4] 124.77.25.186: deleting connection
instance with peer 124.77.25.186 {isakmp=#0/ipsec=#0}

A debug-log of the CREATE_CHILD_SA packet would help here.


This looks like the server->client path is losing (encrypted) IKE packets:

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 DPD=active}

The client didn't see the IKE_AUTH response so is pinging the server;
hence the retransmitted response:

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

This is ~30s after the server thinks the IKE SA established, is it a
liveness probe?  If it is then it looks like the client isn't seeing
it and/or responding.

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

Some sort of tcpdump on the client might help here.

All very strange.


More information about the Swan mailing list