Project

General

Profile

Bug #1537

Updated by Tobias Brunner about 6 years ago

Hi,

I am able to reproduce this issue with IKEv1 between strongswan and a non-strongswan client both being initiators. Below are the detailed steps to reproduce this issue, (Although I could not reproduce the exact same issue between 2 strongswan)
Note: Am using swanctl to operate strongswan here.

1. Initially when strongswan is up and client is down, Strongswan initiates the connection. IKEv1 Phase 1 is in 'connecting' mode. Phase 1 tasks are active and QUICK_MODE is queued.
<pre>
6fd252fb-815e-41f5-bdd8-940cc0d9ea81: #4, \#4, CONNECTING, IKEv1, a80bf9bda13c3322_i* 0000000000000000_r
local '%any' @ 10.15.1.254[500] 10.15.1.254\[500\]
remote '%any' @ 51.1.1.1[500] 51.1.1.1\[500\]
queued: QUICK_MODE QUICK_MODE
active: ISAKMP_VENDOR ISAKMP_CERT_PRE MAIN_MODE ISAKMP_CERT_POST ISAKMP_NATD
</pre>


2. When client is up with, strongswan loads an IKEv1 connection and tries to initiate QUICK_MODE. IKEv1 Phase 1 gets established but QUICK_MODE is queued both in 'active' and 'queued' list.
<pre>
ab88e862-81b8-484c-aaa4-969f719223cd: #4, \#4, ESTABLISHED, IKEv1, ed1d94aed05caa9e:a51c076b630526d6
local '50.1.1.1' @ 10.15.1.254[500] 10.15.1.254\[500\]
remote '51.1.1.1' @ 51.1.1.1[500] 51.1.1.1\[500\]
AES_CBC-192/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048
established 12s ago, rekeying in 79094s
queued: QUICK_MODE
active: QUICK_MODE
</pre>


3. After this point, if I issue a IKE-SA terminate ISAKMP_DELETE action is queued in 'queued' list.
<pre>
6fd252fb-815e-41f5-bdd8-940cc0d9ea81: #4, \#4, ESTABLISHED, IKEv1, a80bf9bda13c3322_i* 5fe68352fb84b8ec_r
local '50.1.1.1' @ 10.15.1.254[500] 10.15.1.254\[500\]
remote '51.1.1.1' @ 51.1.1.1[500] 51.1.1.1\[500\]
AES_CBC-192/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048
established 73s ago, rekeying in 79469s
queued: QUICK_MODE ISAKMP_DELETE QUICK_MODE
active: QUICK_MODE
</pre>


4. After this point, ISAKMP_DELETE task never gets executed. Because since QUICK_MODE tries out 5 retransmissions, gets reset. ISAKMP_DELETE is erased from both the queues and QUICK_MODE is queued again. Have pasted charon logs when this happens.
<pre>
6fd252fb-815e-41f5-bdd8-940cc0d9ea81: #10, \#10, ESTABLISHED, IKEv1, a1fc5d7bb6086405_i* a7c004948a042212_r
local '50.1.1.1' @ 10.15.1.254\[500\]
remote '51.1.1.1' @ 51.1.1.1\[500\]
AES_CBC-192/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048
established 1s ago, rekeying in 80044s
queued: QUICK_MODE QUICK_MODE
active: QUICK_MODE
</pre>

<pre>


