Subject: IPSEC still fails on BETA2/vax
To: None <current-users@netbsd.org, port-vax@netbsd.org>
From: Olaf Seibert <rhialto@polderland.nl>
List: current-users
Date: 06/21/2002 00:05:34
This is from the racoon -d -d log on the VAX side (xzan, 10.0.0.7):
watch the "Invalid argument" error.

2002-06-20 23:38:36: DEBUG: pfkey.c:192:pfkey_handler(): get pfkey UPDATE message
2002-06-20 23:38:36: DEBUG2: plog.c:193:plogdump():
02021603 1c000000 06000000 a3000000 02000100 0783f86b 04000303 00000000
02001300 01000000 00000000 00000000 03000500 ff200000 10020000 0a000005
00000000 00000000 03000600 ff200000 10020000 0a000007 00000000 00000000
04000900 c0000000 752c9156 8bb9e65d e42d22b3 305c703e ea9bb3b6 7117b6f0
04000800 a0000000 fdf95e51 16b9fb3c 0fc94a75 432f175c f3b87e34 00000000
04000300 00000000 00000000 00000000 c0a80000 00000000 00000000 00000000
04000400 00000000 00000000 00000000 00870000 00000000 00000000 00000000
2002-06-20 23:38:36: ERROR: pfkey.c:207:pfkey_handler(): pfkey UPDATE failed: Invalid argument
2002-06-20 23:38:36: DEBUG: pfkey.c:192:pfkey_handler(): get pfkey ADD message
2002-06-20 23:38:36: DEBUG2: plog.c:193:plogdump(): 
02030003 14000000 06000000 a3000000 02000100 03815263 04000303 00000000
02001300 01000000 00000000 00000000 03000500 ff200000 10020000 0a000007
00000000 00000000 03000600 ff200000 10020000 0a000005 00000000 00000000
04000300 00000000 00000000 00000000 c0a80000 00000000 00000000 00000000
04000400 00000000 00000000 00000000 00870000 00000000 00000000 00000000
2002-06-20 23:38:37: INFO: pfkey.c:1319:pk_recvadd(): IPsec-SA established: ESP/Transport 10.0.0.7->10.0.0.5 spi=58806883(0x3815263)
2002-06-20 23:38:37: DEBUG: pfkey.c:1324:pk_recvadd(): ===
Jun 20 23:38:37 xzan /netbsd: IPv4 ESP input: no key association found for spi 126089323
Jun 20 23:38:37 xzan /netbsd: IPv4 ESP input: no key association found for spi 126089323
Jun 20 23:39:08 xzan last message repeated 5 times

    while this is what I hope is symmetrically the same from the Alpha
    side (azenomei, 10.0.0.5):

2002-06-20 23:38:06: DEBUG: pfkey.c:192:pfkey_handler(): get pfkey UPDATE message
2002-06-20 23:38:06: DEBUG: plog.c:206:plogdump(): 
02020003 14000000 d9d5b7ab 45740000 02000100 03815263 04000303 00000000
02001300 01000000 00000000 00000000 03000500 ff200000 10020000 0a000007
00000000 00000000 03000600 ff200000 10020000 0a000005 00000000 00000000
04000300 00000000 00000000 00000000 c0a80000 00000000 00000000 00000000
04000400 00000000 00000000 00000000 00870000 00000000 00000000 00000000
2002-06-20 23:38:06: DEBUG: pfkey.c:1120:pk_recvupdate(): pfkey UPDATE succeeded: ESP/Transport 10.0.0.7->10.0.0.5 spi=58806883(0x3815263)
2002-06-20 23:38:06: INFO: pfkey.c:1127:pk_recvupdate(): IPsec-SA established: ESP/Transport 10.0.0.7->10.0.0.5 spi=58806883(0x3815263)
2002-06-20 23:38:06: DEBUG: pfkey.c:1159:pk_recvupdate(): ===
2002-06-20 23:38:06: DEBUG: pfkey.c:192:pfkey_handler(): get pfkey ADD message
2002-06-20 23:38:06: DEBUG: plog.c:206:plogdump(): 
02030003 14000000 d9d5b7ab 45740000 02000100 0783f86b 04000303 00000000
02001300 01000000 00000000 00000000 03000500 ff200000 10020000 0a000005
00000000 00000000 03000600 ff200000 10020000 0a000007 00000000 00000000
04000300 00000000 00000000 00000000 c0a80000 00000000 00000000 00000000
04000400 00000000 00000000 00000000 00870000 00000000 00000000 00000000
2002-06-20 23:38:06: INFO: pfkey.c:1313:pk_recvadd(): IPsec-SA established: ESP/Transport 10.0.0.5->10.0.0.7 spi=126089323(0x783f86b)
2002-06-20 23:38:06: DEBUG: pfkey.c:1318:pk_recvadd(): ===
2002-06-20 23:38:33: DEBUG: isakmp.c:232:isakmp_handler(): ===
2002-06-20 23:38:33: DEBUG: isakmp.c:233:isakmp_handler(): 60 bytes message received from 10.0.0.7[500]

