Subject: bin/18331: racoon doesn't keep SAs in sync
To: None <gnats-bugs@gnats.netbsd.org>
From: None <M.Drochner@fz-juelich.de>
List: netbsd-bugs
Date: 09/18/2002 16:22:44
>Number:         18331
>Category:       bin
>Synopsis:       racoon doesn't keep SAs in sync
>Confidential:   no
>Severity:       critical
>Priority:       high
>Responsible:    bin-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Wed Sep 18 07:23:00 PDT 2002
>Closed-Date:
>Last-Modified:
>Originator:     Matthias Drochner
>Release:        NetBSD 1.6H
>Organization:
	KFA Juelich
>Environment:
System: NetBSD wlclient1 1.6H NetBSD 1.6H (ZELZ48) #20: Wed Sep 18 12:25:47 MEST 2002 drochner@wlclient1:/usr/users/drochner/NetBSD-current/sys/arch/i386/compile/ZELZ48 i386
Architecture: i386
Machine: i386
>Description:
	Im using an asymmetric IPSEC tunnel setup to secure a wireless LAN.
("assymetric" in a sense that one endpoint -a laptop- is tunnel endpoint
and connection endpoint at the same time, while the other -gateway- is tunnel
endpoint only. Probably this fact is not relevant for the bug described, just
for understanding the appended logfiles.)
Sometimes one side uses SAs which are not valid on the other, leading to
kernel messages
IPv4 ESP input: no key association found for spi XXX
and inability to get a connection.

This is easily triggered by (if not caused by) a time jump backwards
on one system.
The following output was created by setting the clock forward by one
minute before booting the laptop. During boot, ntpdate will correct the
clock which is enough to confuse the IKE. (the bug was already observed
after time jumps of less than 2 seconds)
The gateway has 2 SAs in each direction after that, and the laptop only
one for each. The gateway obviously tries to use the SPI unknown to the
laptop.
To get a working connection, a "setkey -F" on the gateway can be used.
This cannot be done by laptop users in the intended application, so
unattended use in a production environment is not possible - that's
the reason this PR is marked "critical".

I'm appending the output of "setkey -D" of both systems and excerpts
of /var/log/messages.

1. setkey -D on the laptop:
134.94.206.11 134.94.206.1 
	esp mode=tunnel spi=175289342(0x0a72b3fe) reqid=0(0x00000000)
	E: 3des-cbc  78aa5431 45e5d7f8 b580ba4c b9f6979b 9d0dd1d4 a7173e1d
	A: hmac-sha1  cc04b594 c8d3fb41 83bd2dfe 6331a478 1fd9db17
	seq=0x00000000 replay=4 flags=0x00000000 state=mature 
	created: Sep 18 15:23:41 2002	current: Sep 18 15:24:13 2002
	diff: 32(s)	hard: 43200(s)	soft: 34560(s)
	last:                     	hard: 0(s)	soft: 0(s)
	current: 0(bytes)	hard: 0(bytes)	soft: 0(bytes)
	allocated: 0	hard: 0	soft: 0
	sadb_seq=1 pid=259 refcnt=1
134.94.206.1 134.94.206.11 
	esp mode=tunnel spi=148340590(0x08d77f6e) reqid=0(0x00000000)
	E: 3des-cbc  5fe7280f 2b219d27 d2016a41 c9468525 ebd4f1b2 c3357c6c
	A: hmac-sha1  08d3c43d 9b96dcc6 e61fb2fd 92929afa 679fd10e
	seq=0x00000000 replay=4 flags=0x00000000 state=mature 
	created: Sep 18 15:23:41 2002	current: Sep 18 15:24:13 2002
	diff: 32(s)	hard: 43200(s)	soft: 34560(s)
	last:                     	hard: 0(s)	soft: 0(s)
	current: 0(bytes)	hard: 0(bytes)	soft: 0(bytes)
	allocated: 0	hard: 0	soft: 0
	sadb_seq=0 pid=259 refcnt=1

