Menu
▾
▴
[Ipsec-tools-users] ERROR: fatal INVALID-SPI notify messsage, phase1 should be deleted.
|
From: Brian A. S. <lav...@sp...> - 2007-05-03 16:28:25
|
Okay with a variety of versions (4.8->5.0) on Linux/OSX/Windows, I can cause the daemon / SPD/SAD database to become out of sync / stale by reconnecting and disconnecting in sequence. # uname -a FreeBSD headend 6.1-RELEASE-p15 FreeBSD 6.1-RELEASE-p15 #3: Fri Apr 27 18:23:12 UTC 2007 root@headend:/usr/obj/usr/src/sys/TEST i386 [root@headend ~/ipsec-tools-0.7-beta3]# /usr/local/sbin/racoon -Fv4d Foreground mode. 2007-05-03 16:22:05: INFO: @(#)ipsec-tools 0.7-beta3 (http://ipsec-tools.sourceforge.net) 2007-05-03 16:22:05: INFO: @(#)This product linked OpenSSL 0.9.7e-p1 25 Oct 2004 (http://www.openssl.org/) 2007-05-03 16:22:05: INFO: Reading configuration from "/usr/local/etc/racoon.conf" At startup no entries: [root@headend ~/ipsec-tools-0.7-beta3]# setkey -D No SAD entries. [root@headend ~/ipsec-tools-0.7-beta3]# setkey -DP No SPD entries. Client connects: # setkey -DP 169.254.128.100[any] 0.0.0.0/0[any] any in ipsec esp/tunnel/206.210.89.206-206.210.89.232/require created: May 3 16:23:17 2007 lastused: May 3 16:24:53 2007 lifetime: 2147483(s) validtime: 0(s) spid=16480 seq=1 pid=796 refcnt=1 0.0.0.0/0[any] 169.254.128.100[any] any out ipsec esp/tunnel/206.210.89.232-206.210.89.206/require created: May 3 16:23:17 2007 lastused: May 3 16:24:53 2007 lifetime: 2147483(s) validtime: 0(s) spid=16481 seq=0 pid=796 refcnt=1 206.210.89.232 206.210.89.206 esp mode=tunnel spi=1918782465(0x725e4c01) reqid=0(0x00000000) E: 3des-cbc ad611e53 7b33e803 45e35574 317777f5 9b5b56a8 ad4e05ce A: hmac-sha1 db257f9f 57c796e3 b1afa948 fccc5276 90926def seq=0x0000004b replay=4 flags=0x00000000 state=mature created: May 3 16:23:17 2007 current: May 3 16:25:06 2007 diff: 109(s) hard: 2147483(s) soft: 1717986(s) last: May 3 16:25:05 2007 hard: 0(s) soft: 0(s) current: 10200(bytes) hard: 0(bytes) soft: 0(bytes) allocated: 75 hard: 0 soft: 0 sadb_seq=1 pid=800 refcnt=2 206.210.89.206 206.210.89.232 esp mode=tunnel spi=150500957(0x08f8765d) reqid=0(0x00000000) E: 3des-cbc cf40d32f b8ec6af4 69cbde8d 1b6da68b fa803bd6 e7ebbb4e A: hmac-sha1 12b3e564 d7eba208 909120bd cacd074d 399b9a4d seq=0x0000004b replay=4 flags=0x00000000 state=mature created: May 3 16:23:17 2007 current: May 3 16:25:06 2007 diff: 109(s) hard: 2147483(s) soft: 1717986(s) last: May 3 16:25:05 2007 hard: 0(s) soft: 0(s) current: 6300(bytes) hard: 0(bytes) soft: 0(bytes) allocated: 75 hard: 0 soft: 0 sadb_seq=0 pid=800 refcnt=1 Then the client disconnects: 2007-05-03 16:25:19: DEBUG: 76 bytes message received from 206.210.89.206[500] to 206.210.89.232[500] 2007-05-03 16:25:19: DEBUG: 14b455ad b1a04290 aaf0fb76 9b63f0c1 08100501 4d969798 0000004c 4dd5151c 3f50880f 5d98d339 504d23e8 775c9d78 be9c6a10 3baf5999 1d582a6a e061df93 5586fe37 572bd22a 96df7834 2007-05-03 16:25:19: DEBUG: receive Information. 2007-05-03 16:25:19: DEBUG: compute IV for phase2 2007-05-03 16:25:19: DEBUG: phase1 last IV: 2007-05-03 16:25:19: DEBUG: 40fdf03d 3a4e7fa0 4d969798 2007-05-03 16:25:19: DEBUG: hash(sha1) 2007-05-03 16:25:19: DEBUG: encryption(3des) 2007-05-03 16:25:19: DEBUG: phase2 IV computed: 2007-05-03 16:25:19: DEBUG: f0022e62 3a370dd2 2007-05-03 16:25:19: DEBUG: begin decryption. 2007-05-03 16:25:19: DEBUG: encryption(3des) 2007-05-03 16:25:19: DEBUG: IV was saved for next processing: 2007-05-03 16:25:19: DEBUG: 572bd22a 96df7834 2007-05-03 16:25:19: DEBUG: encryption(3des) 2007-05-03 16:25:19: DEBUG: with key: 2007-05-03 16:25:19: DEBUG: 1d27e9c3 aca27fc5 7b338833 2bc7bde6 cfd9f9be c4cd4ab1 2007-05-03 16:25:19: DEBUG: decrypted payload by IV: 2007-05-03 16:25:19: DEBUG: f0022e62 3a370dd2 2007-05-03 16:25:19: DEBUG: decrypted payload, but not trimed. 2007-05-03 16:25:19: DEBUG: 0c000018 f68de8ae 65cf35d9 fdd46ef6 f9d6d665 9f0a272d 00000014 00000001 03040002 725e4c01 08f8765d 00000000 2007-05-03 16:25:19: DEBUG: padding len=1 2007-05-03 16:25:19: DEBUG: skip to trim padding. 2007-05-03 16:25:19: DEBUG: decrypted. 2007-05-03 16:25:19: DEBUG: 14b455ad b1a04290 aaf0fb76 9b63f0c1 08100501 4d969798 0000004c 0c000018 f68de8ae 65cf35d9 fdd46ef6 f9d6d665 9f0a272d 00000014 00000001 03040002 725e4c01 08f8765d 00000000 2007-05-03 16:25:19: DEBUG: IV freed 2007-05-03 16:25:19: DEBUG: HASH with: 2007-05-03 16:25:19: DEBUG: 4d969798 00000014 00000001 03040002 725e4c01 08f8765d 2007-05-03 16:25:19: DEBUG: hmac(hmac_sha1) 2007-05-03 16:25:19: DEBUG: HASH computed: 2007-05-03 16:25:19: DEBUG: f68de8ae 65cf35d9 fdd46ef6 f9d6d665 9f0a272d 2007-05-03 16:25:19: DEBUG: hash validated. 2007-05-03 16:25:19: DEBUG: begin. 2007-05-03 16:25:19: DEBUG: seen nptype=8(hash) 2007-05-03 16:25:19: DEBUG: seen nptype=12(delete) 2007-05-03 16:25:19: DEBUG: succeed. 2007-05-03 16:25:19: DEBUG: delete payload for protocol ESP 2007-05-03 16:25:19: DEBUG: call pfkey_send_dump 2007-05-03 16:25:19: DEBUG: pk_recv: retry[0] recv() 2007-05-03 16:25:19: DEBUG: pk_recv: retry[0] recv() 2007-05-03 16:25:19: DEBUG: purged SAs. 2007-05-03 16:25:19: DEBUG: === 2007-05-03 16:25:19: DEBUG: 84 bytes message received from 206.210.89.206[500] to 206.210.89.232[500] 2007-05-03 16:25:19: DEBUG: 14b455ad b1a04290 aaf0fb76 9b63f0c1 08100501 465c02c9 00000054 60d7f3fc f4e50c5a f65f5475 8ff01610 4ba57bc1 a57d14ce c14ca6ad cf381aaa fd7ea36a 1cf35a14 c52a76fc 1be6fe2d 5ec7a44b 24cc92a0 2007-05-03 16:25:19: DEBUG: receive Information. 2007-05-03 16:25:19: DEBUG: compute IV for phase2 2007-05-03 16:25:19: DEBUG: phase1 last IV: 2007-05-03 16:25:19: DEBUG: 40fdf03d 3a4e7fa0 465c02c9 2007-05-03 16:25:19: DEBUG: hash(sha1) 2007-05-03 16:25:19: DEBUG: encryption(3des) 2007-05-03 16:25:19: DEBUG: phase2 IV computed: 2007-05-03 16:25:19: DEBUG: 34c57a72 4ea25413 2007-05-03 16:25:19: DEBUG: begin decryption. 2007-05-03 16:25:19: DEBUG: encryption(3des) 2007-05-03 16:25:19: DEBUG: IV was saved for next processing: 2007-05-03 16:25:19: DEBUG: 5ec7a44b 24cc92a0 2007-05-03 16:25:19: DEBUG: encryption(3des) 2007-05-03 16:25:19: DEBUG: with key: 2007-05-03 16:25:19: DEBUG: 1d27e9c3 aca27fc5 7b338833 2bc7bde6 cfd9f9be c4cd4ab1 2007-05-03 16:25:19: DEBUG: decrypted payload by IV: 2007-05-03 16:25:19: DEBUG: 34c57a72 4ea25413 2007-05-03 16:25:19: DEBUG: decrypted payload, but not trimed. 2007-05-03 16:25:19: DEBUG: 0c000018 83026ff5 76509fbb 989821c3 1acc0eb2 6f193e01 0000001c 00000000 01100001 14b455ad b1a04290 aaf0fb76 9b63f0c1 00000000 2007-05-03 16:25:19: DEBUG: padding len=1 2007-05-03 16:25:19: DEBUG: skip to trim padding. 2007-05-03 16:25:19: DEBUG: decrypted. 2007-05-03 16:25:19: DEBUG: 14b455ad b1a04290 aaf0fb76 9b63f0c1 08100501 465c02c9 00000054 0c000018 83026ff5 76509fbb 989821c3 1acc0eb2 6f193e01 0000001c 00000000 01100001 14b455ad b1a04290 aaf0fb76 9b63f0c1 00000000 2007-05-03 16:25:19: DEBUG: IV freed 2007-05-03 16:25:19: DEBUG: HASH with: 2007-05-03 16:25:19: DEBUG: 465c02c9 0000001c 00000000 01100001 14b455ad b1a04290 aaf0fb76 9b63f0c1 2007-05-03 16:25:19: DEBUG: hmac(hmac_sha1) 2007-05-03 16:25:19: DEBUG: HASH computed: 2007-05-03 16:25:19: DEBUG: 83026ff5 76509fbb 989821c3 1acc0eb2 6f193e01 2007-05-03 16:25:19: DEBUG: hash validated. 2007-05-03 16:25:19: DEBUG: begin. 2007-05-03 16:25:19: DEBUG: seen nptype=8(hash) 2007-05-03 16:25:19: DEBUG: seen nptype=12(delete) 2007-05-03 16:25:19: DEBUG: succeed. 2007-05-03 16:25:19: ERROR: delete payload with invalid doi:0. 2007-05-03 16:25:19: DEBUG: delete payload for protocol ISAKMP 2007-05-03 16:25:19: INFO: ISAKMP-SA expired 206.210.89.232[500]-206.210.89.206[500] spi:14b455adb1a04290:aaf0fb769b63f0c1 2007-05-03 16:25:19: DEBUG: purged SAs. 2007-05-03 16:25:20: INFO: ISAKMP-SA deleted 206.210.89.232[500]-206.210.89.206[500] spi:14b455adb1a04290:aaf0fb769b63f0c1 2007-05-03 16:25:20: INFO: Released port 0 2007-05-03 16:25:20: DEBUG: IV freed But the SAD/SPD entries remain: [root@headend ~/ipsec-tools-0.7-beta3]# setkey -DP | wc -l 14 [root@headend ~/ipsec-tools-0.7-beta3]# setkey -D | wc -l 22 It's possible that this is a FreeBSD 6.1 bug; but I'm doubltful ~BAS This was compiled with: $ ./configure --enable-adminport --enable-hybrid --enable-frag --enable-stts --enable-dpd --enable-fastquit --with-libpam --enable-natt=yes l8* -lava (Brian A. Seklecki - Pittsburgh, PA, USA) http://www.spiritual-machines.org/ "...from back in the heady days when "helpdesk" meant nothing, "diskquota" meant everything, and lives could be bought and sold for a couple of pages of laser printout - and frequently were." |