I tested the same setup with the Alpha communicating with an i386, and
that works, so I know it is not a problem of my testing setup.

I don't know enough about IPSEC to debug this by myself, but I can see
that the very first "plogdump" data looks much different in size and
structure from the others.

I also know that this problem exists for over a year now, since I
reported it in port-vax and current-users on Sat, 21 Apr 2001 14:11:16
+0200, and again on Sun, 11 Nov 2001 21:57:15 +0100 (which at that time
found a vax-specific in_cksum bug).

Full tcpdump output looks like this:

azenomei:~$ sudo tcpdump -i ne0 -s 1500 host xzan
tcpdump: listening on ne0
23:36:24.296710 xzan.falu.nl.isakmp > azenomei.falu.nl.isakmp: isakmp: phase 1 I
 agg:
    (sa: doi=ipsec situation=identity
        (p: #1 protoid=isakmp transform=1
            (t: #1 id=ike (type=lifetype value=sec)(type=lifeduration len=4 valu
e=00015180)(type=enc value=3des)(type=auth value=preshared)(type=hash value=sha1
)(type=group desc value=modp1024))))
    (ke: key len=128)
    (nonce: n len=16)
    (id: idtype=IPv4 protoid=udp port=500 len=4 xzan.falu.nl)
23:36:25.131711 azenomei.falu.nl.isakmp > xzan.falu.nl.isakmp: isakmp: phase 1 R
 agg:
    (sa: doi=ipsec situation=identity
        (p: #1 protoid=isakmp transform=1
            (t: #1 id=ike (type=lifetype value=sec)(type=lifeduration len=4 valu
e=00015180)(type=enc value=3des)(type=auth value=preshared)(type=hash value=sha1
)(type=group desc value=modp1024))))
    (ke: key len=128)
    (nonce: n len=16)
    (id: idtype=IPv4 protoid=udp port=500 len=4 azenomei.falu.nl)
    (hash: len=20)
    (vid: len=16)
23:36:35.175092 azenomei.falu.nl.isakmp > xzan.falu.nl.isakmp: isakmp: phase 1 R
 agg:
    (sa: doi=ipsec situation=identity
        (p: #1 protoid=isakmp transform=1
            (t: #1 id=ike (type=lifetype value=sec)(type=lifeduration len=4 valu
e=00015180)(type=enc value=3des)(type=auth value=preshared)(type=hash value=sha1
)(type=group desc value=modp1024))))
    (ke: key len=128)
    (nonce: n len=16)
    (id: idtype=IPv4 protoid=udp port=500 len=4 azenomei.falu.nl)
    (hash: len=20)
    (vid: len=16)
23:36:45.187211 azenomei.falu.nl.isakmp > xzan.falu.nl.isakmp: isakmp: phase 1 R
 agg:
    (sa: doi=ipsec situation=identity
        (p: #1 protoid=isakmp transform=1
            (t: #1 id=ike (type=lifetype value=sec)(type=lifeduration len=4 valu
e=00015180)(type=enc value=3des)(type=auth value=preshared)(type=hash value=sha1
)(type=group desc value=modp1024))))
    (ke: key len=128)
    (nonce: n len=16)
    (id: idtype=IPv4 protoid=udp port=500 len=4 azenomei.falu.nl)
    (hash: len=20)
    (vid: len=16)
