On Tue 09 Jul 2002 at 08:33:37 +0900, itojun@iijlab.net wrote:
> >>I have the console output now, it crashed the very first time this time
> >>around. Another difference is that the values as printed seem ok now.
> >>Pid 176 would be raccoon, I expect.
> >	my wild guess is that you are running two copies of racoon daemon by
> >	mistake.
> 
> 	sorry, i checked your original posting.  could you check where the
> 	kernel code is returning EINVAL in UPDATE message handling?  it should
> 	be somewhere inside sys/netkey/*.c (some printfs should do it).

I added some printf() calls in sys/netkey/key.c in the function
key_update(). Now I get this on my console (racoon output mixed with
kernel output).  I show the spi from the kernel messages and the one
other occurrance of it. Could it be some time-out because there is such
a long time (1 minute 21 seconds) between these parts?

The kernel printed the messages "*** key.c:key_update" (twice) when
entering the function and "key_update: no such a SA found
(spi:190697512)" (at least once) when failing the function and they are
repeated by syslog.

2002-07-09 23:41:53: DEBUG: pfkey.c:192:pfkey_handler(): get pfkey GETSPI message
2002-07-09 23:41:53: DEBUG: pfkey.c:873:pk_recvgetspi(): pfkey GETSPI succeeded: ESP/Transport 10.0.0.5->10.0.0.7 spi=190697512(0xb5dd028)

... (in this omitted part the string 190697512 does not occur) ...

2002-07-09 23:43:14: DEBUG: plog.c:193:plogdump(): 
4dcffc6f 573a5cbb e3486ea7 f8b180c2 ce0f47b1 7d8f312e 8f1967c9 870369b8
fcf351b1 177f0f50 477ce23c e7c8a953 b69a1e52 16a33a18 d9fd3b3c 0e4acab1
216cd6b9 b04ff226 fe088027 063cd472
2002-07-09 23:43:14: DEBUG: oakley.c:389:oakley_compute_keymat(): KEYMAT compute
d.
2002-07-09 23:43:14: DEBUG: isakmp_quick.c:649:quick_i2send(): call pk_sendupdat
e
2002-07-09 23:43:14: DEBUG: algorithm.c:509:alg_ipsec_encdef(): encription(3des)
2002-07-09 23:43:14: DEBUG: algorithm.c:552:alg_ipsec_hmacdef(): hmac(hmac_sha1)
2002-07-09 23:43:14: DEBUG: pfkey.c:971:pk*** key.c:key_update
)
2002-07-09 23:43:13: DEBUG: algorithm.c:322:alg_oakley_hmacdef(): hmac(hmac_sha1
)
2002-07-09 23:43:13: DEBUG: plog.c:193:plogdump(): 
b3f0a0b8 f78d49ec aea60b2d c495a0f5 1b56fed4 ac4ef49b c900bac6 fb64ee68
c3d0ef4e a431abb9 7e3c0642 5f91ab66 b9afb1ff 7b3c19c6 bd969a9c 5e2a5cfa
50d5bc3a 6733bffe 691aa0a8 cfee1871
2002-07-09 23:43:13: DEBUG: oakley.c:461:oakley_compute_keymat_x(): KEYMAT compu
te with
2002-07-09 23:43:13: DEBUG: plog.c:193:plogdump(): 
ee172e9c cc5e9811 b776d2ad c1a8a1f7 9816bf77 a2b0084a 43dd4598 82a12f22
104b641a 19027015 b4dcb3fb 654afa1a b44b46e3 beb85d32 e8feb0f3 dae2986d
2d93eae1 9b5d348e ec8d91d8 3b610557 241e8ee8 c86e666a 241b69de 54b49e15
ad7c6a90 27a68c7d c9760cb0 84b1a76f 686a0257 4ca9c355 3beb7171 058395a8
0303a822 6bb9851c 6477fbeb 66ea2987 a54b1482 3cae0ad7 8f96eaf2 6bbdbe74
dc26f9c6 17
2002-07-09 23:43:13: DEBUG: algorithm.c:322:alg_oakley_hmacdef(): hmac(hmac_sha1
)
2002-07-09 23:43:14: DEBUG: algorithm.c:509:alg_ipsec_encdef(): encription(3des)
2002-07-09 23:43:14: DEBUG: algorithm.c:552:alg_ipsec_hmacdef(): hmac(hmac_sha1)
2002-07-09 23:43:14: DEBUG: oakley.c:494:oakley_compute_keymat_x(): encklen=192 
authklen=160
2002-07-09 23:43:14: DEBUG: oakley.c:501:oakley_compute_keymat_x(): generating 6
40 bits of key (dupkeymat=4)
2002-07-09 23:43:14: DEBUG: oakley.c:519:oakley_compute_keymat_x(): generating K
1...K4 for KEYMAT.
2002-07-09 23:43:14: DEBUG: algorithm.c:322:alg_oakley_hmacdef(): hmac(hmac_sha1
)
2002-07-09 23:43:14: DEBUG: algorithm.c:322:alg_oakley_hmacdef(): hmac(hmac_sha1
)
2002-07-09 23:43:14: DEBUG: algorithm.c:322:alg_oakley_hmacdef(): hmac(hmac_sha1
)
2002-07-09 23:43:14: DEBUG: plog.c:193:plogdump(): 
4dcffc6f 573a5cbb e3486ea7 f8b180c2 ce0f47b1 7d8f312e 8f1967c9 870369b8
fcf351b1 177f0f50 477ce23c e7c8a953 b69a1e52 16a33a18 d9fd3b3c 0e4acab1
216cd6b9 b04ff226 fe088027 063cd472
2002-07-09 23:43:14: DEBUG: oakley.c:389:oakley_compute_keymat(): KEYMAT compute
d.
2002-07-09 23:43:14: DEBUG: isakmp_quick.c:649:quick_i2send(): call pk_sendupdat
e
2002-07-09 23:43:14: DEBUG: algorithm.c:509:alg_ipsec_encdef(): encription(3des)
2002-07-09 23:43:14: DEBUG: algorithm.c:552:alg_ipsec_hmacdef(): hmac(hmac_sha1)
2002-07-09 23:43:14: DEBUG: pfkey.c:971:pk*** key.c:key_update
_sekey_update: no such a SA found (spi:190697512)
ndupdate(): call pfkey_send_update
2002-07-09 23:43:15: DEBUG: isakmp_quick.c:654:quick_i2send(): pfkey update sent
.
Jul  9 23:43:15 xzan /netbsd: *** key.c:key_update
Jul  9 23:43:15 xzan /netbsd: key_update: no such a SA found (spi:190697512)
2002-07-09 23:43:15: DEBUG: algorithm.c:509:alg_ipsec_encdef(): encription(3des)
Jul  9 23:43:15 xzan /netbsd: key_update: no such a SA found (spi:190697512)
2002-07-09 23:43:15: DEBUG: algorithm.c:552:alg_ipsec_hmacdef(): hmac(hmac_sha1)
2002-07-09 23:43:16: DEBUG: pfkey.c:1212:pk_sendadd(): call pfkey_send_add
2002-07-09 23:43:16: DEBUG: isakmp_quick.c:661:quick_i2send(): pfkey add sent.


> itojun
-Olaf.
-- 
___ Olaf 'Rhialto' Seibert - rhialto@       -- Woe betide the one who feels
\X/ polderland.nl  -- remorse without sin - Tom Poes, "Het boze oog", 4444.