Jun 27 19:03:21 14[CFG] vici terminate IKE_SA '6fd252fb-815e-41f5-bdd8-940cc0d9ea81'
Jun 27 19:03:27 04[IKE] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|13> sending retransmit 4 of request message ID 3465307493, seq 4
Jun 27 19:03:27 04[NET] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|13> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 50.1.1.1[500] 50.1.1.1\[500\] (172 bytes)
Jun 27 19:03:29 13[IKE] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|14> sending retransmit 4 of request message ID 3741647669, seq 4
Jun 27 19:03:29 13[NET] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|14> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 51.1.1.1[500] 51.1.1.1\[500\] (172 bytes)
Jun 27 19:04:09 11[IKE] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|13> sending retransmit 5 of request message ID 3465307493, seq 4
Jun 27 19:04:09 11[NET] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|13> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 50.1.1.1[500] 50.1.1.1\[500\] (172 bytes)
Jun 27 19:04:11 04[IKE] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|14> sending retransmit 5 of request message ID 3741647669, seq 4
Jun 27 19:04:11 04[NET] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|14> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 51.1.1.1[500] 51.1.1.1\[500\] (172 bytes)
Jun 27 19:05:24 09[KNL] creating delete job for CHILD_SA ESP/0xce395042/10.15.1.254
Jun 27 19:05:24 09[JOB] CHILD_SA ESP/0xce395042/10.15.1.254 not found for delete
Jun 27 19:05:24 05[IKE] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|13> giving up after 5 retransmits
Jun 27 19:05:24 05[IKE] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|13> initiating Main Mode IKE_SA dbd9e93b-7288-4910-9e3d-dabc763a6f88[15] to 50.1.1.1
Jun 27 19:05:24 05[ENC] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|13> generating ID_PROT request 0 [ SA V V V V ]
Jun 27 19:05:24 05[NET] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|13> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 50.1.1.1[500] 50.1.1.1\[500\] (160 bytes)
Jun 27 19:05:24 04[NET] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> received packet: from 50.1.1.1[500] 50.1.1.1\[500\] to 10.15.1.254[500] 10.15.1.254\[500\] (128 bytes)
Jun 27 19:05:24 04[ENC] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> parsed ID_PROT response 0 [ SA V V ]
Jun 27 19:05:24 04[IKE] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> received DPD vendor ID
Jun 27 19:05:24 04[ENC] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> received unknown vendor ID: ba:c7:c1:d1:9a:44:d6:af:51:af:a2:e9:60:96:98:4f
Jun 27 19:05:24 04[ENC] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> generating ID_PROT request 0 [ KE No ]
Jun 27 19:05:24 04[NET] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 50.1.1.1[500] 50.1.1.1\[500\] (324 bytes)
Jun 27 19:05:24 08[NET] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> received packet: from 50.1.1.1[500] 50.1.1.1\[500\] to 10.15.1.254[500] 10.15.1.254\[500\] (308 bytes)
Jun 27 19:05:24 08[ENC] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> parsed ID_PROT response 0 [ KE No ]
Jun 27 19:05:24 08[ENC] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> generating ID_PROT request 0 [ ID HASH ]
Jun 27 19:05:24 08[NET] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 50.1.1.1[500] 50.1.1.1\[500\] (76 bytes)
Jun 27 19:05:24 06[NET] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> received packet: from 50.1.1.1[500] 50.1.1.1\[500\] to 10.15.1.254[500] 10.15.1.254\[500\] (76 bytes)
Jun 27 19:05:24 06[ENC] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> parsed ID_PROT response 0 [ ID HASH ]
Jun 27 19:05:24 06[IKE] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> IKE_SA dbd9e93b-7288-4910-9e3d-dabc763a6f88[15] established between 10.15.1.254[50.1.1.1]...50.1.1.1[50.1.1.1]
Jun 27 19:05:24 06[IKE] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> scheduling rekeying in 81813s
Jun 27 19:05:24 06[IKE] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> maximum IKE_SA lifetime 90453s
Jun 27 19:05:24 06[ENC] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> generating QUICK_MODE request 2904747605 [ HASH SA No ID ID ]
Jun 27 19:05:24 06[NET] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 50.1.1.1[500] 50.1.1.1\[500\] (172 bytes)
Jun 27 19:05:27 09[KNL] creating delete job for CHILD_SA ESP/0xcd07ea41/10.15.1.254
Jun 27 19:05:27 09[JOB] CHILD_SA ESP/0xcd07ea41/10.15.1.254 not found for delete
Jun 27 19:05:27 16[IKE] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|14> giving up after 5 retransmits
Jun 27 19:05:27 14[CFG] vici connection 47 unknown
Jun 27 19:05:27 16[IKE] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|14> initiating Main Mode IKE_SA 6fd252fb-815e-41f5-bdd8-940cc0d9ea81[16] to 51.1.1.1
Jun 27 19:05:27 16[ENC] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|14> generating ID_PROT request 0 [ SA V V V V ]
Jun 27 19:05:27 16[NET] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|14> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 51.1.1.1[500] 51.1.1.1\[500\] (160 bytes)
Jun 27 19:05:27 07[NET] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> received packet: from 51.1.1.1[500] 51.1.1.1\[500\] to 10.15.1.254[500] 10.15.1.254\[500\] (128 bytes)
Jun 27 19:05:27 07[ENC] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> parsed ID_PROT response 0 [ SA V V ]
Jun 27 19:05:27 07[IKE] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> received DPD vendor ID
Jun 27 19:05:27 07[ENC] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> received unknown vendor ID: ba:c7:c1:d1:9a:44:d6:af:51:af:a2:e9:60:96:98:4f
Jun 27 19:05:27 07[ENC] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> generating ID_PROT request 0 [ KE No ]
Jun 27 19:05:27 07[NET] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 51.1.1.1[500] 51.1.1.1\[500\] (324 bytes)
Jun 27 19:05:27 04[NET] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> received packet: from 51.1.1.1[500] 51.1.1.1\[500\] to 10.15.1.254[500] 10.15.1.254\[500\] (308 bytes)
Jun 27 19:05:27 04[ENC] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> parsed ID_PROT response 0 [ KE No ]
Jun 27 19:05:27 04[ENC] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> generating ID_PROT request 0 [ ID HASH ]
Jun 27 19:05:27 04[NET] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 51.1.1.1[500] 51.1.1.1\[500\] (76 bytes)
Jun 27 19:05:27 09[NET] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> received packet: from 51.1.1.1[500] 51.1.1.1\[500\] to 10.15.1.254[500] 10.15.1.254\[500\] (76 bytes)
Jun 27 19:05:27 09[ENC] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> parsed ID_PROT response 0 [ ID HASH ]
Jun 27 19:05:27 09[IKE] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> IKE_SA 6fd252fb-815e-41f5-bdd8-940cc0d9ea81[16] established between 10.15.1.254[50.1.1.1]...51.1.1.1[51.1.1.1]
Jun 27 19:05:27 09[IKE] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> scheduling rekeying in 81975s
Jun 27 19:05:27 09[IKE] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> maximum IKE_SA lifetime 90615s
Jun 27 19:05:27 09[ENC] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> generating QUICK_MODE request 1906900257 [ HASH SA No ID ID ]
Jun 27 19:05:27 09[NET] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 51.1.1.1[500] 51.1.1.1\[500\] (172 bytes)
Jun 27 19:05:28 04[IKE] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> sending retransmit 1 of request message ID 2904747605, seq 4
Jun 27 19:05:28 04[NET] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 50.1.1.1[500] 50.1.1.1\[500\] (172 bytes)
Jun 27 19:05:31 14[IKE] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> sending retransmit 1 of request message ID 1906900257, seq 4
Jun 27 19:05:31 14[NET] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 51.1.1.1[500] 51.1.1.1\[500\] (172 bytes)
Jun 27 19:05:35 05[IKE] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> sending retransmit 2 of request message ID 2904747605, seq 4
Jun 27 19:05:35 05[NET] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 50.1.1.1[500] 50.1.1.1\[500\] (172 bytes)
Jun 27 19:05:38 10[IKE] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> sending retransmit 2 of request message ID 1906900257, seq 4
Jun 27 19:05:38 10[NET] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 51.1.1.1[500] 51.1.1.1\[500\] (172 bytes)
Jun 27 19:05:48 13[IKE] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> sending retransmit 3 of request message ID 2904747605, seq 4
Jun 27 19:05:48 13[NET] <dbd9e93b-7288-4910-9e3d-dabc763a6f88|15> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 50.1.1.1[500] 50.1.1.1\[500\] (172 bytes)
Jun 27 19:05:51 14[IKE] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> sending retransmit 3 of request message ID 1906900257, seq 4
Jun 27 19:05:51 14[NET] <6fd252fb-815e-41f5-bdd8-940cc0d9ea81|16> sending packet: from 10.15.1.254[500] 10.15.1.254\[500\] to 51.1.1.1[500] 51.1.1.1\[500\] (172 bytes)
</pre>


I found 2 issues created and fixed earlier related to this: https://wiki.strongswan.org/issues/429 and https://wiki.strongswan.org/issues/1410
Also, if i try out the patch provided in #1410 with few additions like in this PR https://github.com/strongswan/strongswan/pull/48
I was able to see this issue fixed.
Wanted to ask is there a reason why the patch wasn't merged to master.

Back