2. setkey -D on the gateway:
134.94.206.1 134.94.206.11 
	esp mode=tunnel spi=148340590(0x08d77f6e) reqid=0(0x00000000)
	E: 3des-cbc  5fe7280f 2b219d27 d2016a41 c9468525 ebd4f1b2 c3357c6c
	A: hmac-sha1  08d3c43d 9b96dcc6 e61fb2fd 92929afa 679fd10e
	seq=0x00000000 replay=4 flags=0x00000000 state=mature 
	created: Sep 18 15:23:41 2002	current: Sep 18 15:24:28 2002
	diff: 47(s)	hard: 43200(s)	soft: 34560(s)
	last:                     	hard: 0(s)	soft: 0(s)
	current: 0(bytes)	hard: 0(bytes)	soft: 0(bytes)
	allocated: 0	hard: 0	soft: 0
	sadb_seq=3 pid=362 refcnt=1
134.94.206.1 134.94.206.11 
	esp mode=tunnel spi=39998711(0x026254f7) reqid=0(0x00000000)
	E: 3des-cbc  b0ca90cb fba9baaa 1421c36b aa28cd44 a3397d7b e8c70a7a
	A: hmac-sha1  ef7890ba c8275d7e 7f9cf524 3cc4c49e e772d150
	seq=0x00000008 replay=4 flags=0x00000000 state=mature 
	created: Sep 18 15:23:17 2002	current: Sep 18 15:24:28 2002
	diff: 71(s)	hard: 43200(s)	soft: 34560(s)
	last: Sep 18 15:23:33 2002	hard: 0(s)	soft: 0(s)
	current: 976(bytes)	hard: 0(bytes)	soft: 0(bytes)
	allocated: 8	hard: 0	soft: 0
	sadb_seq=2 pid=362 refcnt=2
134.94.206.11 134.94.206.1 
	esp mode=tunnel spi=175289342(0x0a72b3fe) reqid=0(0x00000000)
	E: 3des-cbc  78aa5431 45e5d7f8 b580ba4c b9f6979b 9d0dd1d4 a7173e1d
	A: hmac-sha1  cc04b594 c8d3fb41 83bd2dfe 6331a478 1fd9db17
	seq=0x00000000 replay=4 flags=0x00000000 state=mature 
	created: Sep 18 15:23:41 2002	current: Sep 18 15:24:28 2002
	diff: 47(s)	hard: 43200(s)	soft: 34560(s)
	last:                     	hard: 0(s)	soft: 0(s)
	current: 0(bytes)	hard: 0(bytes)	soft: 0(bytes)
	allocated: 0	hard: 0	soft: 0
	sadb_seq=1 pid=362 refcnt=1
134.94.206.11 134.94.206.1 
	esp mode=tunnel spi=47245265(0x02d0e7d1) reqid=0(0x00000000)
	E: 3des-cbc  4ae627b6 653cd829 9ee45592 d2e62f65 18b150b6 3ad96c2b
	A: hmac-sha1  93d810a5 b6629c3b b68e45cb 4f3714cf 17e47c3c
	seq=0x00000006 replay=4 flags=0x00000000 state=mature 
	created: Sep 18 15:23:17 2002	current: Sep 18 15:24:28 2002
	diff: 71(s)	hard: 43200(s)	soft: 34560(s)
	last: Sep 18 15:23:18 2002	hard: 0(s)	soft: 0(s)
	current: 456(bytes)	hard: 0(bytes)	soft: 0(bytes)
	allocated: 6	hard: 0	soft: 0
	sadb_seq=0 pid=362 refcnt=1

