[strongSwan] SAD entry deleted when INFORMATIONAL_V1 message received in QM_NEGOTIATED state
Bharath Kumar
cbkumar at gmail.com
Thu Dec 27 08:21:02 CET 2012
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] === 172.17.0.0/16[tcp]
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] => match: 172.17.0.0/16[tcp]
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] => match: 0.0.0.0/0[tcp/http]
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/20121226/32d48b56/attachment.html>
More information about the Users
mailing list