Thread: [Ipsec-tools-devel] FreeBSD and XP: "malformed cookie received or the spi expired"
Brought to you by:
mit_warlord,
netbsd
From: Brian C. <B.C...@po...> - 2005-12-29 09:35:25
|
Hello, I'm trying to get IPSEC to interoperate between FreeBSD 6.0-RELEASE and Windows XP SP2, but am getting a problem with key exchange. For the sake of simplicity I'm starting with tunnel mode and preshared key. The FreeBSD box has ipsec-tools 0.6.4 installed from ports. The FreeBSD box is on 192.168.1.100 and also has an outside Internet connection. The Windows box is on 192.168.1.200 and points its defaultroute at the FreeBSD box. The FreeBSD box has pf and nat so that the Windows box can see the outside world; before I add any ipsec policy, the Windows box can access the Internet just fine. Next I configure a policy on the XP box: ipseccmd -f 0=* -t 192.168.1.100 -a PRESHARE:"wibble" ipseccmd -f *=0 -t 192.168.1.200 -a PRESHARE:"wibble" I have not yet configured any corresponding policy on the FreeBSD box; I want to get as far as a successful key exchange first. Now when I type "ping 1.2.3.4" on the Windows box, I get Negotiating IP Security. Negotiating IP Security. Negotiating IP Security. Negotiating IP Security. and I see packets on UDP port 500 being exchanged. I get a lot of debug output for racoon, but these end up with Dec 29 09:09:02 candlerb racoon: DEBUG: === Dec 29 09:09:02 candlerb racoon: DEBUG: 68 bytes message received from 192.168.1.200[500] to 192.168.1.100[500] Dec 29 09:09:02 candlerb racoon: DEBUG: ab0413c9 b9395de1 30c86eb1 ad2cffe6 05100201 00000000 00000044 ccdf144b 206d64cb 16345837 9ce73c57 c1dd8d2a 3a4e4319 37988e04 a708bb39 8a0f15f5 ec17fa80 Dec 29 09:09:02 candlerb racoon: DEBUG: malformed cookie received or the spi expired. Dec 29 09:09:10 candlerb racoon: DEBUG: === Dec 29 09:09:10 candlerb racoon: DEBUG: 68 bytes message received from 192.168.1.200[500] to 192.168.1.100[500] Dec 29 09:09:10 candlerb racoon: DEBUG: ab0413c9 b9395de1 30c86eb1 ad2cffe6 05100201 00000000 00000044 ccdf144b 206d64cb 16345837 9ce73c57 c1dd8d2a 3a4e4319 37988e04 a708bb39 8a0f15f5 ec17fa80 Dec 29 09:09:10 candlerb racoon: DEBUG: malformed cookie received or the spi expired. My /usr/local/etc/racoon.conf is based on the supplied /usr/local/share/examples/ipsec-tools/racoon.conf.sample with just the path to the PSK file changed. Attached is the full debug log and racoon.conf, and a tcpdump of the exchange. I don't know what the Windows box will use as its isakmp identity type (ID_IPV4_ADDR? ID_FQDN?) and therefore what I should put in the LH column of the psk.txt file. However since the racoon debug output doesn't mention an identity, I am guessing it hasn't got as far as picking a PSK to use. However I'm afraid my knowledge of ISAKMP is very limited at present. I suspect I shall end up learning more than I wish to :-) Extra information: * When racoon starts, I get the following error logged: Dec 29 09:18:05 candlerb racoon: DEBUG: get pfkey X_SPDDUMP message Dec 29 09:18:05 candlerb racoon: DEBUG2: 02120200 02000000 00000000 29040000 Dec 29 09:18:05 candlerb racoon: DEBUG: pfkey X_SPDDUMP failed: No such file or directory During the exchange I also get Dec 29 09:18:59 candlerb racoon: DEBUG: an undead schedule has been deleted. I don't know if either of these is significant at all. * The FreeBSD box's kernel is GENERIC with 'options INET6' commented out and the following options added. options IPSEC options IPSEC_ESP options IPSEC_DEBUG device pf device pflog However I don't think it's getting as far as that being used. * My /etc/rc.conf contains ipsec_enable="YES" racoon_enable="YES" racoon_flags="-v -d -d -d -d -d" * I also tried setting my_identifier address 192.168.1.100; in /usr/local/etc/racoon/racoon.conf, but that didn't seem to make any difference. Regards, Brian. P.S. Supplementary question: anybody know how to remove or flush policies under Windows XP? At the moment I'm having to reboot the box every time :-O |
From: Brian C. <B.C...@po...> - 2005-12-29 10:02:56
|
> Dec 29 09:09:02 candlerb racoon: DEBUG: === > Dec 29 09:09:02 candlerb racoon: DEBUG: 68 bytes message received from 192.168.1.200[500] to 192.168.1.100[500] > Dec 29 09:09:02 candlerb racoon: DEBUG: ab0413c9 b9395de1 30c86eb1 ad2cffe6 05100201 00000000 00000044 ccdf144b 206d64cb 16345837 9ce73c57 c1dd8d2a 3a4e4319 37988e04 a708bb39 8a0f15f5 ec17fa80 > Dec 29 09:09:02 candlerb racoon: DEBUG: malformed cookie received or the spi expired. > Dec 29 09:09:10 candlerb racoon: DEBUG: === > Dec 29 09:09:10 candlerb racoon: DEBUG: 68 bytes message received from 192.168.1.200[500] to 192.168.1.100[500] > Dec 29 09:09:10 candlerb racoon: DEBUG: ab0413c9 b9395de1 30c86eb1 ad2cffe6 05100201 00000000 00000044 ccdf144b 206d64cb 16345837 9ce73c57 c1dd8d2a 3a4e4319 37988e04 a708bb39 8a0f15f5 ec17fa80 > Dec 29 09:09:10 candlerb racoon: DEBUG: malformed cookie received or the spi expired. Ah, I have discovered something. If I run racoon in the foreground (-F) I get helpful ERROR: messages, which don't appear anywhere in my syslog normally. This appears to be an issue with the FreeBSD port. So now I see: 2005-12-29 09:52:38: ERROR: /usr/local/etc/racoon/psk.txt has weak file permission 2005-12-29 09:52:38: ERROR: failed to open pre_share_key file /usr/local/etc/racoon/psk.txt 2005-12-29 09:52:38: ERROR: couldn't find the pskey for 192.168.1.200. 2005-12-29 09:52:38: ERROR: failed to process packet. 2005-12-29 09:52:38: ERROR: phase1 negotiation failed. 2005-12-29 09:52:38: DEBUG: an undead schedule has been deleted. 2005-12-29 09:52:38: DEBUG: === Fixing this with chmod 600 then gives me: 2005-12-29 09:54:39: ERROR: no policy found: 192.168.1.200/32[0] 0.0.0.0/0[0] proto=any dir=in 2005-12-29 09:54:39: ERROR: failed to get proposal for responder. 2005-12-29 09:54:39: ERROR: failed to pre-process packet. OK, well I'm heading in the right direction now. As for the syslog problem: it seems in plog.c that ERROR is mapped to LOG_INFO. However under FreeBSD, messages of 'daemon.info' by default don't go anywhere. In syslog.conf you have: *.notice;authpriv.none;kern.debug;lpr.info;mail.crit;news.err /var/log/messages security.* /var/log/security auth.info;authpriv.info /var/log/auth.log mail.info /var/log/maillog lpr.info /var/log/lpd-errs ftp.info /var/log/xferlog The port should probably make an attempt to fix that. Regards, Brian. |
From: Brian C. <B.C...@po...> - 2005-12-29 12:28:36
|
Final update: * Once I set a suitable policy in /etc/ipsec.conf on the FreeBSD side: spdadd 192.168.1.200 0.0.0.0/0 any -P in ipsec esp/tunnel/192.168.1.200-192.168.1.100/require; spdadd 0.0.0.0/0 192.168.1.200 any -P out ipsec esp/tunnel/192.168.1.100-192.168.1.200/require; it actually works! Blimey! Here are some tunnel-encapsulated pings. 10:27:18.484928 00:12:3f:69:c9:3c > 00:48:54:d0:bb:d5, ethertype IPv4 (0x0800), length 126: 192.168.1.200 > 192.168.1.100: ESP(spi=0x0dbbd4f8,seq=0xf), length 92 10:27:18.679597 00:48:54:d0:bb:d5 > 00:12:3f:69:c9:3c, ethertype IPv4 (0x0800), length 126: 192.168.1.100 > 192.168.1.200: ESP(spi=0xbfab7a58,seq=0xe), length 92 10:27:19.484913 00:12:3f:69:c9:3c > 00:48:54:d0:bb:d5, ethertype IPv4 (0x0800), length 126: 192.168.1.200 > 192.168.1.100: ESP(spi=0x0dbbd4f8,seq=0x10), length 92 10:27:19.683942 00:48:54:d0:bb:d5 > 00:12:3f:69:c9:3c, ethertype IPv4 (0x0800), length 126: 192.168.1.100 > 192.168.1.200: ESP(spi=0xbfab7a58,seq=0xf), length 92 * FreeBSD problem report filed. http://www.freebsd.org/cgi/query-pr.cgi?pr=91047 Sorry if this was a rather noisy set of postings, but perhaps they will help someone else who ends up in the same situation. Regards, Brian. |