3. messages on the laptop
Sep 18 15:24:15 wlclient1 racoon: INFO: main.c:168:main(): @(#)package version netbsd-20020507 
Sep 18 15:24:15 wlclient1 racoon: INFO: main.c:170:main(): @(#)internal version 20001216 sakane@kame.net 
Sep 18 15:24:15 wlclient1 racoon: INFO: main.c:171:main(): @(#)This product linked OpenSSL 0.9.6g 9 Aug 2002 (http://www.openssl.org/) 
Sep 18 15:24:15 wlclient1 racoon: INFO: isakmp.c:1357:isakmp_open(): 134.94.206.11[500] used as isakmp port (fd=7) 
Sep 18 15:24:15 wlclient1 racoon: INFO: isakmp.c:1357:isakmp_open(): fe80::207:ebff:fe31:85a3%an0[500] used as isakmp port (fd=8) 
Sep 18 15:24:15 wlclient1 racoon: INFO: isakmp.c:1357:isakmp_open(): fe80::1%lo0[500] used as isakmp port (fd=9) 
Sep 18 15:24:15 wlclient1 racoon: INFO: isakmp.c:1357:isakmp_open(): ::1[500] used as isakmp port (fd=10) 
Sep 18 15:24:15 wlclient1 racoon: INFO: isakmp.c:1357:isakmp_open(): 127.0.0.1[500] used as isakmp port (fd=11) 
Sep 18 15:24:15 wlclient1 savecore: no core dump
Sep 18 15:24:16 wlclient1 racoon: INFO: isakmp.c:1683:isakmp_post_acquire(): IPsec-SA request for 134.94.206.1 queued due to no phase1 found. 
Sep 18 15:24:16 wlclient1 racoon: INFO: isakmp.c:795:isakmp_ph1begin_i(): initiate new phase 1 negotiation: 134.94.206.11[500]<=>134.94.206.1[500] 
Sep 18 15:24:16 wlclient1 racoon: INFO: isakmp.c:800:isakmp_ph1begin_i(): begin Aggressive mode. 
Sep 18 15:24:16 wlclient1 racoon: INFO: vendorid.c:128:check_vendorid(): received Vendor ID: KAME/racoon 
Sep 18 15:24:17 wlclient1 racoon: INFO: isakmp.c:2411:log_ph1established(): ISAKMP-SA established 134.94.206.11[500]-134.94.206.1[500] spi:8200c350cef0689a:5ad9e4a0b7f3e4c9 
Sep 18 15:24:17 wlclient1 racoon: INFO: isakmp.c:939:isakmp_ph2begin_i(): initiate new phase 2 negotiation: 134.94.206.11[0]<=>134.94.206.1[0] 
Sep 18 15:24:17 wlclient1 racoon: INFO: pfkey.c:1107:pk_recvupdate(): IPsec-SA established: ESP/Tunnel 134.94.206.1->134.94.206.11 spi=39998711(0x26254f7) 
Sep 18 15:24:17 wlclient1 racoon: INFO: pfkey.c:1319:pk_recvadd(): IPsec-SA established: ESP/Tunnel 134.94.206.11->134.94.206.1 spi=47245265(0x2d0e7d1) 
Sep 18 15:23:18 wlclient1 ntpdate[135]: step time server 134.94.233.52 offset -59.462726 sec
Sep 18 15:23:18 wlclient1 racoon: INFO: pfkey.c:1365:pk_recvexpire(): IPsec-SA expired: ESP/Tunnel 134.94.206.11->134.94.206.1 spi=47245265(0x2d0e7d1) 
Sep 18 15:23:18 wlclient1 racoon: INFO: isakmp.c:939:isakmp_ph2begin_i(): initiate new phase 2 negotiation: 134.94.206.11[0]<=>134.94.206.1[0] 
Sep 18 15:23:18 wlclient1 racoon: INFO: isakmp.c:1515:isakmp_ph1expire(): ISAKMP-SA expired 134.94.206.11[500]-134.94.206.1[500] spi:8200c350cef0689a:5ad9e4a0b7f3e4c9 
Sep 18 15:23:18 wlclient1 racoon: INFO: pfkey.c:1365:pk_recvexpire(): IPsec-SA expired: ESP/Tunnel 134.94.206.1->134.94.206.11 spi=39998711(0x26254f7) 
Sep 18 15:23:18 wlclient1 racoon: ERROR: isakmp.c:1735:isakmp_post_getspi(): the negotiation is stopped, because there is no suitable ISAKMP-SA. 
Sep 18 15:23:18 wlclient1 racoon: ERROR: pfkey.c:895:pk_recvgetspi(): failed to start post getspi. 
Sep 18 15:23:19 wlclient1 racoon: INFO: isakmp.c:1515:isakmp_ph1expire(): ISAKMP-SA expired 134.94.206.11[500]-134.94.206.1[500] spi:8200c350cef0689a:5ad9e4a0b7f3e4c9 
Sep 18 15:23:20 wlclient1 ntpd[204]: ntpd 4.0.99i Fri Aug  2 17:51:24 MEST 2002 (1)
Sep 18 15:23:20 wlclient1 ntpd[204]: precision = 6 usec
Sep 18 15:23:20 wlclient1 ntpd[204]: using kernel phase-lock loop 0040
Sep 18 15:23:20 wlclient1 ntpd[204]: frequency initialized 48.632 from /var/db/ntp.drift
Sep 18 15:23:20 wlclient1 ntpd[204]: using kernel phase-lock loop 0041
Sep 18 15:23:20 wlclient1 racoon: INFO: isakmp.c:1563:isakmp_ph1delete(): ISAKMP-SA deleted 134.94.206.11[500]-134.94.206.1[500] spi:8200c350cef0689a:5ad9e4a0b7f3e4c9 
Sep 18 15:23:27 wlclient1 /netbsd: IPv4 ESP input: no key association found for spi 39998711

4. messages on the gateway
Sep 18 15:23:12 zel407 dhcpd: DHCPREQUEST for 134.94.206.11 from 00:07:eb:31:85:a3 via ex1
Sep 18 15:23:12 zel407 dhcpd: DHCPACK on 134.94.206.11 to 00:07:eb:31:85:a3 via ex1
Sep 18 15:23:17 zel407 racoon: INFO: isakmp.c:891:isakmp_ph1begin_r(): respond new phase 1 negotiation: 134.94.206.1[500]<=>134.94.206.11[500] 
Sep 18 15:23:17 zel407 racoon: INFO: isakmp.c:896:isakmp_ph1begin_r(): begin Aggressive mode. 
Sep 18 15:23:17 zel407 racoon: INFO: isakmp.c:2411:log_ph1established(): ISAKMP-SA established 134.94.206.1[500]-134.94.206.11[500] spi:8200c350cef0689a:5ad9e4a0b7f3e4c9 
Sep 18 15:23:17 zel407 racoon: INFO: isakmp.c:1046:isakmp_ph2begin_r(): respond new phase 2 negotiation: 134.94.206.1[0]<=>134.94.206.11[0] 
Sep 18 15:23:17 zel407 racoon: INFO: pfkey.c:1107:pk_recvupdate(): IPsec-SA established: ESP/Tunnel 134.94.206.11->134.94.206.1 spi=47245265(0x2d0e7d1) 
Sep 18 15:23:17 zel407 racoon: INFO: pfkey.c:1319:pk_recvadd(): IPsec-SA established: ESP/Tunnel 134.94.206.1->134.94.206.11 spi=39998711(0x26254f7) 
Sep 18 15:23:40 zel407 racoon: INFO: isakmp.c:891:isakmp_ph1begin_r(): respond new phase 1 negotiation: 134.94.206.1[500]<=>134.94.206.11[500] 
Sep 18 15:23:40 zel407 racoon: INFO: isakmp.c:896:isakmp_ph1begin_r(): begin Aggressive mode. 
Sep 18 15:23:40 zel407 racoon: INFO: isakmp.c:2411:log_ph1established(): ISAKMP-SA established 134.94.206.1[500]-134.94.206.11[500] spi:910aa1ecf5a984af:2ae41113b5f8a142 
Sep 18 15:23:41 zel407 racoon: INFO: isakmp.c:1046:isakmp_ph2begin_r(): respond new phase 2 negotiation: 134.94.206.1[0]<=>134.94.206.11[0] 
Sep 18 15:23:41 zel407 racoon: INFO: pfkey.c:1107:pk_recvupdate(): IPsec-SA established: ESP/Tunnel 134.94.206.11->134.94.206.1 spi=175289342(0xa72b3fe) 
Sep 18 15:23:41 zel407 racoon: INFO: pfkey.c:1319:pk_recvadd(): IPsec-SA established: ESP/Tunnel 134.94.206.1->134.94.206.11 spi=148340590(0x8d77f6e) 



>How-To-Repeat:
	as described above
>Fix:
	
>Release-Note:
>Audit-Trail:
>Unformatted: