[strongSwan] SAD entry deleted when INFORMATIONAL_V1 message received in QM_NEGOTIATED state
Bharath Kumar
cbkumar at gmail.com
Mon Dec 31 20:22:53 CET 2012
Does anyone have any clues as to what might be going on here? Any pointers
are appreciated.
Thanks,
Bharath Kumar
On Wed, Dec 26, 2012 at 11:21 PM, Bharath Kumar <cbkumar at gmail.com> wrote:
> Hi,
>
> 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.
>
> 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.
>
> Using RSA authentication
>
> 1. IKE SA gets established OK.
> 2. IKE Phase 2 starts and the initiator (Adtran) sends the first message
> 3. Responder is ok with that and sends the quick mode 2nd message
> 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)
> 5. Initiator (Adtran) immediately sends QUICK MODE 3rd message (Hash)
>
> 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.
>
> 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.
>
> Any help is greatly appreciated.
>
>
> Here is the ipsec.conf
> ================
> # ipsec.conf - strongSwan IPsec configuration file
>
> # basic configuration
>
> config setup
> # charondebug = "dmn 2, mgr 2, ike 2, chd 2, job 2, cfg 2, knl 2,
> net 2, lib 2"
> charondebug = "dmn 3, mgr 3, ike 4, chd 3, job 3, cfg 3, knl 3,
> net 2, lib 3"
> # nat_traversal="yes"
> # strictcrlpolicy=yes
> # uniqueids = no
>
> # Add connections here.
>
> conn %default
> ikelifetime=480m
> keylife=480m
> rekeymargin=3m
> keyingtries=1
> keyexchange=ikev1
>
> conn adtran-cert
> auto=route
> authby=pubkey
> left=%defaultroute
> leftcert=vpngwCert.pem
> leftsubnet=0.0.0.0/0
> #leftprotoport=tcp/http
> right=107.0.5.22
> rightcert=Adtran-VPN.pem
> rightsubnet=172.17.0.0/16
> #rightprotoport=tcp
> #esp=aes128-sha1-modp1536
>
>
>
> Here is the relevant log.
> =========================
>
> 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]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 07[NET] waiting for data on sockets
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[MGR] checkout IKE_SA by message
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[MGR] IKE_SA adtran-cert[2]
> successfully checked out
> 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]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] next IV for MID 3414728253
> => 8 bytes @ 0x7fdf8c000c60
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] 0: A4 CF 08 28 94 0F EE
> 0F ...(....
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[ENC] parsed QUICK_MODE request
> 3414728253 [ HASH SA No ID ID ]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] Hash(1) => 20 bytes @
> 0x7fdf8c0018d0
> 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
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] 16: 99 26 74 FF
> .&t.
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] next IV for MID 3414728253
> => 8 bytes @ 0x7fdf8c0018b0
> 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
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] BK - In QM_INIT
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] looking for a child config
> for 0.0.0.0/0[tcp/http] <http://0.0.0.0/0%5Btcp/http%5D> ===
> 172.17.0.0/16[tcp] <http://172.17.0.0/16%5Btcp%5D>
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] proposing traffic selectors
> for us:
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] 0.0.0.0/0
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] proposing traffic selectors
> for other:
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] 172.17.0.0/16
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] candidate "adtran-cert"
> with prio 1+1
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] found matching child config
> "adtran-cert" with prio 2
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] selecting traffic selectors
> for other:
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] config: 172.17.0.0/16,
> received: 172.17.0.0/16[tcp] <http://172.17.0.0/16%5Btcp%5D> => match:
> 172.17.0.0/16[tcp] <http://172.17.0.0/16%5Btcp%5D>
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] selecting traffic selectors
> for us:
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] config: 0.0.0.0/0,
> received: 0.0.0.0/0[tcp/http] <http://0.0.0.0/0%5Btcp/http%5D> => match:
> 0.0.0.0/0[tcp/http] <http://0.0.0.0/0%5Btcp/http%5D>
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] selecting proposal:
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] no acceptable
> ENCRYPTION_ALGORITHM found
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] selecting proposal:
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] no acceptable
> DIFFIE_HELLMAN_GROUP found
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] selecting proposal:
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] proposal matches
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] received proposals:
> ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ
> 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
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[CFG] selected proposal:
> ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] BK - In QM_INIT - calling
> child_sa_create
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] getting SPI for reqid {2}
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] sending XFRM_MSG_ALLOCSPI:
> => 248 bytes @ 0x7fdfab44c730
> 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 .............`..
> 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 ................
> 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 ................
> 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 ................
> 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 ................
> 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...
> 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...............
> 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 ................
> 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 ................
> 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 ................
> 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 ................
> 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 ................
> 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 ................
> 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 ................
> 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 ................
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] 240: 00 00 00 C0 FF FF FF
> CF .......
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[KNL] got SPI c959f83c for reqid
> {2}
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] BK - Entering QM_NEGOTIATED
> - in build_r
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] Hash(2) => 20 bytes @
> 0x7fdf8c004690
> 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.
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] 16: 14 18 D6 07
> ....
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[ENC] generating QUICK_MODE
> response 3414728253 [ HASH SA No ID ID ]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] next IV for MID 3414728253
> => 8 bytes @ 0x7fdf8c004b70
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[IKE] 0: 75 BF 60 BC 36 B9 AA
> F7 u.`.6...
> 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]
> 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]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 04[JOB] next event in 3s 999ms,
> waiting
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[MGR] checkin IKE_SA adtran-cert[2]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 14[MGR] check-in of IKE_SA
> successful.
> 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]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 07[NET] waiting for data on sockets
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[MGR] checkout IKE_SA by message
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[MGR] IKE_SA adtran-cert[2]
> successfully checked out
> 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]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] next IV for MID 2299459328=> 8 bytes @ 0x7fdf98000e00
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] 0: D1 2E 0B 3D 7A BB 2E
> 55 ...=z..U
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[ENC] parsed INFORMATIONAL_V1
> request 2299459328 [ HASH N((24577)) ]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] Hash => 20 bytes @
> 0x7fdf98001780
> 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..
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] 16: 09 4B CC 33
> .K.3
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] next IV for MID 2299459328=> 8 bytes @ 0x7fdf98000a70
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] 0: C0 3A 7A F3 D2 19 58
> 45 .:z...XE
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] received (24577) notify
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] BK - In QM_NEGOTIATED
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[IKE] BK - In QM_NEGOTIATED -
> returning without installing the SA
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[KNL] deleting SAD entry with SPI
> c959f83c (mark 0/0x00000000)
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[KNL] sending XFRM_MSG_DELSA: =>
> 40 bytes @ 0x7fdfaaa4b770
> 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 (............`..
> 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 ................
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[KNL] 32: C9 59 F8 3C 02 00 32
> 00 .Y.<..2.
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[KNL] deleted SAD entry with SPI
> c959f83c (mark 0/0x00000000)
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[MGR] checkin IKE_SA adtran-cert[2]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 15[MGR] check-in of IKE_SA
> successful.
> 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]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 07[NET] waiting for data on sockets
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[MGR] checkout IKE_SA by message
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[MGR] IKE_SA adtran-cert[2]
> successfully checked out
> 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]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[ENC] parsed QUICK_MODE request
> 3414728253 [ HASH ]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] Hash(3) => 20 bytes @
> 0x7fdf940012d0
> 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
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] 16: BF E0 58 74
> ..Xt
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] next IV for MID 3414728253
> => 8 bytes @ 0x7fdf94001280
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] 0: 01 E8 C5 A6 E3 66 2C
> 9C .....f,.
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] BK - In QM_INIT
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] sa payload missing
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] queueing INFORMATIONAL task
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] activating new tasks
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] activating INFORMATIONAL
> task
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] Hash => 20 bytes @
> 0x7fdf94000f00
> 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
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] 16: 07 98 B9 59
> ...Y
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[ENC] generating INFORMATIONAL_V1
> request 613066051 [ HASH N(CRIT) ]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] next IV for MID 613066051 =>
> 8 bytes @ 0x7fdf94001d20
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] 0: DC B3 F3 3D 08 37 F2
> E3 ...=.7..
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] next IV for MID 613066051 =>
> 8 bytes @ 0x7fdf94001940
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] 0: C9 7B 6C F6 3C 6A 95
> D5 .{l.<j..
> 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]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] activating new tasks
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[IKE] nothing to initiate
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[MGR] checkin IKE_SA adtran-cert[2]
> Dec 27 01:49:45 ip-10-0-0-139 charon: 16[MGR] check-in of IKE_SA
> successful.
> 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]
>
> =========================
>
>
>
>
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.strongswan.org/pipermail/users/attachments/20121231/dd3a56ae/attachment.html>
More information about the Users
mailing list