(racoon2 65) racoon2 bugs?
Franck GILLET <[email protected]> Tue, 21 Mar 2006 14:37:10 +0100
| Newsgroups | gmane.network.ipv6.kame.racoon |
|---|---|
| Message-ID | <[email protected]> |
Hello all,
I tested racoon2 in IPv6 context with certficate authentication. It
works but... when I start daemon SPMD then IKED, the tunnel doesn't work
immediately.
+-----------------+ +-----------------+
| node A | encrypted | node B |
| |eth0====<>=====eth1| |
| (2001:...:f6ef) | flow | (2001:...:7278) |
+-----------------+ +-----------------+
I can fix the bug. I hope that someone can guide me. I describe my
problem in the following lines.
I start daemons in foreground. It works...
##
$ ../sbin/spmd -F&
2006-03-21 12:18:27 [INFO]: main.c:177: Racoon Spmd - Security Policy
Management Daemon - Started
2006-03-21 12:18:27 [INFO]: main.c:178: Spmd Version: 20051102a
$../sbin/iked -6F&
2006-03-21 12:18:49 [INFO]: main.c:269:main(): starting iked for racoon2
20051102a
2006-03-21 12:18:49 [INFO]: main.c:272:main(): OPENSSLDIR:
"/etc/pki/tls"
2006-03-21 12:18:49 [INFO]: main.c:282:main(): reading
config /usr/local/racoon2/etc/racoon2.conf
2006-03-21 12:18:49 [INFO]: isakmp.c:339:isakmp_open(): socket 5 bind
2001:660:3203:1032:204:75ff:fe7f:7278[500]
2006-03-21 12:18:49 [INFO]: main.c:378:main(): starting iked for racoon2
20051102a
##
...But if I PING6 my node A from my node B, I get "connect: Resource
temporarily unavailable", even if I try again. No negociation occurs.
The output give (several times, for each PING6 test):
##
2006-03-21 09:29:55 [INFO]: ike_pfkey.c:459:sadb_expire_callback():
received PFKEY_EXPIRE seq=0
sa_dst=2001:660:3203:1032:204:75ff:fe7f:7278[0] spi=0xb79d213 satype=ESP
samode=transport expired=2
2006-03-21 09:29:55 [INTERNAL_WARN]:
ike_pfkey.c:557:sadb_expire_callback(): 0:? - ?:(nil):PF_KEY SADB_EXPIRE
message does not have corresponding request. (ignored)
##
I can give you my security policy.
##
$ setkey -DP
2001:660:3203:1032:212:3fff:fe79:f6ef[any]
2001:660:3203:1032:204:75ff:fe7f:7278[any] any
in ipsec
esp/transport//require
created: Mar 21 09:28:04 2006 lastused:
lifetime: 0(s) validtime: 0(s)
spid=8 seq=3 pid=3790
refcnt=1
2001:660:3203:1032:204:75ff:fe7f:7278[any]
2001:660:3203:1032:212:3fff:fe79:f6ef[any] any
out ipsec
esp/transport//require
created: Mar 21 09:28:04 2006 lastused: Mar 21 09:48:24 2006
lifetime: 0(s) validtime: 0(s)
spid=1 seq=2 pid=3790
refcnt=1
(per-socket policy)
in none
created: Mar 21 09:28:47 2006 lastused:
lifetime: 0(s) validtime: 0(s)
spid=19 seq=1 pid=3790
refcnt=1
(per-socket policy)
out none
created: Mar 21 09:28:47 2006 lastused: Mar 21 09:48:22 2006
lifetime: 0(s) validtime: 0(s)
spid=28 seq=0 pid=3790
refcnt=1
##
This is my security association:
##
$ setkey -D
2001:660:3203:1032:204:75ff:fe7f:7278
2001:660:3203:1032:212:3fff:fe79:f6ef
esp mode=transport spi=0(0x00000000) reqid=0(0x00000000)
seq=0x00000000 replay=0 flags=0x00000000 state=larval
created: Mar 21 09:31:11 2006 current: Mar 21 09:31:17 2006
diff: 6(s) hard: 30(s) soft: 0(s)
last: hard: 0(s) soft: 0(s)
current: 0(bytes) hard: 0(bytes) soft: 0(bytes)
allocated: 0 hard: 0 soft: 0
sadb_seq=1 pid=3584 refcnt=0
2001:660:3203:1032:212:3fff:fe79:f6ef
2001:660:3203:1032:204:75ff:fe7f:7278
esp mode=transport spi=47136074(0x02cf3d4a) reqid=0(0x00000000)
seq=0x00000000 replay=0 flags=0x00000000 state=larval
created: Mar 21 09:31:11 2006 current: Mar 21 09:31:17 2006
diff: 6(s) hard: 30(s) soft: 0(s)
last: hard: 0(s) soft: 0(s)
current: 0(bytes) hard: 0(bytes) soft: 0(bytes)
allocated: 0 hard: 0 soft: 0
sadb_seq=0 pid=3584 refcnt=0
##
I suspect SAD entry which has a spi=0x0...
After a few times, I get the output:
##
2006-03-21 09:49:26 [PROTO_ERR]: ikev2.c:582:ikev2_timeout():
2:2001:660:3203:1032:204:75ff:fe7f:7278[500] -
2001:660:3203:1032:212:3fff:fe79:f6ef[500]:(nil):retransmission count
exceeded the limit
2006-03-21 09:49:26 [INFO]: ike_sa.c:229:ikev2_abort():
2:2001:660:3203:1032:204:75ff:fe7f:7278[500] -
2001:660:3203:1032:212:3fff:fe79:f6ef[500]:(nil):aborting ike_sa
##
I think it's good.
After a long time and by chance, I get a real negociation... It begins
with:
##
2006-03-21 12:23:13 [INTERNAL_WARN]: ike_conf.c:660:ike_aton(): 0:?
- ?:(nil):ignoring extraneous values returned by
getaddrinfo(2001:660:3203:1032:212:3fff:fe79:f6ef)
2006-03-21 12:23:13 [INTERNAL_WARN]: ike_conf.c:660:ike_aton(): 0:?
- ?:(nil):ignoring extraneous values returned by
getaddrinfo(2001:660:3203:1032:212:3fff:fe79:f6ef)
2006-03-21 12:23:13 [PROTO_WARN]: crypto_openssl.c:351:cb_check_cert():
self signed certificate(18) at depth:0
SubjectName:/C=FR/ST=IDF/L=evry/O=INT/OU=LOR/CN=maknavic4/[email protected]
2006-03-21 12:23:13 [INTERNAL_WARN]: ike_conf.c:660:ike_aton(): 0:?
- ?:(nil):ignoring extraneous values returned by
getaddrinfo(2001:660:3203:1032:204:75ff:fe7f:7278)
2006-03-21 12:23:13 [INFO]: ikev2.c:4490:ikev2_process_notify():
2:2001:660:3203:1032:204:75ff:fe7f:7278[500] -
2001:660:3203:1032:212:3fff:fe79:f6ef[500]:(nil):received Notify payload
protocol 0 type INITIAL_CONTACT
##
Then I obtain a avalanche of messages (with expire messages) like:
##
2006-03-21 12:23:14 [INFO]: ike_pfkey.c:284:sadb_log_add(): SADB_UPDATE
src=2001:660:3203:1032:212:3fff:fe79:f6ef[0]
dst=2001:660:3203:1032:204:75ff:fe7f:7278[0] satype=ESP samode=transport
spi=0xb47b5ce authtype=HMAC-SHA-1 enctype=AES-CBC lifetime soft time=0
bytes=0 hard time=0 bytes=0
2006-03-21 12:23:15 [INFO]: ike_pfkey.c:284:sadb_log_add(): SADB_ADD
src=2001:660:3203:1032:204:75ff:fe7f:7278[0]
dst=2001:660:3203:1032:212:3fff:fe79:f6ef[0] satype=ESP samode=transport
spi=0x29675b4 authtype=HMAC-SHA-1 enctype=AES-CBC lifetime soft time=0
bytes=0 hard time=0 bytes=0
##
I can hope to PING6 the correspondent node. But it doesn't work!
So I read my association security database and I get many SA (at least 6
for each direction)! There are multiple SA corresponding to my link.
##
$ setkey -D
2001:660:3203:1032:204:75ff:fe7f:7278
2001:660:3203:1032:212:3fff:fe79:f6ef
esp mode=transport spi=43414964(0x029675b4) reqid=0(0x00000000)
E: aes-cbc 263b6514 b5a45f7f 43d637ac 9619a09a
A: hmac-sha1 8bc41289 e244c482 799138ac d58feebc f2bd2317
seq=0x00000000 replay=32 flags=0x00000000 state=mature
created: Mar 21 12:23:15 2006 current: Mar 21 12:24:28 2006
diff: 73(s) hard: 0(s) soft: 0(s)
last: Mar 21 12:23:32 2006 hard: 0(s) soft: 0(s)
current: 1248(bytes) hard: 0(bytes) soft: 0(bytes)
allocated: 8 hard: 0 soft: 0
sadb_seq=12 pid=5302 refcnt=0
...(5 times)
2001:660:3203:1032:204:75ff:fe7f:7278
2001:660:3203:1032:212:3fff:fe79:f6ef
esp mode=transport spi=182293886(0x0add957e) reqid=0(0x00000000)
E: aes-cbc 8918d644 7baa1443 cf61053c 161f9ad1
A: hmac-sha1 a83c4dd7 b9b229ca ffbe6a02 69daffcf d41f99e0
seq=0x00000000 replay=32 flags=0x00000000 state=mature
created: Mar 21 12:23:13 2006 current: Mar 21 12:24:28 2006
diff: 75(s) hard: 0(s) soft: 0(s)
last: hard: 0(s) soft: 0(s)
current: 0(bytes) hard: 0(bytes) soft: 0(bytes)
allocated: 0 hard: 0 soft: 0
sadb_seq=6 pid=5302 refcnt=0
2001:660:3203:1032:212:3fff:fe79:f6ef
2001:660:3203:1032:204:75ff:fe7f:7278
esp mode=transport spi=189248974(0x0b47b5ce) reqid=0(0x00000000)
E: aes-cbc 404cd950 0bbafa14 3258e099 0c012087
A: hmac-sha1 798583cd e796ca8f 9d606d3e eece5fb0 c8eef504
seq=0x00000000 replay=32 flags=0x00000000 state=mature
created: Mar 21 12:23:15 2006 current: Mar 21 12:24:28 2006
diff: 73(s) hard: 0(s) soft: 0(s)
last: Mar 21 12:23:32 2006 hard: 0(s) soft: 0(s)
current: 256(bytes) hard: 0(bytes) soft: 0(bytes)
allocated: 4 hard: 0 soft: 0
sadb_seq=5 pid=5302 refcnt=0
...(4 times)
2001:660:3203:1032:212:3fff:fe79:f6ef
2001:660:3203:1032:204:75ff:fe7f:7278
esp mode=transport spi=220871940(0x0d2a3d04) reqid=0(0x00000000)
E: aes-cbc 41686dd5 57e52a5a 03d1fa87 33d9d63e
A: hmac-sha1 cb66b464 9b0c7150 87264b28 d6eca828 e03bcb6d
seq=0x00000000 replay=32 flags=0x00000000 state=mature
created: Mar 21 12:23:13 2006 current: Mar 21 12:24:28 2006
diff: 75(s) hard: 0(s) soft: 0(s)
last: hard: 0(s) soft: 0(s)
current: 0(bytes) hard: 0(bytes) soft: 0(bytes)
allocated: 0 hard: 0 soft: 0
sadb_seq=0 pid=5302 refcnt=0
##
Naturally I flush SADB:
##
$ setkey -F
2006-03-21 12:26:22 [INTERNAL_ERR]: ike_pfkey.c:192:log_rcpfk_error():
0:? - ?:(nil):sadb_poll: unknown message type 0
##
I suppose this output is normal...
And I PING6 to start IKE negociation.
##
$ ping6 2001:660:3203:1032:212:3fff:fe79:f6ef
connect: Resource temporarily unavailable
2006-03-21 12:26:27 [INFO]: ike_pfkey.c:284:sadb_log_add(): SADB_ADD
src=2001:660:3203:1032:204:75ff:fe7f:7278[0]
dst=2001:660:3203:1032:212:3fff:fe79:f6ef[0] satype=ESP samode=transport
spi=0xf17d211 authtype=HMAC-SHA-1 enctype=AES-CBC lifetime soft time=0
bytes=0 hard time=0 bytes=0
2006-03-21 12:26:27 [INFO]: ike_pfkey.c:284:sadb_log_add(): SADB_UPDATE
src=2001:660:3203:1032:212:3fff:fe79:f6ef[0]
dst=2001:660:3203:1032:204:75ff:fe7f:7278[0] satype=ESP samode=transport
spi=0x9badaf3 authtype=HMAC-SHA-1 enctype=AES-CBC lifetime soft time=0
bytes=0 hard time=0 bytes=0
##
And the following PING6 works!!
##
$ tcpdump -ieth1&
$ ping6 2001:660:3203:1032:212:3fff:fe79:f6ef
PING
2001:660:3203:1032:212:3fff:fe79:f6ef(2001:660:3203:1032:212:3fff:fe79:f6ef) 56 data bytes
64 bytes from 2001:660:3203:1032:212:3fff:fe79:f6ef: icmp_seq=0 ttl=64
time=0.193 ms
14:28:59.133740 2001:660:3203:1032:204:75ff:fe7f:7278 >
2001:660:3203:1032:212:3fff:fe79:f6ef: ESP(spi=0x046f895f,seq=0x6)
14:28:59.133898 2001:660:3203:1032:212:3fff:fe79:f6ef >
2001:660:3203:1032:204:75ff:fe7f:7278: ESP(spi=0x0d05f819,seq=0x6)
##
I verify encryption with TCPDUMP.
If you want complete output or more information, I can send it to you.
Thanks in advance.
Best Regards.
Franck GILLET.
[email protected]