23:36:55.200298 azenomei.falu.nl.isakmp > xzan.falu.nl.isakmp: isakmp: phase 1 R
 agg:
    (sa: doi=ipsec situation=identity
        (p: #1 protoid=isakmp transform=1
            (t: #1 id=ike (type=lifetype value=sec)(type=lifeduration len=4 valu
e=00015180)(type=enc value=3des)(type=auth value=preshared)(type=hash value=sha1
)(type=group desc value=modp1024))))
    (ke: key len=128)
    (nonce: n len=16)
    (id: idtype=IPv4 protoid=udp port=500 len=4 azenomei.falu.nl)
    (hash: len=20)
    (vid: len=16)
23:36:58.497289 xzan.falu.nl.isakmp > azenomei.falu.nl.isakmp: isakmp: phase 1 I
 agg:
    (hash: len=20)
23:36:58.603748 azenomei.falu.nl.isakmp > xzan.falu.nl.isakmp: isakmp: phase 2/o
thers R inf[E]: [|hash]
23:37:01.461276 xzan.falu.nl.isakmp > azenomei.falu.nl.isakmp: isakmp: phase 2/o
thers I inf[E]: [|hash]
23:37:04.293427 xzan.falu.nl.isakmp > azenomei.falu.nl.isakmp: isakmp: phase 1 I
 agg:
    (hash: len=20)
23:37:06.898976 xzan.falu.nl.isakmp > azenomei.falu.nl.isakmp: isakmp: phase 1 I
 agg:
    (hash: len=20)
23:37:09.503588 xzan.falu.nl.isakmp > azenomei.falu.nl.isakmp: isakmp: phase 1 I
 agg:
    (hash: len=20)
23:37:36.490996 xzan.falu.nl.isakmp > azenomei.falu.nl.isakmp: isakmp: phase 2/o
thers I oakley-quick[E]: [|hash]
23:37:38.290884 azenomei.falu.nl.isakmp > xzan.falu.nl.isakmp: isakmp: phase 2/o
thers R oakley-quick[E]: [|hash]
23:37:48.305933 azenomei.falu.nl.isakmp > xzan.falu.nl.isakmp: isakmp: phase 2/o
thers R oakley-quick[E]: [|hash]
23:37:58.317084 azenomei.falu.nl.isakmp > xzan.falu.nl.isakmp: isakmp: phase 2/o
thers R oakley-quick[E]: [|hash]
23:38:06.460946 xzan.falu.nl.isakmp > azenomei.falu.nl.isakmp: isakmp: phase 2/o
thers I oakley-quick[E]: [|hash]
23:38:33.550894 xzan.falu.nl.isakmp > azenomei.falu.nl.isakmp: isakmp: phase 2/o
thers I oakley-quick[E]: [|hash]
23:38:35.086130 xzan.falu.nl.isakmp > azenomei.falu.nl.isakmp: isakmp: phase 2/o
thers I oakley-quick[E]: [|hash]
23:38:37.966093 xzan.falu.nl > azenomei.falu.nl: ESP(spi=58806883,seq=0x1)
23:38:37.967070 azenomei.falu.nl > xzan.falu.nl: ESP(spi=126089323,seq=0x1)
23:38:44.093326 xzan.falu.nl > azenomei.falu.nl: ESP(spi=58806883,seq=0x2) [tos 
0x10]
23:38:44.094303 azenomei.falu.nl > xzan.falu.nl: ESP(spi=126089323,seq=0x2) [tos
 0x10]
23:39:05.243587 azenomei.falu.nl > xzan.falu.nl: ESP(spi=126089323,seq=0x3)
23:39:06.247536 azenomei.falu.nl > xzan.falu.nl: ESP(spi=126089323,seq=0x4)
23:39:07.245623 azenomei.falu.nl > xzan.falu.nl: ESP(spi=126089323,seq=0x5)
23:39:08.245663 azenomei.falu.nl > xzan.falu.nl: ESP(spi=126089323,seq=0x6)
23:39:09.245703 azenomei.falu.nl > xzan.falu.nl: ESP(spi=126089323,seq=0x7)
...


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