IPSEC btwn stable and Linksys BEFVP41 stopped working.

Tue Jan 13 14:29:07 PST 2004

Hi,

I have been using IPsec to communicate between a laptop that tracks
-stable and a Linksys BEFVP41 router.

I only use it infrequently, but it's been working great.  My setup is
as described in http://grapeape.alerce.com/linksys-ipsec/article.html
(which I am planning to submit to the handbook when it's done).

I'm no longer able to make an ipsec connection, and I can't put my
finger on anything that's changed.  The most obvious candidate is the
move from 4.8 to 4.9.  It could also be that something involving the
racoon port needs to move forward to match 4.9?  I have recompiled the
version of the port that I'm using, distinfo says:

MD5 (racoon-20030711a.tar.gz) = 0546688efd5bb3725c8243045500a48a

I'm loath to start blindly updating everything in sight, and since
none of the comments in the racoon CVS directory talk about "fixing it
for 4.9" or anything, I've been sticking with what I have for now.

I have two hopefully useful pieces of information.

Here's a trace from "racoon -F -d -f racoon.conf"

   2004-01-13 13:36:39: INFO: main.c:172:main(): @(#)package version freebsd-20030711a
   2004-01-13 13:36:39: INFO: main.c:174:main(): @(#)internal version 20001216 sakane at kame.net
   2004-01-13 13:36:39: INFO: main.c:175:main(): @(#)This product linked OpenSSL 0.9.7c 30 Sep 2003 (http://www.openssl.org/)
   2004-01-13 13:36:39: DEBUG: pfkey.c:371:pfkey_init(): call pfkey_send_register for AH
   2004-01-13 13:36:39: DEBUG: pfkey.c:371:pfkey_init(): call pfkey_send_register for ESP
   2004-01-13 13:36:39: DEBUG: pfkey.c:371:pfkey_init(): call pfkey_send_register for IPCOMP
   2004-01-13 13:36:39: DEBUG: cftoken.l:549:yycf_set_buffer(): reading config file /usr/local/etc/racoon/racoon.conf
   2004-01-13 13:36:39: DEBUG: algorithm.c:614:alg_oakley_dhdef(): hmac(modp1024)
   2004-01-13 13:36:39: DEBUG: pfkey.c:2310:pk_checkalg(): compression algorithm can not be checked because sadb message doesn't support it.
   2004-01-13 13:36:39: DEBUG: grabmyaddr.c:204:grab_myaddrs(): my interface: 64.1.164.95 (fxp0)
   2004-01-13 13:36:39: DEBUG: grabmyaddr.c:204:grab_myaddrs(): my interface: fe80::a00:46ff:fe07:71d5%fxp0 (fxp0)
   2004-01-13 13:36:39: DEBUG: grabmyaddr.c:204:grab_myaddrs(): my interface: ::1 (lo0)
   2004-01-13 13:36:39: DEBUG: grabmyaddr.c:204:grab_myaddrs(): my interface: fe80::1%lo0 (lo0)
   2004-01-13 13:36:39: DEBUG: grabmyaddr.c:204:grab_myaddrs(): my interface: 127.0.0.1 (lo0)
   2004-01-13 13:36:39: DEBUG: grabmyaddr.c:471:autoconf_myaddrsport(): configuring default isakmp port.
   2004-01-13 13:36:39: DEBUG: grabmyaddr.c:493:autoconf_myaddrsport(): 5 addrs are configured successfully
   2004-01-13 13:36:39: INFO: isakmp.c:1358:isakmp_open(): 127.0.0.1[500] used as isakmp port (fd=5)
   2004-01-13 13:36:39: INFO: isakmp.c:1358:isakmp_open(): fe80::1%lo0[500] used as isakmp port (fd=6)
   2004-01-13 13:36:39: INFO: isakmp.c:1358:isakmp_open(): ::1[500] used as isakmp port (fd=7)
   2004-01-13 13:36:39: INFO: isakmp.c:1358:isakmp_open(): fe80::a00:46ff:fe07:71d5%fxp0[500] used as isakmp port (fd=8)
   2004-01-13 13:36:39: INFO: isakmp.c:1358:isakmp_open(): 64.1.164.95[500] used as isakmp port (fd=9)
   2004-01-13 13:36:39: DEBUG: pfkey.c:195:pfkey_handler(): get pfkey X_SPDDUMP message
   2004-01-13 13:36:39: DEBUG: pfkey.c:195:pfkey_handler(): get pfkey X_SPDDUMP message
   2004-01-13 13:36:39: DEBUG: policy.c:184:cmpspidxstrict(): sub:0xbfbff828: 64.1.164.95/32[0] 192.168.1.0/24[0] proto=any dir=out
   2004-01-13 13:36:39: DEBUG: policy.c:185:cmpspidxstrict(): db :0x80a1c08: 192.168.1.0/24[0] 64.1.164.95/32[0] proto=any dir=in
   2004-01-13 13:36:41: DEBUG: pfkey.c:195:pfkey_handler(): get pfkey ACQUIRE message
   2004-01-13 13:36:41: DEBUG: pfkey.c:1557:pk_recvacquire(): suitable outbound SP found: 64.1.164.95/32[0] 192.168.1.0/24[0] proto=any dir=out.
   2004-01-13 13:36:41: DEBUG: policy.c:184:cmpspidxstrict(): sub:0xbfbff814: 192.168.1.0/24[0] 64.1.164.95/32[0] proto=any dir=in
   2004-01-13 13:36:41: DEBUG: policy.c:185:cmpspidxstrict(): db :0x80a1c08: 192.168.1.0/24[0] 64.1.164.95/32[0] proto=any dir=in
   2004-01-13 13:36:41: DEBUG: pfkey.c:1573:pk_recvacquire(): suitable inbound SP found: 192.168.1.0/24[0] 64.1.164.95/32[0] proto=any dir=in.
   2004-01-13 13:36:41: DEBUG: pfkey.c:1612:pk_recvacquire(): new acquire 64.1.164.95/32[0] 192.168.1.0/24[0] proto=any dir=out
   2004-01-13 13:36:41: DEBUG: sainfo.c:112:getsainfo(): anonymous sainfo selected.
   2004-01-13 13:36:41: DEBUG: proposal.c:825:printsaproto():  (proto_id=ESP spisize=4 spi=00000000 spi_p=00000000 encmode=Tunnel reqid=0:0)
   2004-01-13 13:36:41: DEBUG: proposal.c:859:printsatrns():   (trns_id=3DES encklen=0 authtype=2)
   2004-01-13 13:36:41: DEBUG: remoteconf.c:129:getrmconf(): anonymous configuration selected for 64.1.164.92.
   2004-01-13 13:36:41: INFO: isakmp.c:1684:isakmp_post_acquire(): IPsec-SA request for 64.1.164.92 queued due to no phase1 found.
   2004-01-13 13:36:41: DEBUG: isakmp.c:793:isakmp_ph1begin_i(): ===
   2004-01-13 13:36:41: INFO: isakmp.c:798:isakmp_ph1begin_i(): initiate new phase 1 negotiation: 64.1.164.95[500]<=>64.1.164.92[500]
   2004-01-13 13:36:41: INFO: isakmp.c:803:isakmp_ph1begin_i(): begin Identity Protection mode.
   2004-01-13 13:36:41: DEBUG: isakmp.c:1996:isakmp_newcookie(): new cookie:
   3a7de03600b9ca1e 
   2004-01-13 13:36:41: DEBUG: isakmp.c:2113:set_isakmp_payload(): add payload of len 52, next type 0
   2004-01-13 13:36:41: DEBUG: isakmp.c:2248:isakmp_printpacket(): begin.
   36:41.616852 64.1.164.95:500 -> 64.1.164.92:500: isakmp 1.0 msgid 00000000: phase 1 I ident:
       (sa: doi=ipsec situation=identity
           (p: #1 protoid=isakmp transform=1
               (t: #1 id=ike (type=lifetype value=sec)(type=lifeduration len=4 value=00015180)(type=enc value=3des)(type=auth value=preshared)(type=hash value=sha1)(type=group desc value=modp1024))))
   2004-01-13 13:36:41: DEBUG: sockmisc.c:421:sendfromto(): sockname 64.1.164.95[500]
   2004-01-13 13:36:41: DEBUG: sockmisc.c:423:sendfromto(): send packet from 64.1.164.95[500]
   2004-01-13 13:36:41: DEBUG: sockmisc.c:425:sendfromto(): send packet to 64.1.164.92[500]
   2004-01-13 13:36:41: DEBUG: sockmisc.c:570:sendfromto(): 1 times of 84 bytes message will be sent to 64.1.164.92[500]
   2004-01-13 13:36:41: DEBUG: plog.c:193:plogdump(): 
   3a7de036 00b9ca1e 00000000 00000000 01100200 00000000 00000054 00000038
   00000001 00000001 0000002c 01010001 00000024 01010000 800b0001 000c0004
   00015180 80010005 80030001 80020002 80040002
   2004-01-13 13:36:41: DEBUG: isakmp.c:1449:isakmp_ph1resend(): resend phase1 packet 3a7de03600b9ca1e:0000000000000000
   2004-01-13 13:36:50: DEBUG: pfkey.c:195:pfkey_handler(): get pfkey ACQUIRE message
   2004-01-13 13:36:50: DEBUG: pfkey.c:1541:pk_recvacquire(): ignore the acquire becuase ph2 found
   2004-01-13 13:36:51: DEBUG: sockmisc.c:421:sendfromto(): sockname 64.1.164.95[500]
   2004-01-13 13:36:51: DEBUG: sockmisc.c:423:sendfromto(): send packet from 64.1.164.95[500]
   2004-01-13 13:36:51: DEBUG: sockmisc.c:425:sendfromto(): send packet to 64.1.164.92[500]
   2004-01-13 13:36:51: DEBUG: sockmisc.c:570:sendfromto(): 1 times of 84 bytes message will be sent to 64.1.164.92[500]
   2004-01-13 13:36:51: DEBUG: plog.c:193:plogdump(): 
   3a7de036 00b9ca1e 00000000 00000000 01100200 00000000 00000054 00000038
   00000001 00000001 0000002c 01010001 00000024 01010000 800b0001 000c0004
   00015180 80010005 80030001 80020002 80040002
   2004-01-13 13:36:51: DEBUG: isakmp.c:1449:isakmp_ph1resend(): resend phase1 packet 3a7de03600b9ca1e:0000000000000000
   ^C2004-01-13 13:36:53: INFO: session.c:299:check_sigreq(): caught signal 2
   2004-01-13 13:36:53: DEBUG: pfkey.c:195:pfkey_handler(): get pfkey FLUSH message
   2004-01-13 13:36:53: DEBUG: schedule.c:210:sched_scrub_param(): an undead schedule has been deleted.
   2004-01-13 13:36:54: DEBUG: pfkey.c:271:pfkey_dump_sadb(): call pfkey_send_dump
   2004-01-13 13:36:54: DEBUG: schedule.c:210:sched_scrub_param(): an undead schedule has been deleted.
   2004-01-13 13:36:54: INFO: session.c:180:close_session(): racoon shutdown

And when I have a ping running that should be going over the tunnel,
the Linksys logs this:

2004-01-13 13:36:51 **IKE incoming packet dropped : unknown peer ! 
2004-01-13 13:36:51 Received: IP=64.1.164.95 I_Cookie=[3a 7d e0 36 00 b9 ca 1e ] R_Cookie=[00 00 00 00 00 00 00 00 ]

All of the examples of packets w/ I_cookies I could find by googling
also had values for the R_cookie field.....

Does this ring any bells for anyone.  Can someone point me in a useful
direction?

g.