<div dir="ltr">Hi,<div><br></div><div>First up, apologies if my previous messages did reach the group - there was no way for me to check and they didn't appear in the archive yet. I have done further debugging and wanted to ask a follow up question.</div>
<div><br></div><div style>I am facing a strange problem when trying to get Adtran Netvanta 5430 work with Strongswan 5.0.1. Here's what's happening - I've debugged quite a bit, added more debug statements in the code to find out what's going on, etc. Any help is greatly appreciated.</div>
<div style><br></div><div style>Using RSA authentication</div><div style><br></div><div style>1. IKE SA gets established OK.</div><div style>2. IKE Phase 2 starts and the initiator (Adtran) sends the first message</div><div style>
3. Responder is ok with that and sends the quick mode 2nd message</div><div style>4. Initiator (Adtran) is happy and dandy but before sending the quick mode 3rd message (Hash), it sends an INFORMATIONAL_V1 message 24577 (replay-status)</div>
<div style>5. Initiator (Adtran) immediately sends QUICK MODE 3rd message (Hash)</div><div style><br></div><div style>Now, per the logs on Strongswan side, everything is great until step 3 above. When the INFORMATIONAL_V1 message comes in at step 4, it is processed by process_r method in libcharon/sa/ikev1/tasks/quick_mode.c and returns SUCCESS at line 1021 - this much I verified adding additional debugging code.</div>
<div style><br></div><div style>But before the QUICK MODE 3rd message comes in (step 5), Strongswan is deleting the SAD entry and going back to QM_INIT. I verified it is in QM_INIT by adding additional debugging.</div><div style>
<br></div><div style>Any help is greatly appreciated.</div><div style><br></div><div style><br></div><div style>Here is the ipsec.conf</div><div style>================</div><div style><div># ipsec.conf - strongSwan IPsec configuration file</div>
<div><br></div><div># basic configuration</div><div><br></div><div>config setup</div><div> # charondebug = "dmn 2, mgr 2, ike 2, chd 2, job 2, cfg 2, knl 2, net 2, lib 2"</div><div> charondebug = "dmn 3, mgr 3, ike 4, chd 3, job 3, cfg 3, knl 3, net 2, lib 3"</div>
<div> # nat_traversal="yes"</div><div> # strictcrlpolicy=yes</div><div> # uniqueids = no</div><div><br></div><div># Add connections here.</div><div><br></div><div>conn %default</div><div> ikelifetime=480m</div>
<div> keylife=480m</div><div> rekeymargin=3m</div><div> keyingtries=1</div><div> keyexchange=ikev1</div><div><br></div><div>conn adtran-cert</div><div> auto=route</div><div> authby=pubkey</div>
<div> left=%defaultroute</div><div> leftcert=vpngwCert.pem</div><div> leftsubnet=<a href="http://0.0.0.0/0">0.0.0.0/0</a></div><div> #leftprotoport=tcp/http</div><div> right=107.0.5.22</div>
<div> rightcert=Adtran-VPN.pem</div><div> rightsubnet=<a href="http://172.17.0.0/16">172.17.0.0/16</a></div><div> #rightprotoport=tcp</div><div> #esp=aes128-sha1-modp1536</div><div><br></div></div>
<div style><br></div><div style><br></div><div style>Here is the relevant log.</div><div style>=========================</div><div style><br></div><div style><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 07[NET] received packet: from 107.0.5.22[500] to 10.0.0.139[500]</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 07[NET] waiting for data on sockets</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[MGR] checkout IKE_SA by message</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[MGR] IKE_SA adtran-cert[2] successfully checked out</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[NET] received packet: from 107.0.5.22[500] to 10.0.0.139[500]</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] next IV for MID 3414728253 => 8 bytes @ 0x7fdf8c000c60</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] 0: A4 CF 08 28 94 0F EE 0F ...(....</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[ENC] parsed QUICK_MODE request 3414728253 [ HASH SA No ID ID ]</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] Hash(1) => 20 bytes @ 0x7fdf8c0018d0</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] 0: C8 93 6D 4E 4E B2 98 9F 69 7D 31 16 02 A4 A5 4D ..mNN...i}1....M</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] 16: 99 26 74 FF .&t.</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] next IV for MID 3414728253 => 8 bytes @ 0x7fdf8c0018b0</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] 0: 25 69 01 A7 BD 75 5F 77 %i...u_w</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] BK - In QM_INIT</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] looking for a child config for <a href="http://0.0.0.0/0[tcp/http]">0.0.0.0/0[tcp/http]</a> === <a href="http://172.17.0.0/16[tcp]">172.17.0.0/16[tcp]</a></div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] proposing traffic selectors for us:</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] <a href="http://0.0.0.0/0">0.0.0.0/0</a></div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] proposing traffic selectors for other:</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] <a href="http://172.17.0.0/16">172.17.0.0/16</a></div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] candidate "adtran-cert" with prio 1+1</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] found matching child config "adtran-cert" with prio 2</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] selecting traffic selectors for other:</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] config: <a href="http://172.17.0.0/16">172.17.0.0/16</a>, received: <a href="http://172.17.0.0/16[tcp]">172.17.0.0/16[tcp]</a> => match: <a href="http://172.17.0.0/16[tcp]">172.17.0.0/16[tcp]</a></div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] selecting traffic selectors for us:</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] config: <a href="http://0.0.0.0/0">0.0.0.0/0</a>, received: <a href="http://0.0.0.0/0[tcp/http]">0.0.0.0/0[tcp/http]</a> => match: <a href="http://0.0.0.0/0[tcp/http]">0.0.0.0/0[tcp/http]</a></div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] selecting proposal:</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] no acceptable ENCRYPTION_ALGORITHM found</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] selecting proposal:</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] no acceptable DIFFIE_HELLMAN_GROUP found</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] selecting proposal:</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] proposal matches</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] received proposals: ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] configured proposals: ESP:AES_CBC_128/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ, ESP:3DES_CBC/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/AES_CBC_192/AES_CBC_256/3DES_CBC/BLOWFISH_CBC_256/HMAC_SHA1_96/AES_XCBC_96/HMAC_MD5_96/NO_EXT_SEQ</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] selected proposal: ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] BK - In QM_INIT - calling child_sa_create</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] getting SPI for reqid {2}</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] sending XFRM_MSG_ALLOCSPI: => 248 bytes @ 0x7fdfab44c730</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 0: F8 00 00 00 16 00 01 00 CC 00 00 00 89 60 00 00 .............`..</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 16: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 32: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 64: 00 00 00 00 00 00 00 00 0A 00 00 8B 00 00 00 00 ................</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 80: 00 00 00 00 00 00 00 00 00 00 00 00 32 00 00 00 ............2...</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 96: 6B 00 05 16 00 00 00 00 00 00 00 00 00 00 00 00 k...............</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................</div><div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 224: 02 00 00 00 02 00 01 00 00 00 00 00 00 00 00 00 ................</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 240: 00 00 00 C0 FF FF FF CF .......</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] got SPI c959f83c for reqid {2}</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] BK - Entering QM_NEGOTIATED - in build_r</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] Hash(2) => 20 bytes @ 0x7fdf8c004690</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] 0: 25 C2 A9 3A 3E 2E C5 DE 91 FE C7 CA 09 28 44 9C %..:>........(D.</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] 16: 14 18 D6 07 ....</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[ENC] generating QUICK_MODE response 3414728253 [ HASH SA No ID ID ]</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] next IV for MID 3414728253 => 8 bytes @ 0x7fdf8c004b70</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] 0: 75 BF 60 BC 36 B9 AA F7 u.`.6...</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[NET] sending packet: from 10.0.0.139[500] to 107.0.5.22[500]</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 08[NET] sending packet: from 10.0.0.139[500] to 107.0.5.22[500]</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 04[JOB] next event in 3s 999ms, waiting</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[MGR] checkin IKE_SA adtran-cert[2]</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 14[MGR] check-in of IKE_SA successful.</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 07[NET] received packet: from 107.0.5.22[500] to 10.0.0.139[500]</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 07[NET] waiting for data on sockets</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[MGR] checkout IKE_SA by message</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[MGR] IKE_SA adtran-cert[2] successfully checked out</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[NET] received packet: from 107.0.5.22[500] to 10.0.0.139[500]</div><div>
Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] next IV for MID 2299459328 => 8 bytes @ 0x7fdf98000e00</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] 0: D1 2E 0B 3D 7A BB 2E 55 ...=z..U</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[ENC] parsed INFORMATIONAL_V1 request 2299459328 [ HASH N((24577)) ]</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] Hash => 20 bytes @ 0x7fdf98001780</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] 0: B5 91 96 6C B8 57 EA CE FD CB 8B 6A E3 53 04 10 ...l.W.....j.S..</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] 16: 09 4B CC 33 .K.3</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] next IV for MID 2299459328 => 8 bytes @ 0x7fdf98000a70</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] 0: C0 3A 7A F3 D2 19 58 45 .:z...XE</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] received (24577) notify</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] BK - In QM_NEGOTIATED</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] BK - In QM_NEGOTIATED - returning without installing the SA</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[KNL] deleting SAD entry with SPI c959f83c (mark 0/0x00000000)</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[KNL] sending XFRM_MSG_DELSA: => 40 bytes @ 0x7fdfaaa4b770</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[KNL] 0: 28 00 00 00 11 00 05 00 CD 00 00 00 89 60 00 00 (............`..</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[KNL] 16: 0A 00 00 8B 00 00 00 00 00 00 00 00 00 00 00 00 ................</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[KNL] 32: C9 59 F8 3C 02 00 32 00 .Y.<..2.</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[KNL] deleted SAD entry with SPI c959f83c (mark 0/0x00000000)</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[MGR] checkin IKE_SA adtran-cert[2]</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 15[MGR] check-in of IKE_SA successful.</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 07[NET] received packet: from 107.0.5.22[500] to 10.0.0.139[500]</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 07[NET] waiting for data on sockets</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[MGR] checkout IKE_SA by message</div>
</div><div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[MGR] IKE_SA adtran-cert[2] successfully checked out</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[NET] received packet: from 107.0.5.22[500] to 10.0.0.139[500]</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[ENC] parsed QUICK_MODE request 3414728253 [ HASH ]</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] Hash(3) => 20 bytes @ 0x7fdf940012d0</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] 0: 7C 2E 99 6E 60 E9 17 46 B1 35 F1 C0 99 EF FD 61 |..n`..F.5.....a</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] 16: BF E0 58 74 ..Xt</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] next IV for MID 3414728253 => 8 bytes @ 0x7fdf94001280</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] 0: 01 E8 C5 A6 E3 66 2C 9C .....f,.</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] BK - In QM_INIT</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] sa payload missing</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] queueing INFORMATIONAL task</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] activating new tasks</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] activating INFORMATIONAL task</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] Hash => 20 bytes @ 0x7fdf94000f00</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] 0: 33 6C 5C 31 CF C1 75 47 36 CA 23 92 8A 02 E3 33 3l\1..uG6.#....3</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] 16: 07 98 B9 59 ...Y</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[ENC] generating INFORMATIONAL_V1 request 613066051 [ HASH N(CRIT) ]</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] next IV for MID 613066051 => 8 bytes @ 0x7fdf94001d20</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] 0: DC B3 F3 3D 08 37 F2 E3 ...=.7..</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] next IV for MID 613066051 => 8 bytes @ 0x7fdf94001940</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] 0: C9 7B 6C F6 3C 6A 95 D5 .{l.<j..</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[NET] sending packet: from 10.0.0.139[500] to 107.0.5.22[500]</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] activating new tasks</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] nothing to initiate</div>
<div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[MGR] checkin IKE_SA adtran-cert[2]</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 16[MGR] check-in of IKE_SA successful.</div><div>Dec 27 01:49:45 ip-10-0-0-139 charon: 08[NET] sending packet: from 10.0.0.139[500] to 107.0.5.22[500]</div>
</div></div><div style><br></div><div style>=========================</div><div style><br></div><div style><br></div><div style><br></div><div style><br></div><div style><br></div><div style><br></div></div>