[strongSwan] Mismatched reqids after delayed IKE_SA_INIT
Alan Ford
alan.ford at gmail.com
Thu May 23 12:32:55 CEST 2013
Hi again,
I have had another problem with asymmetric configuration appearing on
strongSwan; this time involving mismatched reqids on one end. Seen this
happen a few times now. Same setup as my previous (unanswered so far) mail,
running 4.6.4, but what appears to be a different problem.
Seems to be related to packet loss/delay during setup. I can sort-of follow
what's happened here in the logs, things are getting confused due to
out-of-order packets… But should charon be able to cope with this? Looks
like after a retransmitted IKE_SA_INIT turns up, the endpoint goes to
replace its SA with this new one, but does not properly do so, leaving the
incoming side configured with the previous reqid. Is there a bug here?
Box1 (10.1.1.1):
(Taken at 2013-05-18T21:30:00)
(ipsec statusall)
box2[7]: ESTABLISHED 56 seconds ago, 10.1.1.1[10.1.1.1]…10.1.1.2[10.1.1.2]
box2[7]: IKE SPIs: ed0f0b2d780d3e52_i* 8079151befcb9f95_r, public key
reauthentication in 2 hours
box2[7]: IKE proposal:
AES_CBC_256/HMAC_SHA2_512_256/PRF_HMAC_SHA2_512/MODP_4096
box2{8}: INSTALLED, TRANSPORT, ESP SPIs: c85aefe6_i ccfc9b50_o
box2{8}: AES_CBC_256/HMAC_SHA2_512_256, 6580 bytes_i (2s ago), 6552
bytes_o (2s ago), rekeying in 47 minutes
box2{8}: 10.1.1.1/32 === 10.1.1.2/32
(ip xfrm policy)
src 10.1.1.2/32 dst 10.1.1.1/32
dir in priority 1795
tmpl src 0.0.0.0 dst 0.0.0.0
proto esp reqid 8 mode transport
src 10.1.1.1/32 dst 10.1.1.2/32
dir out priority 1795
tmpl src 0.0.0.0 dst 0.0.0.0
proto esp reqid 8 mode transport
Box2 (10.1.1.2):
(ipsec statusall)
box1[9]: ESTABLISHED 57 seconds ago, 10.1.1.2[10.1.1.2]…10.1.1.1[10.1.1.2]
box1[9]: IKE SPIs: ed0f0b2d780d3e52_i 8079151befcb9f95_r*, public key
reauthentication in 2 hours
box1[9]: IKE proposal:
AES_CBC_256/HMAC_SHA2_512_256/PRF_HMAC_SHA2_512/MODP_4096
box1{8}: INSTALLED, TRANSPORT, ESP SPIs: ccfc9b50_i c85aefe6_o
box1{8}: AES_CBC_256/HMAC_SHA2_512_256, 6786 bytes_i (0s ago), 6815
bytes_o (1s ago), rekeying in 45 minutes
box1{8}: 10.1.1.2/32 === 10.1.1.1/32
(ip xfrm policy)
src 10.1.1.1/32 dst 10.1.1.2/32
dir in priority 3843
tmpl src 0.0.0.0 dst 0.0.0.0
proto esp reqid 3 mode transport
src 10.1.1.2/32 dst 10.1.1.1/32
dir out priority 1795
tmpl src 0.0.0.0 dst 0.0.0.0
proto esp reqid 8 mode transport
*=> reqid 3 does not exist, so incoming traffic fails.*
Logs during setup were:
Box1:
2013-05-18T21:27:36.793+00:00 charon: 14[CFG] received stroke: add
connection 'box2'
2013-05-18T21:27:36.793+00:00 charon: 14[CFG] loaded certificate
2013-05-18T21:27:36.793+00:00 charon: 14[CFG] added configuration 'box2'
2013-05-18T21:27:36.793+00:00 charon: 11[CFG] received stroke: route 'box2'
2013-05-18T21:27:36.827+00:00 charon: 16[KNL] creating acquire job for
policy 10.1.1.1/32[udp/8005] === 10.1.1.2/32[udp/8005] with reqid {8}
2013-05-18T21:27:36.827+00:00 charon: 09[IKE] initiating IKE_SA box2[7] to
10.1.1.2
2013-05-18T21:27:36.859+00:00 charon: 09[ENC] generating IKE_SA_INIT
request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) ]
2013-05-18T21:27:36.859+00:00 charon: 09[NET] sending packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:27:40.859+00:00 charon: 15[IKE] retransmit 1 of request with
message ID 0
2013-05-18T21:27:40.859+00:00 charon: 15[NET] sending packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:27:48.059+00:00 charon: 13[IKE] retransmit 2 of request with
message ID 0
2013-05-18T21:27:48.059+00:00 charon: 13[NET] sending packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:28:01.020+00:00 charon: 14[IKE] retransmit 3 of request with
message ID 0
2013-05-18T21:28:01.020+00:00 charon: 14[NET] sending packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:28:24.092+00:00 charon: 14[IKE] retransmit 4 of request with
message ID 0
2013-05-18T21:28:24.092+00:00 charon: 14[NET] sending packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:29:04.520+00:00 charon: 14[NET] received packet: from
10.1.1.2[500] to 10.1.1.1[500]
2013-05-18T21:29:04.520+00:00 charon: 14[ENC] parsed IKE_SA_INIT request 0
[ SA KE No N(NATD_S_IP) N(NATD_D_IP) ]
2013-05-18T21:29:04.520+00:00 charon: 14[IKE] 10.1.1.2 is initiating an
IKE_SA
2013-05-18T21:29:04.574+00:00 charon: 14[IKE] sending cert request for "..."
2013-05-18T21:29:04.574+00:00 charon: 14[ENC] generating IKE_SA_INIT
response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(MULT_AUTH) ]
2013-05-18T21:29:04.574+00:00 charon: 14[NET] sending packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:29:04.639+00:00 charon: 09[NET] received packet: from
10.1.1.2[500] to 10.1.1.1[500]
2013-05-18T21:29:04.639+00:00 charon: 09[ENC] parsed IKE_AUTH request 1 [
IDi CERT N(INIT_CONTACT) CERTREQ IDr AUTH N(USE_TRANSP) SA TSi TSr
N(MULT_AUTH) N(EAP_ONLY) ]
2013-05-18T21:29:04.639+00:00 charon: 09[IKE] received cert request for
"..."
2013-05-18T21:29:04.639+00:00 charon: 09[IKE] received end entity cert "..."
2013-05-18T21:29:04.639+00:00 charon: 09[CFG] looking for peer configs
matching 10.1.1.1[10.1.1.1]...10.1.1.2[10.1.1.2]
2013-05-18T21:29:04.639+00:00 charon: 09[CFG] selected peer config 'box2'
2013-05-18T21:29:04.639+00:00 charon: 09[CFG] using certificate "..."
2013-05-18T21:29:04.639+00:00 charon: 09[CFG] using trusted ca
certificate "..."
2013-05-18T21:29:04.639+00:00 charon: 09[CFG] checking certificate status
of "..."
2013-05-18T21:29:04.639+00:00 charon: 09[CFG] certificate status is not
available
2013-05-18T21:29:04.639+00:00 charon: 09[CFG] reached self-signed root ca
with a path length of 0
2013-05-18T21:29:04.639+00:00 charon: 09[IKE] authentication of '10.1.1.2'
with RSA signature successful
2013-05-18T21:29:04.652+00:00 charon: 09[IKE] authentication of '10.1.1.1'
(myself) with RSA signature successful
2013-05-18T21:29:04.652+00:00 charon: 09[IKE] IKE_SA box2[10] established
between 10.1.1.1[10.1.1.1]...10.1.1.2[10.1.1.2]
2013-05-18T21:29:04.652+00:00 charon: 09[IKE] scheduling reauthentication
in 10247s
2013-05-18T21:29:04.652+00:00 charon: 09[IKE] maximum IKE_SA lifetime 10787s
2013-05-18T21:29:04.652+00:00 charon: 09[IKE] sending end entity cert "..."
2013-05-18T21:29:04.652+00:00 charon: 09[IKE] CHILD_SA box2{11} established
with SPIs c9e6e6ac_i c096a2e3_o and TS 10.1.1.1/32 === 10.1.1.2/32
2013-05-18T21:29:04.652+00:00 charon: 09[ENC] generating IKE_AUTH response
1 [ IDr CERT AUTH N(USE_TRANSP) SA TSi TSr N(AUTH_LFT) ]
2013-05-18T21:29:04.652+00:00 charon: 09[NET] sending packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:29:06.082+00:00 charon: 10[IKE] retransmit 5 of request with
message ID 0
2013-05-18T21:29:06.082+00:00 charon: 10[NET] sending packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:29:06.136+00:00 charon: 12[NET] received packet: from
10.1.1.2[500] to 10.1.1.1[500]
2013-05-18T21:29:06.136+00:00 charon: 12[ENC] parsed IKE_SA_INIT response 0
[ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(MULT_AUTH) ]
2013-05-18T21:29:06.162+00:00 charon: 12[IKE] received cert request for
"..."
2013-05-18T21:29:06.162+00:00 charon: 12[IKE] sending cert request for "..."
2013-05-18T21:29:06.170+00:00 charon: 12[IKE] authentication of '10.1.1.1'
(myself) with RSA signature successful
2013-05-18T21:29:06.170+00:00 charon: 12[IKE] sending end entity cert "..."
2013-05-18T21:29:06.170+00:00 charon: 12[IKE] establishing CHILD_SA box2{8}
2013-05-18T21:29:06.170+00:00 charon: 12[ENC] generating IKE_AUTH request 1
[ IDi CERT CERTREQ IDr AUTH N(USE_TRANSP) SA TSi TSr N(MULT_AUTH)
N(EAP_ONLY) ]
2013-05-18T21:29:06.170+00:00 charon: 12[NET] sending packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:29:06.178+00:00 charon: 13[NET] received packet: from
10.1.1.2[500] to 10.1.1.1[500]
2013-05-18T21:29:06.178+00:00 charon: 13[ENC] parsed INFORMATIONAL request
2 [ D ]
2013-05-18T21:29:06.178+00:00 charon: 13[IKE] received DELETE for IKE_SA
box2[10]
2013-05-18T21:29:06.178+00:00 charon: 13[IKE] deleting IKE_SA box2[10]
between 10.1.1.1[10.1.1.1]...10.1.1.2[10.1.1.2]
2013-05-18T21:29:06.178+00:00 charon: 13[IKE] IKE_SA deleted
2013-05-18T21:29:06.178+00:00 charon: 13[ENC] generating INFORMATIONAL
response 2 [ ]
2013-05-18T21:29:06.178+00:00 charon: 13[NET] sending packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:29:06.179+00:00 charon: 15[NET] received packet: from
10.1.1.2[500] to 10.1.1.1[500]
2013-05-18T21:29:06.179+00:00 charon: 15[ENC] parsed IKE_AUTH response 1 [
IDr CERT AUTH N(USE_TRANSP) SA TSi TSr N(AUTH_LFT) ]
2013-05-18T21:29:06.179+00:00 charon: 15[IKE] received end entity cert "..."
2013-05-18T21:29:06.179+00:00 charon: 15[CFG] using certificate "..."
2013-05-18T21:29:06.179+00:00 charon: 15[CFG] using trusted ca
certificate "..."
2013-05-18T21:29:06.179+00:00 charon: 15[CFG] checking certificate status
of "..."
2013-05-18T21:29:06.179+00:00 charon: 15[CFG] certificate status is not
available
2013-05-18T21:29:06.179+00:00 charon: 15[CFG] reached self-signed root ca
with a path length of 0
2013-05-18T21:29:06.179+00:00 charon: 15[IKE] authentication of '10.1.1.2'
with RSA signature successful
2013-05-18T21:29:06.179+00:00 charon: 15[IKE] IKE_SA box2[7] established
between 10.1.1.1[10.1.1.1]...10.1.1.2[10.1.1.2]
2013-05-18T21:29:06.179+00:00 charon: 15[IKE] scheduling reauthentication
in 9965s
2013-05-18T21:29:06.179+00:00 charon: 15[IKE] maximum IKE_SA lifetime 10505s
2013-05-18T21:29:06.180+00:00 charon: 15[IKE] CHILD_SA box2{8} established
with SPIs c85aefe6_i ccfc9b50_o and TS 10.1.1.1/32 === 10.1.1.2/32
2013-05-18T21:29:06.180+00:00 charon: 15[IKE] received AUTH_LIFETIME of
10226s, scheduling reauthentication in 9686s
Box2:
2013-05-18T21:29:03.964+00:00 charon: 16[KNL] creating acquire job for
policy 10.1.1.2/32[udp/8005] === 10.1.1.1/32[udp/8005] with reqid {3}
2013-05-18T21:29:03.973+00:00 charon: 13[IKE] initiating IKE_SA box1[6] to
10.1.1.1
2013-05-18T21:29:04.035+00:00 charon: 13[ENC] generating IKE_SA_INIT
request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) ]
2013-05-18T21:29:04.035+00:00 charon: 13[NET] sending packet: from
10.1.1.2[500] to 10.1.1.1[500]
2013-05-18T21:29:04.091+00:00 charon: 09[NET] received packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:29:04.091+00:00 charon: 09[ENC] parsed IKE_SA_INIT response 0
[ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(MULT_AUTH) ]
2013-05-18T21:29:04.152+00:00 charon: 09[IKE] authentication of '10.1.1.2'
(myself) with RSA signature successful
2013-05-18T21:29:04.154+00:00 charon: 09[IKE] sending end entity cert "..."
2013-05-18T21:29:04.154+00:00 charon: 09[IKE] establishing CHILD_SA box1{3}
2013-05-18T21:29:04.154+00:00 charon: 09[ENC] generating IKE_AUTH request 1
[ IDi CERT N(INIT_CONTACT) CERTREQ IDr AUTH N(USE_TRANSP) SA TSi TSr
N(MULT_AUTH) N(EAP_ONLY) ]
2013-05-18T21:29:04.155+00:00 charon: 09[NET] sending packet: from
10.1.1.2[500] to 10.1.1.1[500]
2013-05-18T21:29:04.169+00:00 charon: 14[NET] received packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:29:04.169+00:00 charon: 14[ENC] parsed IKE_AUTH response 1 [
IDr CERT AUTH N(USE_TRANSP) SA TSi TSr N(AUTH_LFT) ]
2013-05-18T21:29:04.169+00:00 charon: 14[IKE] received end entity cert "..."
2013-05-18T21:29:04.169+00:00 charon: 14[CFG] using certificate "…"
2013-05-18T21:29:04.169+00:00 charon: 14[CFG] using trusted ca
certificate "…"
2013-05-18T21:29:04.169+00:00 charon: 14[CFG] checking certificate status
of "..."
2013-05-18T21:29:04.169+00:00 charon: 14[CFG] certificate status is not
available
2013-05-18T21:29:04.169+00:00 charon: 14[CFG] reached self-signed root ca
with a path length of 0
2013-05-18T21:29:04.169+00:00 charon: 14[IKE] authentication of '10.1.1.1'
with RSA signature successful
2013-05-18T21:29:04.169+00:00 charon: 14[IKE] IKE_SA box1[6] established
between 10.1.1.2[10.1.1.2]...10.1.1.1[10.1.1.1]
2013-05-18T21:29:04.169+00:00 charon: 14[IKE] scheduling reauthentication
in 9975s
2013-05-18T21:29:04.169+00:00 charon: 14[IKE] maximum IKE_SA lifetime 10515s
2013-05-18T21:29:04.169+00:00 charon: 14[IKE] CHILD_SA box1{3} established
with SPIs c096a2e3_i c9e6e6ac_o and TS 10.1.1.2/32 === 10.1.1.1/32
2013-05-18T21:29:04.169+00:00 charon: 14[IKE] received AUTH_LIFETIME of
10247s, scheduling reauthentication in 9707s
But then! Looks like a delayed IKE_SA_INIT turns up…
2013-05-18T21:29:05.600+00:00 charon: 12[NET] received packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:29:05.600+00:00 charon: 12[ENC] parsed IKE_SA_INIT request 0
[ SA KE No N(NATD_S_IP) N(NATD_D_IP) ]
2013-05-18T21:29:05.600+00:00 charon: 12[IKE] 10.1.1.1 is initiating an
IKE_SA
2013-05-18T21:29:05.652+00:00 charon: 12[IKE] sending cert request for "..."
2013-05-18T21:29:05.652+00:00 charon: 12[ENC] generating IKE_SA_INIT
response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(MULT_AUTH) ]
2013-05-18T21:29:05.652+00:00 charon: 12[NET] sending packet: from
10.1.1.2[500] to 10.1.1.1[500]
2013-05-18T21:29:05.687+00:00 charon: 10[NET] received packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:29:05.687+00:00 charon: 10[ENC] parsed IKE_AUTH request 1 [
IDi CERT CERTREQ IDr AUTH N(USE_TRANSP) SA TSi TSr N(MULT_AUTH) N(EAP_ONLY)
]
2013-05-18T21:29:05.687+00:00 charon: 10[IKE] received cert request for "…"
2013-05-18T21:29:05.687+00:00 charon: 10[IKE] received end entity cert "..."
2013-05-18T21:29:05.687+00:00 charon: 10[CFG] looking for peer configs
matching 10.1.1.2[10.1.1.2]...10.1.1.1[10.1.1.1]
2013-05-18T21:29:05.687+00:00 charon: 10[CFG] selected peer config 'box1'
2013-05-18T21:29:05.687+00:00 charon: 10[CFG] using certificate "…"
2013-05-18T21:29:05.687+00:00 charon: 10[CFG] using trusted ca
certificate "..."
2013-05-18T21:29:05.687+00:00 charon: 10[CFG] checking certificate status
of "..."
2013-05-18T21:29:05.687+00:00 charon: 10[CFG] certificate status is not
available
2013-05-18T21:29:05.687+00:00 charon: 10[CFG] reached self-signed root ca
with a path length of 0
2013-05-18T21:29:05.693+00:00 charon: 10[IKE] authentication of '10.1.1.1'
with RSA signature successful
2013-05-18T21:29:05.695+00:00 charon: 10[IKE] authentication of '10.1.1.2'
(myself) with RSA signature successful
2013-05-18T21:29:05.695+00:00 charon: 10[IKE] deleting duplicate IKE_SA for
peer '10.1.1.1' due to uniqueness policy
2013-05-18T21:29:05.695+00:00 charon: 10[IKE] deleting IKE_SA box1[6]
between 10.1.1.2[10.1.1.2]...10.1.1.1[10.1.1.1]
2013-05-18T21:29:05.695+00:00 charon: 10[IKE] sending DELETE for IKE_SA
box1[6]
2013-05-18T21:29:05.695+00:00 charon: 10[ENC] generating INFORMATIONAL
request 2 [ D ]
2013-05-18T21:29:05.695+00:00 charon: 10[NET] sending packet: from
10.1.1.2[500] to 10.1.1.1[500]
2013-05-18T21:29:05.695+00:00 charon: 10[IKE] IKE_SA box1[9] established
between 10.1.1.2[10.1.1.2]...10.1.1.1[10.1.1.1]
2013-05-18T21:29:05.695+00:00 charon: 10[IKE] scheduling reauthentication
in 10226s
2013-05-18T21:29:05.695+00:00 charon: 10[IKE] maximum IKE_SA lifetime 10766s
2013-05-18T21:29:05.695+00:00 charon: 10[IKE] sending end entity cert "..."
2013-05-18T21:29:05.696+00:00 charon: 15[NET] received packet: from
10.1.1.1[500] to 10.1.1.2[500]
2013-05-18T21:29:05.696+00:00 charon: 15[ENC] parsed INFORMATIONAL response
2 [ ]
2013-05-18T21:29:05.696+00:00 charon: 15[IKE] IKE_SA deleted
2013-05-18T21:29:05.696+00:00 charon: 10[IKE] CHILD_SA box1{8} established
with SPIs ccfc9b50_i c85aefe6_o and TS 10.1.1.2/32 === 10.1.1.1/32
2013-05-18T21:29:05.696+00:00 charon: 10[ENC] generating IKE_AUTH response
1 [ IDr CERT AUTH N(USE_TRANSP) SA TSi TSr N(AUTH_LFT) ]
2013-05-18T21:29:05.696+00:00 charon: 10[NET] sending packet: from
10.1.1.2[500] to 10.1.1.1[500]
Many thanks,
Alan
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.strongswan.org/pipermail/users/attachments/20130523/2fa1f061/attachment.html>
More information about the Users
mailing list