Menu
▾
▴
ipsec-tools-devel — Development discussion of IPsec Tools
This list is closed, nobody may subscribe to it.
| 2003 |
Jan
|
Feb
|
Mar
(3) |
Apr
(6) |
May
|
Jun
(14) |
Jul
(4) |
Aug
(19) |
Sep
(27) |
Oct
(7) |
Nov
(4) |
Dec
(3) |
|---|---|---|---|---|---|---|---|---|---|---|---|---|
| 2004 |
Jan
(58) |
Feb
(20) |
Mar
(70) |
Apr
(93) |
May
(102) |
Jun
(130) |
Jul
(47) |
Aug
(61) |
Sep
(149) |
Oct
(160) |
Nov
(243) |
Dec
(94) |
| 2005 |
Jan
(199) |
Feb
(166) |
Mar
(276) |
Apr
(422) |
May
(289) |
Jun
(222) |
Jul
(306) |
Aug
(154) |
Sep
(72) |
Oct
(163) |
Nov
(113) |
Dec
(195) |
| 2006 |
Jan
(174) |
Feb
(94) |
Mar
(130) |
Apr
(45) |
May
(85) |
Jun
(115) |
Jul
(120) |
Aug
(111) |
Sep
(210) |
Oct
(56) |
Nov
(72) |
Dec
(30) |
| 2007 |
Jan
(56) |
Feb
(49) |
Mar
(35) |
Apr
(58) |
May
(83) |
Jun
(101) |
Jul
(46) |
Aug
(58) |
Sep
(47) |
Oct
(58) |
Nov
(55) |
Dec
(54) |
| 2008 |
Jan
(52) |
Feb
(21) |
Mar
(20) |
Apr
(49) |
May
(20) |
Jun
(37) |
Jul
(101) |
Aug
(49) |
Sep
(75) |
Oct
(152) |
Nov
(34) |
Dec
(63) |
| 2009 |
Jan
(90) |
Feb
(12) |
Mar
(88) |
Apr
(49) |
May
(36) |
Jun
(36) |
Jul
(52) |
Aug
(54) |
Sep
(19) |
Oct
(45) |
Nov
(18) |
Dec
(34) |
| 2010 |
Jan
(12) |
Feb
(28) |
Mar
(18) |
Apr
(19) |
May
(14) |
Jun
(15) |
Jul
(24) |
Aug
(45) |
Sep
(6) |
Oct
(4) |
Nov
(21) |
Dec
(23) |
| 2011 |
Jan
(24) |
Feb
(45) |
Mar
(56) |
Apr
(18) |
May
(4) |
Jun
(10) |
Jul
(15) |
Aug
(38) |
Sep
(11) |
Oct
(48) |
Nov
(55) |
Dec
(29) |
| 2012 |
Jan
(41) |
Feb
(15) |
Mar
(24) |
Apr
(17) |
May
(12) |
Jun
(17) |
Jul
(18) |
Aug
(17) |
Sep
(17) |
Oct
(4) |
Nov
(8) |
Dec
(13) |
| 2013 |
Jan
(9) |
Feb
(1) |
Mar
(10) |
Apr
(18) |
May
(18) |
Jun
(14) |
Jul
(34) |
Aug
(6) |
Sep
(7) |
Oct
|
Nov
(8) |
Dec
(4) |
| 2014 |
Jan
(12) |
Feb
(6) |
Mar
(1) |
Apr
(12) |
May
|
Jun
(2) |
Jul
(20) |
Aug
(1) |
Sep
|
Oct
(3) |
Nov
(2) |
Dec
|
| 2015 |
Jan
(16) |
Feb
(2) |
Mar
(9) |
Apr
|
May
(56) |
Jun
(6) |
Jul
(7) |
Aug
(1) |
Sep
(17) |
Oct
(13) |
Nov
(23) |
Dec
(3) |
| 2016 |
Jan
(10) |
Feb
(8) |
Mar
(34) |
Apr
(19) |
May
(26) |
Jun
(3) |
Jul
|
Aug
(1) |
Sep
(2) |
Oct
(6) |
Nov
(5) |
Dec
(2) |
| 2017 |
Jan
|
Feb
|
Mar
|
Apr
|
May
(1) |
Jun
|
Jul
(1) |
Aug
(1) |
Sep
(1) |
Oct
(2) |
Nov
|
Dec
|
| 2018 |
Jan
|
Feb
|
Mar
|
Apr
|
May
(3) |
Jun
(1) |
Jul
|
Aug
|
Sep
|
Oct
(1) |
Nov
|
Dec
(1) |
| 2019 |
Jan
|
Feb
(1) |
Mar
(2) |
Apr
|
May
|
Jun
|
Jul
|
Aug
|
Sep
|
Oct
|
Nov
(2) |
Dec
|
| S | M | T | W | T | F | S |
|---|---|---|---|---|---|---|
|
|
|
|
1
|
2
|
3
|
4
|
|
5
|
6
(4) |
7
|
8
|
9
|
10
|
11
|
|
12
(1) |
13
|
14
|
15
(3) |
16
|
17
|
18
|
|
19
(1) |
20
|
21
|
22
|
23
|
24
|
25
|
|
26
|
27
|
28
|
29
|
30
(1) |
|
|
|
From: Akos K. <ako...@gm...> - 2011-06-30 09:58:51
|
Hi all,
I am trying to create an IPSec tunnel between two Linux boxes using IPv6 and
racoon 0.6.5. I get a "failed to get sainfo" error though my sainfo entries
are exactly the same (with addresses interchanged) on the two ends. The same
configuration worked with IPv4 addresses. My remote and sainfo entries in
racoon.conf:
remote fdbd::5:103 inherit anonymous {
exchange_mode main;
verify_cert off;
my_identifier asn1dn;
certificate_type x509 "9d567e1b.0" "key_NE01.pem";
ca_type x509 "9786cb84.0";
peers_identifier asn1dn;
lifetime time 1440 secs;
proposal {
encryption_algorithm 3des;
hash_algorithm sha1;
authentication_method rsasig;
dh_group 2;
}
}
sainfo address fdbd::2:101 any address fdbd::5:0/120 any
{
encryption_algorithm 3des;
authentication_algorithm hmac_sha1;
compression_algorithm deflate;
}
My setkey.conf:
#!/usr/sbin/setkey -f
spdflush;
spdadd fdbd::2:101 fdbd::5:0/120 any -P out ipsec
esp/tunnel/fdbd::2:2-fdbd::5:103/require;
spdadd fdbd::5:0/120 fdbd::2:101 any -P in ipsec
esp/tunnel/fdbd::5:103-fdbd::2:2/require;
The other side is the same with addresses interchanged, the sainfo there is
sainfo address fdbd::5:0/120 any address fdbd::2:101 any
{
encryption_algorithm 3des;
authentication_algorithm hmac_sha1;
compression_algorithm deflate;
}
When pinging the other side:
ping6 -I fdbd::2:101 fdbd::5:3
I get:
Foreground mode.
2011-06-30 11:34:08: INFO: @(#)ipsec-tools 0.6.5 (
http://ipsec-tools.sourceforge.net)
2011-06-30 11:34:08: INFO: @(#)This product linked OpenSSL 0.9.8a 11 Oct
2005 (http://www.openssl.org/)
2011-06-30 11:34:08: DEBUG2: lifetime = 28800
2011-06-30 11:34:08: DEBUG2: lifebyte = 0
2011-06-30 11:34:08: DEBUG2: encklen=0
2011-06-30 11:34:08: DEBUG2: p:1 t:1
2011-06-30 11:34:08: DEBUG2: 3DES-CBC(5)
2011-06-30 11:34:08: DEBUG2: SHA(2)
2011-06-30 11:34:08: DEBUG2: 1024-bit MODP group(2)
2011-06-30 11:34:08: DEBUG2: RSA signatures(3)
2011-06-30 11:34:08: DEBUG2:
2011-06-30 11:34:08: DEBUG: configuration found for anonymous.
2011-06-30 11:34:08: DEBUG: configuration found for anonymous.
2011-06-30 11:34:08: DEBUG2: lifetime = 1440
2011-06-30 11:34:08: DEBUG2: lifebyte = 0
2011-06-30 11:34:08: DEBUG2: encklen=0
2011-06-30 11:34:08: DEBUG2: p:1 t:1
2011-06-30 11:34:08: DEBUG2: 3DES-CBC(5)
2011-06-30 11:34:08: DEBUG2: SHA(2)
2011-06-30 11:34:08: DEBUG2: 1536-bit MODP group(5)
2011-06-30 11:34:08: DEBUG2: RSA signatures(3)
2011-06-30 11:34:08: DEBUG2:
2011-06-30 11:34:08: DEBUG2: lifetime = 1440
2011-06-30 11:34:08: DEBUG2: lifebyte = 0
2011-06-30 11:34:08: DEBUG2: encklen=0
2011-06-30 11:34:08: DEBUG2: p:1 t:2
2011-06-30 11:34:08: DEBUG2: 3DES-CBC(5)
2011-06-30 11:34:08: DEBUG2: MD5(1)
2011-06-30 11:34:08: DEBUG2: 1536-bit MODP group(5)
2011-06-30 11:34:08: DEBUG2: RSA signatures(3)
2011-06-30 11:34:08: DEBUG2:
2011-06-30 11:34:08: DEBUG2: lifetime = 1440
2011-06-30 11:34:08: DEBUG2: lifebyte = 0
2011-06-30 11:34:08: DEBUG2: encklen=0
2011-06-30 11:34:08: DEBUG2: p:1 t:3
2011-06-30 11:34:08: DEBUG2: 3DES-CBC(5)
2011-06-30 11:34:08: DEBUG2: SHA(2)
2011-06-30 11:34:08: DEBUG2: 1024-bit MODP group(2)
2011-06-30 11:34:08: DEBUG2: RSA signatures(3)
2011-06-30 11:34:08: DEBUG2:
2011-06-30 11:34:08: DEBUG2: lifetime = 1440
2011-06-30 11:34:08: DEBUG2: lifebyte = 0
2011-06-30 11:34:08: DEBUG2: encklen=0
2011-06-30 11:34:08: DEBUG2: p:1 t:4
2011-06-30 11:34:08: DEBUG2: 3DES-CBC(5)
2011-06-30 11:34:08: DEBUG2: MD5(1)
2011-06-30 11:34:08: DEBUG2: 1024-bit MODP group(2)
2011-06-30 11:34:08: DEBUG2: RSA signatures(3)
2011-06-30 11:34:08: DEBUG2:
2011-06-30 11:34:08: DEBUG2: lifetime = 1440
2011-06-30 11:34:08: DEBUG2: lifebyte = 0
2011-06-30 11:34:08: DEBUG2: encklen=0
2011-06-30 11:34:08: DEBUG2: p:1 t:5
2011-06-30 11:34:08: DEBUG2: 3DES-CBC(5)
2011-06-30 11:34:08: DEBUG2: SHA(2)
2011-06-30 11:34:08: DEBUG2: 768-bit MODP group(1)
2011-06-30 11:34:08: DEBUG2: RSA signatures(3)
2011-06-30 11:34:08: DEBUG2:
2011-06-30 11:34:08: DEBUG2: lifetime = 1440
2011-06-30 11:34:08: DEBUG2: lifebyte = 0
2011-06-30 11:34:08: DEBUG2: encklen=0
2011-06-30 11:34:08: DEBUG2: p:1 t:6
2011-06-30 11:34:08: DEBUG2: 3DES-CBC(5)
2011-06-30 11:34:08: DEBUG2: MD5(1)
2011-06-30 11:34:08: DEBUG2: 768-bit MODP group(1)
2011-06-30 11:34:08: DEBUG2: RSA signatures(3)
2011-06-30 11:34:08: DEBUG2:
2011-06-30 11:34:08: DEBUG: compression algorithm can not be checked because
sadb message doesn't support it.
2011-06-30 11:34:08: DEBUG2: parse successed.
2011-06-30 11:34:08: DEBUG: open /var/run/racoon/racoon.sock as racoon
management.
2011-06-30 11:34:08: INFO: fdbd::2:2[500] used as isakmp port (fd=6)
2011-06-30 11:34:08: DEBUG: get pfkey X_SPDDUMP message
2011-06-30 11:34:08: DEBUG2:
02120000 23000100 02000000 d1420000 05000500 ff780000 0a000000 00000000
fdbd0000 00000000 00000000 00050000 00000000 00000000 05000600 ff800000
0a000000 00000000 fdbd0000 00000000 00000000 00020101 00000000 00000000
04000300 00000000 00000000 00000000 00000000 00000000 00000000 00000000
04000400 00000000 00000000 00000000 00000000 00000000 00000000 00000000
04000200 00000000 00000000 00000000 fc420c4e 00000000 00000000 00000000
0b001200 02000100 b81b0000 00000080 48003200 02020000 00000000 00000000
0a000000 00000000 fdbd0000 00000000 00000000 00050103 00000000 0a000000
00000000 fdbd0000 00000000 00000000 00020002 00000000
2011-06-30 11:34:08: DEBUG: get pfkey X_SPDDUMP message
2011-06-30 11:34:08: DEBUG2:
02120000 23000100 01000000 d1420000 05000500 ff800000 0a000000 00000000
fdbd0000 00000000 00000000 00020101 00000000 00000000 05000600 ff780000
0a000000 00000000 fdbd0000 00000000 00000000 00050000 00000000 00000000
04000300 00000000 00000000 00000000 00000000 00000000 00000000 00000000
04000400 00000000 00000000 00000000 00000000 00000000 00000000 00000000
04000200 00000000 00000000 00000000 fc420c4e 00000000 00000000 00000000
0b001200 02000200 b11b0000 00000080 48003200 02020000 00000000 00000000
0a000000 00000000 fdbd0000 00000000 00000000 00020002 00000000 0a000000
00000000 fdbd0000 00000000 00000000 00050103 00000000
2011-06-30 11:34:08: DEBUG: sub:0x7fffadf65820: fdbd::2:101/128[0]
fdbd::5:0/120[0] proto=any dir=out
2011-06-30 11:34:08: DEBUG: db :0x58b930: fdbd::5:0/120[0]
fdbd::2:101/128[0] proto=any dir=in
2011-06-30 11:34:08: DEBUG: get pfkey X_SPDDUMP message
2011-06-30 11:34:08: DEBUG2:
02120000 23000100 00000000 d1420000 05000500 ff780000 0a000000 00000000
fdbd0000 00000000 00000000 00050000 00000000 00000000 05000600 ff800000
0a000000 00000000 fdbd0000 00000000 00000000 00020101 00000000 00000000
04000300 00000000 00000000 00000000 00000000 00000000 00000000 00000000
04000400 00000000 00000000 00000000 00000000 00000000 00000000 00000000
04000200 00000000 00000000 00000000 fc420c4e 00000000 00000000 00000000
0b001200 02000300 c21b0000 00000080 48003200 02020000 00000000 00000000
0a000000 00000000 fdbd0000 00000000 00000000 00050103 00000000 0a000000
00000000 fdbd0000 00000000 00000000 00020002 00000000
2011-06-30 11:34:08: DEBUG: sub:0x7fffadf65820: fdbd::5:0/120[0]
fdbd::2:101/128[0] proto=any dir=fwd
2011-06-30 11:34:08: DEBUG: db :0x58b930: fdbd::5:0/120[0]
fdbd::2:101/128[0] proto=any dir=in
2011-06-30 11:34:08: DEBUG: sub:0x7fffadf65820: fdbd::5:0/120[0]
fdbd::2:101/128[0] proto=any dir=fwd
2011-06-30 11:34:08: DEBUG: db :0x58bba0: fdbd::2:101/128[0]
fdbd::5:0/120[0] proto=any dir=out
2011-06-30 11:34:16: DEBUG: get pfkey ACQUIRE message
2011-06-30 11:34:16: DEBUG2:
02060003 0f000000 52030000 00000000 05000500 00800000 0a000000 00000000
fdbd0000 00000000 00000000 00020002 00000000 08000200 05000600 00800000
0a000000 00000000 fdbd0000 00000000 00000000 00050103 00000000 00050003
02001200 02000200 b11b0000 00000000 01000d00 20000000
2011-06-30 11:34:16: DEBUG: suitable outbound SP found: fdbd::2:101/128[0]
fdbd::5:0/120[0] proto=any dir=out.
2011-06-30 11:34:16: DEBUG: sub:0x7fffadf657f0: fdbd::5:0/120[0]
fdbd::2:101/128[0] proto=any dir=in
2011-06-30 11:34:16: DEBUG: db :0x58b930: fdbd::5:0/120[0]
fdbd::2:101/128[0] proto=any dir=in
2011-06-30 11:34:16: DEBUG: suitable inbound SP found: fdbd::5:0/120[0]
fdbd::2:101/128[0] proto=any dir=in.
2011-06-30 11:34:16: DEBUG: new acquire fdbd::2:101/128[0] fdbd::5:0/120[0]
proto=any dir=out
2011-06-30 11:34:16: ERROR: failed to get sainfo.
It works when I replace the addresses of the racoon.conf sainfo with
anonymous. What am I doing wrong? Or shall I upgrade to a newer racoon?
Thank you.
BR
Akos Korosmezey
|
|
From: Rainer W. <rwe...@mo...> - 2011-06-19 18:48:31
|
VANHULLEBUS Yvan <va...@fr...> writes: > On Sun, Jun 12, 2011 at 08:26:12PM +0100, Rainer Weikusat wrote: > [....] >> Regarding the actual issue: The isakmp_main function in >> src/racoon/isakmp.c contains a block of code (starting at line 467 in >> 0.8.0) which changes the source and destination addresses associated >> with an existing ph1handle structure provided a message was received >> whose source addresses differed from the adresses recorded in the >> ph1handle structure, both endpoints are capable of NAT-T and no such >> address change has already happened. This is wrong/ not really >> sensible in a number of ways, specifically >> >> - it will change the addresses of an existing ph1 SA which >> isn't using NAT-T >> >> - it will do so upon receipt of any kind of message despite >> NAT-T 'port floating' is only supposed to happen during ph1 >> negotiation, in the initiator message containing the ID >> payload. > > Port floating is only supposed to happen during phase1, but peer's IP > address change may happen at anytime, because NAT device between peer > and us may have a new IP address, etc... The racoon code has never supported this: It sets a flag after an address change has happened (NAT_PORTS_CHANGED) and this prevents further address changes. Supporting this also isn't that easy because phase 2 SAs also contain these addresses and racoon tries to locate ph2 SAs associated with a ph1 SA by searching for matching addresses in various places, eg, 'delete payload processing'. That was actually what caused the VPN outage I mentioned: After the remote VPN gateway had switched back to its proper address, it sent ph1 and ph2 delete requests but racoon didn't delete the ph2s because the ph1 address change meant it couldn't find them anymore. This then lead to the situation where the kernel on our end believed to be in possession of a valid ph2 SA which could be used for communication with the other VPN endpoint while said endpoint considered the same ph2 SA to be dead. It was necessary to remove the 'undead' ph2 SA manually in order to get things going again (after some hours and an urgent customer support call). |
|
From: VANHULLEBUS Y. <va...@fr...> - 2011-06-15 09:42:58
|
On Wed, Jun 15, 2011 at 10:43:05AM +0200, Roman Hoog Antink wrote: > Dear Maintainers Hi. Sorry for the very late reply, I kept your other mails but never found time to had a look at your patch. > The device that raised the DPD-failure issue (see previous postings of > this thread [1]) was a Cisco 836 running IOS 12.3(8)T which is > End-of-life, according to this link [2]. > > Are you willing to include my patch? Or are you not interested in this > compatibility issue, while racoon violates RFC 3706? > > [1] > http://sourceforge.net/mailarchive/forum.php?thread_name=4D9BFA4F.4010804%40open.ch&forum_name=ipsec-tools-devel > [2] http://www.cisco.com/en/US/products/ps5858/index.html I'll have a look at them ASAP, feel free to ask me again if you don't see any commit/mail in a few weeks. Yvan. |
|
From: VANHULLEBUS Y. <va...@fr...> - 2011-06-15 09:42:58
|
Hi. On Sun, Jun 12, 2011 at 08:26:12PM +0100, Rainer Weikusat wrote: [....] > Regarding the actual issue: The isakmp_main function in > src/racoon/isakmp.c contains a block of code (starting at line 467 in > 0.8.0) which changes the source and destination addresses associated > with an existing ph1handle structure provided a message was received > whose source addresses differed from the adresses recorded in the > ph1handle structure, both endpoints are capable of NAT-T and no such > address change has already happened. This is wrong/ not really > sensible in a number of ways, specifically > > - it will change the addresses of an existing ph1 SA which > isn't using NAT-T > > - it will do so upon receipt of any kind of message despite > NAT-T 'port floating' is only supposed to happen during ph1 > negotiation, in the initiator message containing the ID > payload. Port floating is only supposed to happen during phase1, but peer's IP address change may happen at anytime, because NAT device between peer and us may have a new IP address, etc... However, you're absolutely right at least on one point: such IP change shoud NOT be done before checking packets does *really* come from peer ! > - as opposed to procedure given in RFC3947, the change is not > done after the message itself was found to be valid but > before any payload processing, after a couple of generic > consistency checks have been done. Unless I'm very much > mistaken, this means that anyone who 'knows' the initiator > and responder cookies can fake a message which will cause > racoon to change the ph1 addresses to an abitrary value. At > least, this seems to be a DoS against a VPN using DPD. > > Below is a patch which addresses this by tightening the address check > in isakmp_main to reject messages with unexpected addresses except if > the etype is an phase1 negotiation etype, NAT was detected and no port > floating has occured for this phase1 SA yet and by moving the address > changing code into ph1_main, in between the 'process received packet' > and 'send reply message' calls so that only valid messages can trigger > address changes. This is an adapted version of a patch against 0.7.3 > and the 0.7.3 variant used in 'our product' is actually running in > production with this change (since last Friday). [patch] I'll review your patch ASAP. Guess it will need some changes if we want to keep the possibility to update peer's IP at anytime, but only after checking packet does really comes from peer. Yvan. |
|
From: Roman H. A. <rh...@op...> - 2011-06-15 08:43:15
|
Dear Maintainers The device that raised the DPD-failure issue (see previous postings of this thread [1]) was a Cisco 836 running IOS 12.3(8)T which is End-of-life, according to this link [2]. Are you willing to include my patch? Or are you not interested in this compatibility issue, while racoon violates RFC 3706? [1] http://sourceforge.net/mailarchive/forum.php?thread_name=4D9BFA4F.4010804%40open.ch&forum_name=ipsec-tools-devel [2] http://www.cisco.com/en/US/products/ps5858/index.html Cheers, -Roman |
|
From: Rainer W. <rwe...@mo...> - 2011-06-12 19:38:48
|
An introductory remark: The reason why I noticed this was because one
of the customers of the company I presently work for operates a VPN
gateway which has two uplinks to the internet using two different ISPs,
with one of this uplinks being subject to NAT. For some reason, this
VPN gateway chose to use its NATted uplink for sending a DPD R-U-THERE
to 'our' (racoon-using) VPN endpoint and this caused the VPN to stop
working until the SA db in the kernel (Linux) was flushed manually
about three hours later.
Regarding the actual issue: The isakmp_main function in
src/racoon/isakmp.c contains a block of code (starting at line 467 in
0.8.0) which changes the source and destination addresses associated
with an existing ph1handle structure provided a message was received
whose source addresses differed from the adresses recorded in the
ph1handle structure, both endpoints are capable of NAT-T and no such
address change has already happened. This is wrong/ not really
sensible in a number of ways, specifically
- it will change the addresses of an existing ph1 SA which
isn't using NAT-T
- it will do so upon receipt of any kind of message despite
NAT-T 'port floating' is only supposed to happen during ph1
negotiation, in the initiator message containing the ID
payload.
- as opposed to procedure given in RFC3947, the change is not
done after the message itself was found to be valid but
before any payload processing, after a couple of generic
consistency checks have been done. Unless I'm very much
mistaken, this means that anyone who 'knows' the initiator
and responder cookies can fake a message which will cause
racoon to change the ph1 addresses to an abitrary value. At
least, this seems to be a DoS against a VPN using DPD.
Below is a patch which addresses this by tightening the address check
in isakmp_main to reject messages with unexpected addresses except if
the etype is an phase1 negotiation etype, NAT was detected and no port
floating has occured for this phase1 SA yet and by moving the address
changing code into ph1_main, in between the 'process received packet'
and 'send reply message' calls so that only valid messages can trigger
address changes. This is an adapted version of a patch against 0.7.3
and the 0.7.3 variant used in 'our product' is actually running in
production with this change (since last Friday).
----
diff -rNu ipsec-tools-0.8.0/src/racoon/isakmp.c ipsec-tools-0.8.0.patched//src/racoon/isakmp.c
--- ipsec-tools-0.8.0/src/racoon/isakmp.c 2011-03-15 13:20:14.000000000 +0000
+++ ipsec-tools-0.8.0.patched//src/racoon/isakmp.c 2011-06-12 19:45:02.000000000 +0100
@@ -177,8 +177,10 @@
static u_char r_ck0[] = { 0,0,0,0,0,0,0,0 }; /* used to verify the r_ck. */
+struct isakmp_addrs;
+
static int isakmp_main __P((vchar_t *, struct sockaddr *, struct sockaddr *));
-static int ph1_main __P((struct ph1handle *, vchar_t *));
+static int ph1_main __P((struct ph1handle *, vchar_t *, struct isakmp_addrs *));
static int quick_main __P((struct ph2handle *, vchar_t *));
static int isakmp_ph1begin_r __P((vchar_t *,
struct sockaddr *, struct sockaddr *, u_int8_t));
@@ -388,6 +390,70 @@
}
/*
+ * isakmp main address checking helpers
+ */
+struct isakmp_addrs {
+ struct sockaddr *local, *remote;
+};
+
+#define LOCAL_ADDR_MISMATCH 1
+#define REMOTE_ADDR_MISMATCH 2
+
+static inline u_int32_t
+port_floating_etype(etype)
+ u_int32_t etype;
+{
+#ifdef ENABLE_NATT
+#define FLOAT_MAP (1 << ISAKMP_ETYPE_IDENT | 1 << ISAKMP_ETYPE_AGG \
+ | 1 << ISAKMP_ETYPE_BASE)
+
+ return FLOAT_MAP & (1 << etype);
+
+#undef FLOAT_MAP
+#else
+ return 0;
+#endif
+}
+
+static inline int
+expect_natt_addr_change(iph1)
+ struct ph1handle *iph1;
+{
+#ifdef ENABLE_NATT
+
+ if (iph1->natt_flags & NAT_PORTS_CHANGED) return 0;
+ return iph1->natt_flags & NAT_DETECTED;
+
+#else
+ return 0;
+#endif
+}
+
+static void
+print_addr_mismatch_warning(which, sa0, sa1)
+ int which;
+ struct sockaddr *sa0;
+ struct sockaddr *sa1;
+{
+ char *sa0_s, *which_s;
+
+ which_s = which == REMOTE_ADDR_MISMATCH ?
+ "remote" : "local";
+
+ sa0_s = racoon_strdup(saddr2str(sa0));
+ if (!sa0_s) {
+ plog(LLV_WARNING, LOCATION, NULL,
+ "%s address mismatch\n", which_s);
+ return;
+ }
+
+ plog(LLV_WARNING, LOCATION, NULL,
+ "%s address mismatch (%s <-> %s)\n",
+ which_s, sa0_s, saddr2str(sa1));
+ racoon_free(sa0_s);
+}
+
+/*
* main processing to handle isakmp payload
*/
static int
@@ -399,6 +465,7 @@
isakmp_index *index = (isakmp_index *)isakmp;
u_int32_t msgid = isakmp->msgid;
struct ph1handle *iph1;
+ int addr_mismatch;
#ifdef HAVE_PRINT_ISAKMP_C
isakmp_printpacket(msg, remote, local, 0);
@@ -453,6 +520,7 @@
}
}
+ addr_mismatch = 0;
iph1 = getph1byindex(index);
if (iph1 != NULL) {
/* validity check */
@@ -464,74 +532,28 @@
return -1;
}
-#ifdef ENABLE_NATT
- /* Floating ports for NAT-T */
- if (NATT_AVAILABLE(iph1) &&
- ! (iph1->natt_flags & NAT_PORTS_CHANGED) &&
- ((cmpsaddr(iph1->remote, remote) != CMPSADDR_MATCH) ||
- (cmpsaddr(iph1->local, local) != CMPSADDR_MATCH)))
- {
- /* prevent memory leak */
- racoon_free(iph1->remote);
- racoon_free(iph1->local);
- iph1->remote = NULL;
- iph1->local = NULL;
-
- /* copy-in new addresses */
- iph1->remote = dupsaddr(remote);
- if (iph1->remote == NULL) {
- plog(LLV_ERROR, LOCATION, iph1->remote,
- "phase1 failed: dupsaddr failed.\n");
- remph1(iph1);
- delph1(iph1);
- return -1;
- }
- iph1->local = dupsaddr(local);
- if (iph1->local == NULL) {
- plog(LLV_ERROR, LOCATION, iph1->remote,
- "phase1 failed: dupsaddr failed.\n");
- remph1(iph1);
- delph1(iph1);
- return -1;
- }
-
- /* set the flag to prevent further port floating
- (FIXME: should we allow it? E.g. when the NAT gw
- is rebooted?) */
- iph1->natt_flags |= NAT_PORTS_CHANGED | NAT_ADD_NON_ESP_MARKER;
-
- /* print some neat info */
- plog (LLV_INFO, LOCATION, NULL,
- "NAT-T: ports changed to: %s\n",
- saddr2str_fromto ("%s<->%s", iph1->remote, iph1->local));
-
- natt_keepalive_add_ph1 (iph1);
- }
-#endif
-
- /* must be same addresses in one stream of a phase at least. */
- if (cmpsaddr(iph1->remote, remote) != CMPSADDR_MATCH) {
- char *saddr_db, *saddr_act;
-
- saddr_db = racoon_strdup(saddr2str(iph1->remote));
- saddr_act = racoon_strdup(saddr2str(remote));
- STRDUP_FATAL(saddr_db);
- STRDUP_FATAL(saddr_act);
-
- plog(LLV_WARNING, LOCATION, remote,
- "remote address mismatched. db=%s, act=%s\n",
- saddr_db, saddr_act);
-
- racoon_free(saddr_db);
- racoon_free(saddr_act);
- }
-
- /*
- * don't check of exchange type here because other type will be
- * with same index, for example, informational exchange.
- */
-
- /* XXX more acceptable check */
+ if (cmpsaddr(iph1->remote, remote) != CMPSADDR_MATCH)
+ addr_mismatch = REMOTE_ADDR_MISMATCH;
+ else if (cmpsaddr(iph1->local, local) != CMPSADDR_MATCH)
+ addr_mismatch = LOCAL_ADDR_MISMATCH;
+
+ if (addr_mismatch
+ &&
+ !((port_floating_etype(iph1->etype)
+ && expect_natt_addr_change(iph1)))) {
+ struct sockaddr *sa0, *sa1;
+
+ if (addr_mismatch == REMOTE_ADDR_MISMATCH) {
+ sa0 = iph1->remote;
+ sa1 = remote;
+ } else {
+ sa0 = iph1->local;
+ sa1 = local;
+ }
+
+ print_addr_mismatch_warning(addr_mismatch, sa0, sa1);
+ return -1;
+ }
}
switch (isakmp->etype) {
@@ -602,15 +624,27 @@
if (isakmp->np == ISAKMP_NPTYPE_FRAG)
return frag_handler(iph1, msg, remote, local);
#endif
-
- /* call main process of phase 1 */
- if (ph1_main(iph1, msg) < 0) {
- plog(LLV_ERROR, LOCATION, iph1->remote,
- "phase1 negotiation failed.\n");
- remph1(iph1);
- delph1(iph1);
- return -1;
+ {
+ struct isakmp_addrs addrs, *paddrs;
+
+ if (addr_mismatch) {
+ addrs.remote = remote;
+ addrs.local = local;
+
+ paddrs = &addrs;
+ } else
+ paddrs = NULL;
+
+ /* call main process of phase 1 */
+ if (ph1_main(iph1, msg, paddrs) < 0) {
+ plog(LLV_ERROR, LOCATION, iph1->remote,
+ "phase1 negotiation failed.\n");
+ remph1(iph1);
+ delph1(iph1);
+ return -1;
+ }
}
+
break;
case ISAKMP_ETYPE_AUTH:
@@ -770,9 +804,10 @@
* main function of phase 1.
*/
static int
-ph1_main(iph1, msg)
+ph1_main(iph1, msg, paddrs)
struct ph1handle *iph1;
vchar_t *msg;
+ struct isakmp_addrs *paddrs;
{
int error;
#ifdef ENABLE_STATS
@@ -833,6 +868,27 @@
/* turn off schedule */
sched_cancel(&iph1->scr);
+#ifdef ENABLE_NATT
+ /*
+ * Set if addresses changed and NAT-T port floating
+ * was expected to happen, see isakmp_main above.
+ *
+ */
+ if (paddrs) {
+ memcpy(iph1->remote, paddrs->remote, sizeof(*paddrs->remote));
+ memcpy(iph1->local, paddrs->local, sizeof(*paddrs->local));
+
+ iph1->natt_flags |= NAT_PORTS_CHANGED | NAT_ADD_NON_ESP_MARKER;
+
+ /* print some neat info */
+ plog (LLV_INFO, LOCATION, NULL,
+ "NAT-T: ports changed to: %s\n",
+ saddr2str_fromto ("%s<->%s", iph1->remote, iph1->local));
+
+ natt_keepalive_add_ph1 (iph1);
+ }
+#endif
+
/* send */
plog(LLV_DEBUG, LOCATION, NULL, "===\n");
if ((ph1exchange[etypesw1(iph1->etype)]
|
|
From: Jaco K. <ja...@ul...> - 2011-06-06 22:33:09
|
Hi,
All sorted. ipsec-tools 0.8.0 sorts out the issues I had, together with
the patch below and another to ignore illegal FQDN IDs as sent by
Windows XP when doing ISAKMP over NAT-T and all is finally working!
Kind Regards,
Jaco
On 06/06/11 22:12, Jaco Kroon wrote:
> Hi All,
>
> I've spotted some behavior which seems to be wrong, so I'm going to try
> and explain what I am seeing, hopefully someone can point out what's
> going wrong and where (and hopefully provide me with either a workaround
> or a fix).
>
> Firstly, I'm using two different clients, one Windows XP box (L2TP/IPSec
> client) and one Gentoo Linux client (racoon on the client). My server
> is also Gentoo Linux, both Linux's has ipsec-tools , and the server has
> the following patch additionally installed (looking for road-warrior
> like functionality, so the patch is basically to enable the server to
> re-use the same pre-shared key for the whole internet - yea, I know I
> should be setting up an PKI but the client is looking for a global
> pre-shared key, we've advised the risks, but a client is always right,
> even when they're wrong).
>
> --- ipsec-tools-0.7.3.o/src/racoon/oakley.c 2009-08-13
> 11:18:45.000000000 +0200
> +++ ipsec-tools-0.7.3/src/racoon/oakley.c 2011-06-06
> 09:36:11.000000000 +0200
> @@ -2498,8 +2498,21 @@
> plog(LLV_ERROR, LOCATION, iph1->remote,
> "couldn't find the pskey for %s.\n",
> saddrwop2str(iph1->remote));
> + }
> + }
> + if (iph1->authstr == NULL) {
> + /*
> + * If we could not locate a psk above try and locate
> + * the default psk, ie, "*".
> + */
> + iph1->authstr = privsep_getpsk("*", 1);
> + if (iph1->authstr == NULL) {
> + plog(LLV_ERROR, LOCATION, iph1->remote,
> + "couldn't find the the default
> pskey either.\n");
> goto end;
> }
> + plog(LLV_NOTIFY, LOCATION, iph1->remote,
> + "Using default PSK.\n");
> }
> plog(LLV_DEBUG, LOCATION, NULL, "the psk found.\n");
> /* should be secret PSK */
>
> This just allows me to put a "* psk" line in psk.txt. This part works.
>
> Pertinent config options on the server (please ask if I miss something):
>
> path pre_shared_key "/etc/racoon/psk.txt";
>
> remote anonymous {
> exchange_mode main;
> doi ipsec_doi;
> situation identity_only;
>
> nat_traversal on;
> initial_contact off;
> passive on;
> proposal_check obey;
>
> ... here goes the proposal (this passes) ...
> }
>
> In my first test case Ive got:
>
> client -> NAT GW -> inet <- Server
>
> On the NAT GW running tcpdump shows this:
>
> 18:29:02.939323 IP 172.24.5.10.500 > 46.134.75.12.500: [|isakmp]
> 18:29:02.939363 IP 46.241.240.125.500 > 46.134.75.12.500: [|isakmp]
> 18:29:03.385950 IP 46.134.75.12.500 > 46.241.240.125.500: [|isakmp]
> 18:29:03.385966 IP 46.134.75.12.500 > 172.24.5.10.500: [|isakmp]
> 18:29:04.609208 IP 172.24.5.10.500 > 46.134.75.12.500: [|isakmp]
> 18:29:04.609222 IP 46.241.240.125.500 > 46.134.75.12.500: [|isakmp]
> 18:29:05.060864 IP 46.134.75.12.500 > 46.241.240.125.500: [|isakmp]
> 18:29:05.060903 IP 46.134.75.12.500 > 172.24.5.10.500: [|isakmp]
> 18:29:06.169912 IP 172.24.5.10.4500 > 46.134.75.12.4500: NONESP-encap:
> [|isakmp]
> 18:29:06.169937 IP 46.241.240.125.4500 > 46.134.75.12.4500:
> NONESP-encap: [|isakmp]
> 18:29:14.635666 IP 46.134.75.12.500 > 46.241.240.125.4500: [|isakmp]
> 18:29:16.319506 IP 172.24.5.10.4500 > 46.134.75.12.4500: NONESP-encap:
> [|isakmp]
> 18:29:16.319522 IP 46.241.240.125.4500 > 46.134.75.12.4500:
> NONESP-encap: [|isakmp]
> 18:29:18.253730 IP 172.24.5.10.4500 > 46.134.75.12.4500:
> isakmp-nat-keep-alive
> 18:29:18.253743 IP 46.241.240.125.4500 > 46.134.75.12.4500:
> isakmp-nat-keep-alive
> 18:29:22.764709 IP 46.134.75.12.500 > 46.241.240.125.4500: [|isakmp]
> 18:29:24.771837 IP 46.134.75.12.500 > 46.241.240.125.4500: [|isakmp]
> 18:29:25.142336 IP 172.24.5.10.4500 > 46.134.75.12.4500: NONESP-encap:
> [|isakmp]
>
> 172.24.5.10 is the client.
> 46.134.75.12 is the server.
> 46.241.240.125 is the external IP of the NAT GW.
>
> As can be seen the NAT seems to work absolutely fine (all packets shows
> twice - tcpdump -i any, one packet with the external GW IP and the other
> with the internal IP), except the second and third last packets, which
> only shows on the external side.
>
> Looking at the above my assumption is that port 500 -> 500 opens a
> mapping in the connection tracking table on the GW, thus the traffic
> goes just fine in both directions. Then the 4500 -> 4500 packet does
> exactly the same and this is where the problem then comes in, the server
> still responds FROM port 500 to port 4500, seeing that the GW has no
> mapping for this incoming pair it has no choice but to drop the packet,
> preventing the security negotiation from completing.
>
> What I did to confirm that this was indeed the case is I installed the
> exact same server config a box on my LAN, and set nat_traversal to force.
>
> This resulted in a similar sequence of packets, with the exception that
> since there is no NAT the traffic from port 500 -> 4500 reached it's
> destination, and resulted in the traffic to complete correctly.
>
> I'm not all that familiar with the code so don't know where to go
> looking for this problem. Or even whether 0.8.0 has perhaps fixed this
> already (didn't see anything obvious in the ChangeLog). Kernels on my
> server and client is 2.6.37.2 in both cases. My setup for setkey on the
> server:
>
> spdadd 0.0.0.0/0[1701] 0.0.0.0/0 udp -P out ipsec
> esp/transport//require;
>
> spdadd 0.0.0.0/0 0.0.0.0/0[1701] udp -P in ipsec
> esp/transport//require;
>
> For the client it's an exact reverse with the in and out keywords just
> swapped around.
>
> The above behavior was observed and confirmed using Linux as the NAT GW,
> but the client has reported the same error occuring on Windows behind at
> least two other unknown NAT gateways.
>
> As it stands the only "fix" I can see is a really ugly iptables based
> hack to rewrite the source port to port 4500 on all packets outbound to
> socket pairs that has originally been inbound to port 4500. And
> honestly, that really feels like a massive kludge and I would not even
> know where to start with pulling off a hack like that anyway.
>
> Kind Regards,
> Jaco
>
> ------------------------------------------------------------------------------
> Simplify data backup and recovery for your virtual environment with vRanger.
> Installation's a snap, and flexible recovery options mean your data is safe,
> secure and there when you need it. Discover what all the cheering's about.
> Get your free trial download today.
> http://p.sf.net/sfu/quest-dev2dev2
> _______________________________________________
> Ipsec-tools-devel mailing list
> Ips...@li...
> https://lists.sourceforge.net/lists/listinfo/ipsec-tools-devel
|
|
From: Jaco K. <ja...@ul...> - 2011-06-06 21:36:52
|
Hi All,
Ok, it seems ipsec-tools 0.8.0 does indeed solve the issue outlined
below, however, I'm still unable to establish my link. setkey -D does
show one of the two directions being able to negotiate parameters, and
the debug logs shows phase1 timing out for some reason.
On the server (log info) I see this:
Jun 6 23:10:56 clyde racoon: alg_oakley_hmacdef_one(hmac_sha1 size=32):
0.000011
Jun 6 23:10:56 clyde racoon: alg_oakley_hmacdef_one(hmac_sha1
size=145): 0.000004
Jun 6 23:10:56 clyde racoon: alg_oakley_hmacdef_one(hmac_sha1
size=165): 0.000005
Jun 6 23:10:56 clyde racoon: alg_oakley_hmacdef_one(hmac_sha1
size=165): 0.000004
Jun 6 23:10:56 clyde racoon: alg_oakley_hmacdef_one(hmac_sha1 size=1):
0.000004
Jun 6 23:10:56 clyde racoon: alg_oakley_hmacdef_one(hmac_sha1 size=20):
0.000003
Jun 6 23:10:56 clyde racoon: phase1(ident R msg2): 0.003390
Jun 6 23:10:57 clyde racoon: INFO: NAT-T: ports changed to:
46.246.240.125[1030]<->46.134.75.12[4500]
Jun 6 23:10:57 clyde racoon: INFO: KA list add:
46.134.75.12[4500]->46.246.240.125[1030]
Jun 6 23:10:57 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000037
Jun 6 23:11:07 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000015
Jun 6 23:11:07 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000011
Jun 6 23:11:17 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000012
Jun 6 23:11:17 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000011
Jun 6 23:11:27 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000011
Jun 6 23:11:27 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000011
Jun 6 23:11:37 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000011
Jun 6 23:11:37 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000011
Jun 6 23:11:46 clyde racoon: ERROR: phase1 negotiation failed due to
time up. 294c2d06e1868e10:83426a7ca8a8fbc9
Which to me looks like it's getting stuck at 23:10:57 onwards. Those
looks like it's trying to process the same packet over and over.
Full debug2 logs, as well as config files for a replay of the above on
the server and client follows.
Server:
racoon.conf:
log debug2;
path pre_shared_key "/etc/racoon/psk.txt";
remote anonymous {
exchange_mode main;
doi ipsec_doi;
situation identity_only;
nat_traversal on;
initial_contact on;
proposal_check obey;
proposal {
encryption_algorithm aes;
encryption_algorithm 3des;
hash_algorithm md5;
hash_algorithm sha1;
authentication_method pre_shared_key;
dh_group modp1024;
}
}
sainfo anonymous
{
lifetime time 1 hour;
encryption_algorithm aes;
encryption_algorithm 3des;
authentication_algorithm hmac_sha1;
authentication_algorithm hmac_md5;
compression_algorithm deflate;
}
Logs:
Jun 6 23:24:32 clyde racoon: DEBUG: ===
Jun 6 23:24:32 clyde racoon: DEBUG: 180 bytes message received from
46.246.240.125[500] to 46.134.75.12[500]
Jun 6 23:24:32 clyde racoon: DEBUG:
Jun 6 23:24:32 clyde racoon: [46.246.240.125] DEBUG2: Checking remote
conf "anonymous" anonymous.
Jun 6 23:24:32 clyde racoon: DEBUG2: enumrmconf: "anonymous" matches.
Jun 6 23:24:32 clyde racoon: DEBUG: ===
Jun 6 23:24:32 clyde racoon: INFO: respond new phase 1 negotiation:
46.134.75.12[500]<=>46.246.240.125[500]
Jun 6 23:24:32 clyde racoon: INFO: begin Identity Protection mode.
Jun 6 23:24:32 clyde racoon: DEBUG: begin.
Jun 6 23:24:32 clyde racoon: DEBUG: seen nptype=1(sa)
Jun 6 23:24:32 clyde racoon: DEBUG: seen nptype=13(vid)
Jun 6 23:24:32 clyde racoon: DEBUG: seen nptype=13(vid)
Jun 6 23:24:32 clyde racoon: DEBUG: seen nptype=13(vid)
Jun 6 23:24:32 clyde racoon: DEBUG: seen nptype=13(vid)
Jun 6 23:24:32 clyde racoon: DEBUG: seen nptype=13(vid)
Jun 6 23:24:32 clyde racoon: DEBUG: succeed.
Jun 6 23:24:32 clyde racoon: INFO: received Vendor ID: RFC 3947
Jun 6 23:24:32 clyde racoon: [46.246.240.125] DEBUG2: Checking remote
conf "anonymous" anonymous.
Jun 6 23:24:32 clyde racoon: DEBUG2: enumrmconf: "anonymous" matches.
Jun 6 23:24:32 clyde racoon: INFO: received Vendor ID:
draft-ietf-ipsec-nat-t-ike-02
Jun 6 23:24:32 clyde racoon: [46.246.240.125] DEBUG2: Checking remote
conf "anonymous" anonymous.
Jun 6 23:24:32 clyde racoon: DEBUG2: enumrmconf: "anonymous" matches.
Jun 6 23:24:32 clyde racoon: INFO: received Vendor ID:
draft-ietf-ipsec-nat-t-ike-02
Jun 6 23:24:32 clyde racoon: [46.246.240.125] DEBUG2: Checking remote
conf "anonymous" anonymous.
Jun 6 23:24:32 clyde racoon: DEBUG2: enumrmconf: "anonymous" matches.
Jun 6 23:24:32 clyde racoon: INFO: received Vendor ID:
draft-ietf-ipsec-nat-t-ike-00
Jun 6 23:24:32 clyde racoon: [46.246.240.125] DEBUG2: Checking remote
conf "anonymous" anonymous.
Jun 6 23:24:32 clyde racoon: DEBUG2: enumrmconf: "anonymous" matches.
Jun 6 23:24:32 clyde racoon: INFO: received Vendor ID: DPD
Jun 6 23:24:32 clyde racoon: DEBUG: remote supports DPD
Jun 6 23:24:32 clyde racoon: [46.246.240.125] INFO: Selected NAT-T
version: RFC 3947
Jun 6 23:24:32 clyde racoon: DEBUG: total SA len=48
Jun 6 23:24:32 clyde racoon: DEBUG:
Jun 6 23:24:32 clyde racoon: DEBUG: begin.
Jun 6 23:24:32 clyde racoon: DEBUG: seen nptype=2(prop)
Jun 6 23:24:32 clyde racoon: DEBUG: succeed.
Jun 6 23:24:32 clyde racoon: DEBUG: proposal #1 len=40
Jun 6 23:24:32 clyde racoon: DEBUG: begin.
Jun 6 23:24:32 clyde racoon: DEBUG: seen nptype=3(trns)
Jun 6 23:24:32 clyde racoon: DEBUG: succeed.
Jun 6 23:24:32 clyde racoon: DEBUG: transform #1 len=32
Jun 6 23:24:32 clyde racoon: DEBUG: type=Life Type, flag=0x8000,
lorv=seconds
Jun 6 23:24:32 clyde racoon: DEBUG: type=Life Duration, flag=0x8000,
lorv=28800
Jun 6 23:24:32 clyde racoon: DEBUG: type=Encryption Algorithm,
flag=0x8000, lorv=3DES-CBC
Jun 6 23:24:32 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:24:32 clyde racoon: DEBUG: type=Authentication Method,
flag=0x8000, lorv=pre-shared key
Jun 6 23:24:32 clyde racoon: DEBUG: type=Hash Algorithm, flag=0x8000,
lorv=SHA
Jun 6 23:24:32 clyde racoon: DEBUG: hash(sha1)
Jun 6 23:24:32 clyde racoon: DEBUG: type=Group Description,
flag=0x8000, lorv=1024-bit MODP group
Jun 6 23:24:32 clyde racoon: DEBUG: hmac(modp1024)
Jun 6 23:24:32 clyde racoon: DEBUG: pair 1:
Jun 6 23:24:32 clyde racoon: DEBUG: 0x1b8ae30: next=(nil) tnext=(nil)
Jun 6 23:24:32 clyde racoon: DEBUG: proposal #1: 1 transform
Jun 6 23:24:32 clyde racoon: DEBUG: type=Life Type, flag=0x8000,
lorv=seconds
Jun 6 23:24:32 clyde racoon: DEBUG: type=Life Duration, flag=0x8000,
lorv=28800
Jun 6 23:24:32 clyde racoon: DEBUG: type=Encryption Algorithm,
flag=0x8000, lorv=3DES-CBC
Jun 6 23:24:32 clyde racoon: DEBUG: type=Authentication Method,
flag=0x8000, lorv=pre-shared key
Jun 6 23:24:32 clyde racoon: DEBUG: type=Hash Algorithm, flag=0x8000,
lorv=SHA
Jun 6 23:24:32 clyde racoon: DEBUG: type=Group Description,
flag=0x8000, lorv=1024-bit MODP group
Jun 6 23:24:32 clyde racoon: DEBUG: prop#=1, prot-id=ISAKMP,
spi-size=0, #trns=1
Jun 6 23:24:32 clyde racoon: DEBUG: trns#=1, trns-id=IKE
Jun 6 23:24:32 clyde racoon: DEBUG: lifetime = 28800
Jun 6 23:24:32 clyde racoon: DEBUG: lifebyte = 0
Jun 6 23:24:32 clyde racoon: DEBUG: enctype = 3DES-CBC
Jun 6 23:24:32 clyde racoon: DEBUG: encklen = 0
Jun 6 23:24:32 clyde racoon: DEBUG: hashtype = SHA
Jun 6 23:24:32 clyde racoon: DEBUG: authmethod = pre-shared key
Jun 6 23:24:32 clyde racoon: DEBUG: dh_group = 1024-bit MODP group
Jun 6 23:24:32 clyde racoon: [46.246.240.125] DEBUG2: Checking remote
conf "anonymous" anonymous.
Jun 6 23:24:32 clyde racoon: DEBUG2: enumrmconf: "anonymous" matches.
Jun 6 23:24:32 clyde racoon: DEBUG2: checkisakmpsa:
Jun 6 23:24:32 clyde racoon: DEBUG: an acceptable proposal found.
Jun 6 23:24:32 clyde racoon: DEBUG: hmac(modp1024)
Jun 6 23:24:32 clyde racoon: DEBUG: agreed on pre-shared key auth.
Jun 6 23:24:32 clyde racoon: DEBUG: ===
Jun 6 23:24:32 clyde racoon: DEBUG: new cookie:
Jun 6 23:24:32 clyde racoon: DEBUG: add payload of len 48, next type 13
Jun 6 23:24:32 clyde racoon: DEBUG: add payload of len 16, next type 13
Jun 6 23:24:32 clyde racoon: DEBUG: add payload of len 16, next type 0
Jun 6 23:24:32 clyde racoon: DEBUG: 120 bytes from 46.134.75.12[500] to
46.246.240.125[500]
Jun 6 23:24:32 clyde racoon: DEBUG: sockname 46.134.75.12[500]
Jun 6 23:24:32 clyde racoon: DEBUG: send packet from 46.134.75.12[500]
Jun 6 23:24:32 clyde racoon: DEBUG: send packet to 46.246.240.125[500]
Jun 6 23:24:32 clyde racoon: DEBUG: src4 46.134.75.12[500]
Jun 6 23:24:32 clyde racoon: DEBUG: dst4 46.246.240.125[500]
Jun 6 23:24:32 clyde racoon: DEBUG: 1 times of 120 bytes message will
be sent to 46.246.240.125[500]
Jun 6 23:24:32 clyde racoon: DEBUG:
Jun 6 23:24:32 clyde racoon: DEBUG: resend phase1 packet
b3a01519dfb2c4c6:54d41f8b8ce78205
Jun 6 23:24:32 clyde racoon: phase1(ident R msg1): 0.000774
Jun 6 23:24:33 clyde racoon: DEBUG: ===
Jun 6 23:24:33 clyde racoon: DEBUG: 228 bytes message received from
46.246.240.125[500] to 46.134.75.12[500]
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG: begin.
Jun 6 23:24:33 clyde racoon: DEBUG: seen nptype=4(ke)
Jun 6 23:24:33 clyde racoon: DEBUG: seen nptype=10(nonce)
Jun 6 23:24:33 clyde racoon: DEBUG: seen nptype=20(nat-d)
Jun 6 23:24:33 clyde racoon: DEBUG: seen nptype=20(nat-d)
Jun 6 23:24:33 clyde racoon: DEBUG: succeed.
Jun 6 23:24:33 clyde racoon: [46.134.75.12] INFO: Hashing
46.134.75.12[500] with algo #2
Jun 6 23:24:33 clyde racoon: DEBUG: hash(sha1)
Jun 6 23:24:33 clyde racoon: INFO: NAT-D payload #0 verified
Jun 6 23:24:33 clyde racoon: [46.246.240.125] INFO: Hashing
46.246.240.125[500] with algo #2
Jun 6 23:24:33 clyde racoon: DEBUG: hash(sha1)
Jun 6 23:24:33 clyde racoon: INFO: NAT-D payload #1 doesn't match
Jun 6 23:24:33 clyde racoon: INFO: NAT detected: PEER
Jun 6 23:24:33 clyde racoon: DEBUG: ===
Jun 6 23:24:33 clyde racoon: oakley_dh_generate(MODP1024): 0.001727
Jun 6 23:24:33 clyde racoon: DEBUG: compute DH's private.
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG: compute DH's public.
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: [46.246.240.125] INFO: Hashing
46.246.240.125[500] with algo #2
Jun 6 23:24:33 clyde racoon: DEBUG: hash(sha1)
Jun 6 23:24:33 clyde racoon: [46.134.75.12] INFO: Hashing
46.134.75.12[500] with algo #2
Jun 6 23:24:33 clyde racoon: DEBUG: hash(sha1)
Jun 6 23:24:33 clyde racoon: INFO: Adding remote and local NAT-D payloads.
Jun 6 23:24:33 clyde racoon: DEBUG: add payload of len 128, next type 10
Jun 6 23:24:33 clyde racoon: DEBUG: add payload of len 16, next type 20
Jun 6 23:24:33 clyde racoon: DEBUG: add payload of len 20, next type 20
Jun 6 23:24:33 clyde racoon: DEBUG: add payload of len 20, next type 0
Jun 6 23:24:33 clyde racoon: DEBUG: 228 bytes from 46.134.75.12[500] to
46.246.240.125[500]
Jun 6 23:24:33 clyde racoon: DEBUG: sockname 46.134.75.12[500]
Jun 6 23:24:33 clyde racoon: DEBUG: send packet from 46.134.75.12[500]
Jun 6 23:24:33 clyde racoon: DEBUG: send packet to 46.246.240.125[500]
Jun 6 23:24:33 clyde racoon: DEBUG: src4 46.134.75.12[500]
Jun 6 23:24:33 clyde racoon: DEBUG: dst4 46.246.240.125[500]
Jun 6 23:24:33 clyde racoon: DEBUG: 1 times of 228 bytes message will
be sent to 46.246.240.125[500]
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG: resend phase1 packet
b3a01519dfb2c4c6:54d41f8b8ce78205
Jun 6 23:24:33 clyde racoon: oakley_dh_compute(MODP1024): 0.001832
Jun 6 23:24:33 clyde racoon: DEBUG: compute DH's shared.
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG: the psk found.
Jun 6 23:24:33 clyde racoon: DEBUG2: psk:
Jun 6 23:24:33 clyde racoon: DEBUG2:
Jun 6 23:24:33 clyde racoon: DEBUG: nonce 1:
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG: nonce 2:
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG: hmac(hmac_sha1)
Jun 6 23:24:33 clyde racoon: alg_oakley_hmacdef_one(hmac_sha1 size=32):
0.000012
Jun 6 23:24:33 clyde racoon: DEBUG: SKEYID computed:
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG: hmac(hmac_sha1)
Jun 6 23:24:33 clyde racoon: alg_oakley_hmacdef_one(hmac_sha1
size=145): 0.000005
Jun 6 23:24:33 clyde racoon: DEBUG: SKEYID_d computed:
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG: hmac(hmac_sha1)
Jun 6 23:24:33 clyde racoon: alg_oakley_hmacdef_one(hmac_sha1
size=165): 0.000005
Jun 6 23:24:33 clyde racoon: DEBUG: SKEYID_a computed:
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG: hmac(hmac_sha1)
Jun 6 23:24:33 clyde racoon: alg_oakley_hmacdef_one(hmac_sha1
size=165): 0.000004
Jun 6 23:24:33 clyde racoon: DEBUG: SKEYID_e computed:
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:24:33 clyde racoon: DEBUG: hash(sha1)
Jun 6 23:24:33 clyde racoon: DEBUG: len(SKEYID_e) < len(Ka) (20 < 24),
generating long key (Ka = K1 | K2 | ...)
Jun 6 23:24:33 clyde racoon: DEBUG: hmac(hmac_sha1)
Jun 6 23:24:33 clyde racoon: alg_oakley_hmacdef_one(hmac_sha1 size=1):
0.000004
Jun 6 23:24:33 clyde racoon: DEBUG: compute intermediate encryption key K1
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG: hmac(hmac_sha1)
Jun 6 23:24:33 clyde racoon: alg_oakley_hmacdef_one(hmac_sha1 size=20):
0.000005
Jun 6 23:24:33 clyde racoon: DEBUG: compute intermediate encryption key K2
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG: final encryption key computed:
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: DEBUG: hash(sha1)
Jun 6 23:24:33 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:24:33 clyde racoon: DEBUG: IV computed:
Jun 6 23:24:33 clyde racoon: DEBUG:
Jun 6 23:24:33 clyde racoon: phase1(ident R msg2): 0.004387
Jun 6 23:24:34 clyde racoon: DEBUG: ===
Jun 6 23:24:34 clyde racoon: DEBUG: 68 bytes message received from
46.246.240.125[4500] to 46.134.75.12[4500]
Jun 6 23:24:34 clyde racoon: DEBUG:
Jun 6 23:24:34 clyde racoon: INFO: NAT-T: ports changed to:
46.246.240.125[4500]<->46.134.75.12[4500]
Jun 6 23:24:34 clyde racoon: INFO: KA list add:
46.134.75.12[4500]->46.246.240.125[4500]
Jun 6 23:24:34 clyde racoon: DEBUG: begin decryption.
Jun 6 23:24:34 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:24:34 clyde racoon: DEBUG: IV was saved for next processing:
Jun 6 23:24:34 clyde racoon: DEBUG:
Jun 6 23:24:34 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:24:34 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000035
Jun 6 23:24:34 clyde racoon: DEBUG: with key:
Jun 6 23:24:34 clyde racoon: DEBUG:
Jun 6 23:24:34 clyde racoon: DEBUG: decrypted payload by IV:
Jun 6 23:24:34 clyde racoon: DEBUG:
Jun 6 23:24:34 clyde racoon: DEBUG: decrypted payload, but not trimed.
Jun 6 23:24:34 clyde racoon: DEBUG:
Jun 6 23:24:34 clyde racoon: DEBUG: padding len=22
Jun 6 23:24:34 clyde racoon: DEBUG: skip to trim padding.
Jun 6 23:24:34 clyde racoon: DEBUG: decrypted.
Jun 6 23:24:34 clyde racoon: DEBUG:
Jun 6 23:24:34 clyde racoon: DEBUG: begin.
Jun 6 23:24:34 clyde racoon: DEBUG: seen nptype=5(id)
Jun 6 23:24:34 clyde racoon: DEBUG: invalid length of payload
Jun 6 23:24:37 clyde racoon: DEBUG: KA:
46.134.75.12[4500]->46.246.240.125[4500]
Jun 6 23:24:37 clyde racoon: DEBUG: sockname 46.134.75.12[4500]
Jun 6 23:24:37 clyde racoon: DEBUG: send packet from 46.134.75.12[4500]
Jun 6 23:24:37 clyde racoon: DEBUG: send packet to 46.246.240.125[4500]
Jun 6 23:24:37 clyde racoon: DEBUG: src4 46.134.75.12[4500]
Jun 6 23:24:37 clyde racoon: DEBUG: dst4 46.246.240.125[4500]
Jun 6 23:24:37 clyde racoon: DEBUG: 1 times of 1 bytes message will be
sent to 46.246.240.125[4500]
Jun 6 23:24:37 clyde racoon: DEBUG:
Jun 6 23:24:43 clyde racoon: DEBUG: Adding NON-ESP marker
Jun 6 23:24:43 clyde racoon: DEBUG: 232 bytes from 46.134.75.12[4500]
to 46.246.240.125[4500]
Jun 6 23:24:43 clyde racoon: DEBUG: sockname 46.134.75.12[4500]
Jun 6 23:24:43 clyde racoon: DEBUG: send packet from 46.134.75.12[4500]
Jun 6 23:24:43 clyde racoon: DEBUG: send packet to 46.246.240.125[4500]
Jun 6 23:24:43 clyde racoon: DEBUG: src4 46.134.75.12[4500]
Jun 6 23:24:43 clyde racoon: DEBUG: dst4 46.246.240.125[4500]
Jun 6 23:24:43 clyde racoon: DEBUG: 1 times of 232 bytes message will
be sent to 46.246.240.125[4500]
Jun 6 23:24:43 clyde racoon: DEBUG:
Jun 6 23:24:43 clyde racoon: DEBUG: resend phase1 packet
b3a01519dfb2c4c6:54d41f8b8ce78205
Jun 6 23:24:44 clyde racoon: DEBUG: ===
Jun 6 23:24:44 clyde racoon: DEBUG: 68 bytes message received from
46.246.240.125[4500] to 46.134.75.12[4500]
Jun 6 23:24:44 clyde racoon: DEBUG:
Jun 6 23:24:44 clyde racoon: DEBUG: begin decryption.
Jun 6 23:24:44 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:24:44 clyde racoon: DEBUG: IV was saved for next processing:
Jun 6 23:24:44 clyde racoon: DEBUG:
Jun 6 23:24:44 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:24:44 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000038
Jun 6 23:24:44 clyde racoon: DEBUG: with key:
Jun 6 23:24:44 clyde racoon: DEBUG:
Jun 6 23:24:44 clyde racoon: DEBUG: decrypted payload by IV:
Jun 6 23:24:44 clyde racoon: DEBUG:
Jun 6 23:24:44 clyde racoon: DEBUG: decrypted payload, but not trimed.
Jun 6 23:24:44 clyde racoon: DEBUG:
Jun 6 23:24:44 clyde racoon: DEBUG: padding len=22
Jun 6 23:24:44 clyde racoon: DEBUG: skip to trim padding.
Jun 6 23:24:44 clyde racoon: DEBUG: decrypted.
Jun 6 23:24:44 clyde racoon: DEBUG:
Jun 6 23:24:44 clyde racoon: DEBUG: begin.
Jun 6 23:24:44 clyde racoon: DEBUG: seen nptype=5(id)
Jun 6 23:24:44 clyde racoon: DEBUG: invalid length of payload
Jun 6 23:24:44 clyde racoon: DEBUG: ===
Jun 6 23:24:44 clyde racoon: DEBUG: 68 bytes message received from
46.246.240.125[4500] to 46.134.75.12[4500]
Jun 6 23:24:44 clyde racoon: DEBUG:
Jun 6 23:24:44 clyde racoon: DEBUG: begin decryption.
Jun 6 23:24:44 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:24:44 clyde racoon: DEBUG: IV was saved for next processing:
Jun 6 23:24:44 clyde racoon: DEBUG:
Jun 6 23:24:44 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:24:44 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000006
Jun 6 23:24:44 clyde racoon: DEBUG: with key:
Jun 6 23:24:44 clyde racoon: DEBUG:
Jun 6 23:24:44 clyde racoon: DEBUG: decrypted payload by IV:
Jun 6 23:24:44 clyde racoon: DEBUG:
Jun 6 23:24:44 clyde racoon: DEBUG: decrypted payload, but not trimed.
Jun 6 23:24:44 clyde racoon: DEBUG:
Jun 6 23:24:44 clyde racoon: DEBUG: padding len=22
Jun 6 23:24:44 clyde racoon: DEBUG: skip to trim padding.
Jun 6 23:24:44 clyde racoon: DEBUG: decrypted.
Jun 6 23:24:44 clyde racoon: DEBUG:
Jun 6 23:24:44 clyde racoon: DEBUG: begin.
Jun 6 23:24:44 clyde racoon: DEBUG: seen nptype=5(id)
Jun 6 23:24:44 clyde racoon: DEBUG: invalid length of payload
Jun 6 23:24:53 clyde racoon: DEBUG: 232 bytes from 46.134.75.12[4500]
to 46.246.240.125[4500]
Jun 6 23:24:53 clyde racoon: DEBUG: sockname 46.134.75.12[4500]
Jun 6 23:24:53 clyde racoon: DEBUG: send packet from 46.134.75.12[4500]
Jun 6 23:24:53 clyde racoon: DEBUG: send packet to 46.246.240.125[4500]
Jun 6 23:24:53 clyde racoon: DEBUG: src4 46.134.75.12[4500]
Jun 6 23:24:53 clyde racoon: DEBUG: dst4 46.246.240.125[4500]
Jun 6 23:24:53 clyde racoon: DEBUG: 1 times of 232 bytes message will
be sent to 46.246.240.125[4500]
Jun 6 23:24:53 clyde racoon: DEBUG:
Jun 6 23:24:53 clyde racoon: DEBUG: resend phase1 packet
b3a01519dfb2c4c6:54d41f8b8ce78205
Jun 6 23:24:54 clyde racoon: DEBUG: ===
Jun 6 23:24:54 clyde racoon: DEBUG: 68 bytes message received from
46.246.240.125[4500] to 46.134.75.12[4500]
Jun 6 23:24:54 clyde racoon: DEBUG:
Jun 6 23:24:54 clyde racoon: DEBUG: begin decryption.
Jun 6 23:24:54 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:24:54 clyde racoon: DEBUG: IV was saved for next processing:
Jun 6 23:24:54 clyde racoon: DEBUG:
Jun 6 23:24:54 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:24:54 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000006
Jun 6 23:24:54 clyde racoon: DEBUG: with key:
Jun 6 23:24:54 clyde racoon: DEBUG:
Jun 6 23:24:54 clyde racoon: DEBUG: decrypted payload by IV:
Jun 6 23:24:54 clyde racoon: DEBUG:
Jun 6 23:24:54 clyde racoon: DEBUG: decrypted payload, but not trimed.
Jun 6 23:24:54 clyde racoon: DEBUG:
Jun 6 23:24:54 clyde racoon: DEBUG: padding len=22
Jun 6 23:24:54 clyde racoon: DEBUG: skip to trim padding.
Jun 6 23:24:54 clyde racoon: DEBUG: decrypted.
Jun 6 23:24:54 clyde racoon: DEBUG:
Jun 6 23:24:54 clyde racoon: DEBUG: begin.
Jun 6 23:24:54 clyde racoon: DEBUG: seen nptype=5(id)
Jun 6 23:24:54 clyde racoon: DEBUG: invalid length of payload
Jun 6 23:24:54 clyde racoon: DEBUG: ===
Jun 6 23:24:54 clyde racoon: DEBUG: 68 bytes message received from
46.246.240.125[4500] to 46.134.75.12[4500]
Jun 6 23:24:54 clyde racoon: DEBUG:
Jun 6 23:24:54 clyde racoon: DEBUG: begin decryption.
Jun 6 23:24:54 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:24:54 clyde racoon: DEBUG: IV was saved for next processing:
Jun 6 23:24:54 clyde racoon: DEBUG:
Jun 6 23:24:54 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:24:54 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000006
Jun 6 23:24:54 clyde racoon: DEBUG: with key:
Jun 6 23:24:54 clyde racoon: DEBUG:
Jun 6 23:24:54 clyde racoon: DEBUG: decrypted payload by IV:
Jun 6 23:24:54 clyde racoon: DEBUG:
Jun 6 23:24:54 clyde racoon: DEBUG: decrypted payload, but not trimed.
Jun 6 23:24:54 clyde racoon: DEBUG:
Jun 6 23:24:54 clyde racoon: DEBUG: padding len=22
Jun 6 23:24:54 clyde racoon: DEBUG: skip to trim padding.
Jun 6 23:24:54 clyde racoon: DEBUG: decrypted.
Jun 6 23:24:54 clyde racoon: DEBUG:
Jun 6 23:24:54 clyde racoon: DEBUG: begin.
Jun 6 23:24:54 clyde racoon: DEBUG: seen nptype=5(id)
Jun 6 23:24:54 clyde racoon: DEBUG: invalid length of payload
Jun 6 23:24:57 clyde racoon: DEBUG: KA:
46.134.75.12[4500]->46.246.240.125[4500]
Jun 6 23:24:57 clyde racoon: DEBUG: sockname 46.134.75.12[4500]
Jun 6 23:24:57 clyde racoon: DEBUG: send packet from 46.134.75.12[4500]
Jun 6 23:24:57 clyde racoon: DEBUG: send packet to 46.246.240.125[4500]
Jun 6 23:24:57 clyde racoon: DEBUG: src4 46.134.75.12[4500]
Jun 6 23:24:57 clyde racoon: DEBUG: dst4 46.246.240.125[4500]
Jun 6 23:24:57 clyde racoon: DEBUG: 1 times of 1 bytes message will be
sent to 46.246.240.125[4500]
Jun 6 23:24:57 clyde racoon: DEBUG:
Jun 6 23:25:03 clyde racoon: DEBUG: 232 bytes from 46.134.75.12[4500]
to 46.246.240.125[4500]
Jun 6 23:25:03 clyde racoon: DEBUG: sockname 46.134.75.12[4500]
Jun 6 23:25:03 clyde racoon: DEBUG: send packet from 46.134.75.12[4500]
Jun 6 23:25:03 clyde racoon: DEBUG: send packet to 46.246.240.125[4500]
Jun 6 23:25:03 clyde racoon: DEBUG: src4 46.134.75.12[4500]
Jun 6 23:25:03 clyde racoon: DEBUG: dst4 46.246.240.125[4500]
Jun 6 23:25:03 clyde racoon: DEBUG: 1 times of 232 bytes message will
be sent to 46.246.240.125[4500]
Jun 6 23:25:03 clyde racoon: DEBUG:
Jun 6 23:25:03 clyde racoon: DEBUG: resend phase1 packet
b3a01519dfb2c4c6:54d41f8b8ce78205
Jun 6 23:25:04 clyde racoon: DEBUG: ===
Jun 6 23:25:04 clyde racoon: DEBUG: 68 bytes message received from
46.246.240.125[4500] to 46.134.75.12[4500]
Jun 6 23:25:04 clyde racoon: DEBUG:
Jun 6 23:25:04 clyde racoon: DEBUG: begin decryption.
Jun 6 23:25:04 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:25:04 clyde racoon: DEBUG: IV was saved for next processing:
Jun 6 23:25:04 clyde racoon: DEBUG:
Jun 6 23:25:04 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:25:04 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000013
Jun 6 23:25:04 clyde racoon: DEBUG: with key:
Jun 6 23:25:04 clyde racoon: DEBUG:
Jun 6 23:25:04 clyde racoon: DEBUG: decrypted payload by IV:
Jun 6 23:25:04 clyde racoon: DEBUG:
Jun 6 23:25:04 clyde racoon: DEBUG: decrypted payload, but not trimed.
Jun 6 23:25:04 clyde racoon: DEBUG:
Jun 6 23:25:04 clyde racoon: DEBUG: padding len=22
Jun 6 23:25:04 clyde racoon: DEBUG: skip to trim padding.
Jun 6 23:25:04 clyde racoon: DEBUG: decrypted.
Jun 6 23:25:04 clyde racoon: DEBUG:
Jun 6 23:25:04 clyde racoon: DEBUG: begin.
Jun 6 23:25:04 clyde racoon: DEBUG: seen nptype=5(id)
Jun 6 23:25:04 clyde racoon: DEBUG: invalid length of payload
Jun 6 23:25:04 clyde racoon: DEBUG: ===
Jun 6 23:25:04 clyde racoon: DEBUG: 68 bytes message received from
46.246.240.125[4500] to 46.134.75.12[4500]
Jun 6 23:25:04 clyde racoon: DEBUG:
Jun 6 23:25:04 clyde racoon: DEBUG: begin decryption.
Jun 6 23:25:04 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:25:04 clyde racoon: DEBUG: IV was saved for next processing:
Jun 6 23:25:04 clyde racoon: DEBUG:
Jun 6 23:25:04 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:25:04 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000006
Jun 6 23:25:04 clyde racoon: DEBUG: with key:
Jun 6 23:25:04 clyde racoon: DEBUG:
Jun 6 23:25:04 clyde racoon: DEBUG: decrypted payload by IV:
Jun 6 23:25:04 clyde racoon: DEBUG:
Jun 6 23:25:04 clyde racoon: DEBUG: decrypted payload, but not trimed.
Jun 6 23:25:04 clyde racoon: DEBUG:
Jun 6 23:25:04 clyde racoon: DEBUG: padding len=22
Jun 6 23:25:04 clyde racoon: DEBUG: skip to trim padding.
Jun 6 23:25:04 clyde racoon: DEBUG: decrypted.
Jun 6 23:25:04 clyde racoon: DEBUG:
Jun 6 23:25:04 clyde racoon: DEBUG: begin.
Jun 6 23:25:04 clyde racoon: DEBUG: seen nptype=5(id)
Jun 6 23:25:04 clyde racoon: DEBUG: invalid length of payload
Jun 6 23:25:13 clyde racoon: DEBUG: 232 bytes from 46.134.75.12[4500]
to 46.246.240.125[4500]
Jun 6 23:25:13 clyde racoon: DEBUG: sockname 46.134.75.12[4500]
Jun 6 23:25:13 clyde racoon: DEBUG: send packet from 46.134.75.12[4500]
Jun 6 23:25:13 clyde racoon: DEBUG: send packet to 46.246.240.125[4500]
Jun 6 23:25:13 clyde racoon: DEBUG: src4 46.134.75.12[4500]
Jun 6 23:25:13 clyde racoon: DEBUG: dst4 46.246.240.125[4500]
Jun 6 23:25:13 clyde racoon: DEBUG: 1 times of 232 bytes message will
be sent to 46.246.240.125[4500]
Jun 6 23:25:13 clyde racoon: DEBUG:
Jun 6 23:25:13 clyde racoon: DEBUG: resend phase1 packet
b3a01519dfb2c4c6:54d41f8b8ce78205
Jun 6 23:25:14 clyde racoon: DEBUG: ===
Jun 6 23:25:14 clyde racoon: DEBUG: 68 bytes message received from
46.246.240.125[4500] to 46.134.75.12[4500]
Jun 6 23:25:14 clyde racoon: DEBUG:
Jun 6 23:25:14 clyde racoon: DEBUG: begin decryption.
Jun 6 23:25:14 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:25:14 clyde racoon: DEBUG: IV was saved for next processing:
Jun 6 23:25:14 clyde racoon: DEBUG:
Jun 6 23:25:14 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:25:14 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000009
Jun 6 23:25:14 clyde racoon: DEBUG: with key:
Jun 6 23:25:14 clyde racoon: DEBUG:
Jun 6 23:25:14 clyde racoon: DEBUG: decrypted payload by IV:
Jun 6 23:25:14 clyde racoon: DEBUG:
Jun 6 23:25:14 clyde racoon: DEBUG: decrypted payload, but not trimed.
Jun 6 23:25:14 clyde racoon: DEBUG:
Jun 6 23:25:14 clyde racoon: DEBUG: padding len=22
Jun 6 23:25:14 clyde racoon: DEBUG: skip to trim padding.
Jun 6 23:25:14 clyde racoon: DEBUG: decrypted.
Jun 6 23:25:14 clyde racoon: DEBUG:
Jun 6 23:25:14 clyde racoon: DEBUG: begin.
Jun 6 23:25:14 clyde racoon: DEBUG: seen nptype=5(id)
Jun 6 23:25:14 clyde racoon: DEBUG: invalid length of payload
Jun 6 23:25:14 clyde racoon: DEBUG: ===
Jun 6 23:25:14 clyde racoon: DEBUG: 68 bytes message received from
46.246.240.125[4500] to 46.134.75.12[4500]
Jun 6 23:25:14 clyde racoon: DEBUG:
Jun 6 23:25:14 clyde racoon: DEBUG: begin decryption.
Jun 6 23:25:14 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:25:14 clyde racoon: DEBUG: IV was saved for next processing:
Jun 6 23:25:14 clyde racoon: DEBUG:
Jun 6 23:25:14 clyde racoon: DEBUG: encryption(3des)
Jun 6 23:25:14 clyde racoon: alg_oakley_encdef_decrypt(3des klen=192
size=40): 0.000005
Jun 6 23:25:14 clyde racoon: DEBUG: with key:
Jun 6 23:25:14 clyde racoon: DEBUG:
Jun 6 23:25:14 clyde racoon: DEBUG: decrypted payload by IV:
Jun 6 23:25:14 clyde racoon: DEBUG:
Jun 6 23:25:14 clyde racoon: DEBUG: decrypted payload, but not trimed.
Jun 6 23:25:14 clyde racoon: DEBUG:
Jun 6 23:25:14 clyde racoon: DEBUG: padding len=22
Jun 6 23:25:14 clyde racoon: DEBUG: skip to trim padding.
Jun 6 23:25:14 clyde racoon: DEBUG: decrypted.
Jun 6 23:25:14 clyde racoon: DEBUG:
Jun 6 23:25:14 clyde racoon: DEBUG: begin.
Jun 6 23:25:14 clyde racoon: DEBUG: seen nptype=5(id)
Jun 6 23:25:14 clyde racoon: DEBUG: invalid length of payload
Jun 6 23:25:17 clyde racoon: DEBUG: KA:
46.134.75.12[4500]->46.246.240.125[4500]
Jun 6 23:25:17 clyde racoon: DEBUG: sockname 46.134.75.12[4500]
Jun 6 23:25:17 clyde racoon: DEBUG: send packet from 46.134.75.12[4500]
Jun 6 23:25:17 clyde racoon: DEBUG: send packet to 46.246.240.125[4500]
Jun 6 23:25:17 clyde racoon: DEBUG: src4 46.134.75.12[4500]
Jun 6 23:25:17 clyde racoon: DEBUG: dst4 46.246.240.125[4500]
Jun 6 23:25:17 clyde racoon: DEBUG: 1 times of 1 bytes message will be
sent to 46.246.240.125[4500]
Jun 6 23:25:17 clyde racoon: DEBUG:
Jun 6 23:25:23 clyde racoon: ERROR: phase1 negotiation failed due to
time up. b3a01519dfb2c4c6:54d41f8b8ce78205
Jun 6 23:25:23 clyde racoon: INFO: KA remove:
46.134.75.12[4500]->46.246.240.125[4500]
Jun 6 23:25:23 clyde racoon: DEBUG: KA tree dump:
46.134.75.12[4500]->46.246.240.125[4500] (in_use=1)
Jun 6 23:25:23 clyde racoon: DEBUG: KA removing this one...
Jun 6 23:25:23 clyde racoon: DEBUG: IV freed
Client:
racoon.conf:
log debug2;
path pre_shared_key "/etc/racoon/psk.txt";
remote anonymous {
exchange_mode main;
doi ipsec_doi;
situation identity_only;
# my_identifier fqdn "blackpearl.local"
nat_traversal on;
initial_contact on;
proposal_check obey;
proposal {
encryption_algorithm aes;
encryption_algorithm 3des;
hash_algorithm md5;
hash_algorithm sha1;
authentication_method pre_shared_key;
dh_group modp1024;
}
}
sainfo anonymous
{
lifetime time 1 hour;
encryption_algorithm aes;
encryption_algorithm 3des;
authentication_algorithm hmac_sha1;
compression_algorithm deflate;
}
Logs:
Jun 6 23:24:32 blackpearl racoon: DEBUG: pk_recv: retry[0] recv()
Jun 6 23:24:32 blackpearl racoon: DEBUG: got pfkey ACQUIRE message
Jun 6 23:24:32 blackpearl racoon: DEBUG2:
Jun 6 23:24:32 blackpearl racoon: DEBUG: suitable outbound SP found:
0.0.0.0/0[0] 0.0.0.0/0[1701] proto=udp dir=out.
Jun 6 23:24:32 blackpearl racoon: DEBUG: sub:0x7fff0bfc97f0:
0.0.0.0/0[1701] 0.0.0.0/0[0] proto=udp dir=in
Jun 6 23:24:32 blackpearl racoon: DEBUG: db :0x13d2320: 0.0.0.0/0[0]
0.0.0.0/0[1701] proto=udp dir=out
Jun 6 23:24:32 blackpearl racoon: DEBUG: sub:0x7fff0bfc97f0:
0.0.0.0/0[1701] 0.0.0.0/0[0] proto=udp dir=in
Jun 6 23:24:32 blackpearl racoon: DEBUG: db :0x13d25a0: 0.0.0.0/0[1701]
0.0.0.0/0[0] proto=udp dir=fwd
Jun 6 23:24:32 blackpearl racoon: DEBUG: sub:0x7fff0bfc97f0:
0.0.0.0/0[1701] 0.0.0.0/0[0] proto=udp dir=in
Jun 6 23:24:32 blackpearl racoon: DEBUG: db :0x13d26f0: 0.0.0.0/0[1701]
0.0.0.0/0[0] proto=udp dir=in
Jun 6 23:24:32 blackpearl racoon: DEBUG: suitable inbound SP found:
0.0.0.0/0[1701] 0.0.0.0/0[0] proto=udp dir=in.
Jun 6 23:24:32 blackpearl racoon: DEBUG: new acquire 0.0.0.0/0[0]
0.0.0.0/0[1701] proto=udp dir=out
Jun 6 23:24:32 blackpearl racoon: [46.134.75.12] DEBUG2: Checking
remote conf "anonymous" anonymous.
Jun 6 23:24:32 blackpearl racoon: DEBUG2: enumrmconf: "anonymous" matches.
Jun 6 23:24:32 blackpearl racoon: [46.134.75.12] DEBUG: configuration
"anonymous" selected.
Jun 6 23:24:32 blackpearl racoon: DEBUG: getsainfo params:
loc='0.0.0.0/0' rmt='0.0.0.0/0' peer='NULL' client='NULL' id=0
Jun 6 23:24:32 blackpearl racoon: DEBUG: evaluating sainfo:
loc='ANONYMOUS', rmt='ANONYMOUS', peer='ANY', id=0
Jun 6 23:24:32 blackpearl racoon: DEBUG: check and compare ids : values
matched (ANONYMOUS)
Jun 6 23:24:32 blackpearl racoon: DEBUG: check and compare ids : values
matched (ANONYMOUS)
Jun 6 23:24:32 blackpearl racoon: DEBUG: selected sainfo:
loc='ANONYMOUS', rmt='ANONYMOUS', peer='ANY', id=0
Jun 6 23:24:32 blackpearl racoon: DEBUG: (proto_id=ESP spisize=4
spi=00000000 spi_p=00000000 encmode=Transport reqid=0:0)
Jun 6 23:24:32 blackpearl racoon: DEBUG: (trns_id=AES encklen=128
authtype=hmac-sha)
Jun 6 23:24:32 blackpearl racoon: DEBUG: (trns_id=3DES encklen=0
authtype=hmac-sha)
Jun 6 23:24:32 blackpearl racoon: DEBUG: in post_acquire
Jun 6 23:24:32 blackpearl racoon: [46.134.75.12] DEBUG2: Checking
remote conf "anonymous" anonymous.
Jun 6 23:24:32 blackpearl racoon: DEBUG2: enumrmconf: "anonymous" matches.
Jun 6 23:24:32 blackpearl racoon: [46.134.75.12] DEBUG: configuration
"anonymous" selected.
Jun 6 23:24:32 blackpearl racoon: DEBUG2: getph1: start
Jun 6 23:24:32 blackpearl racoon: DEBUG2: local: 172.24.5.10[0]
Jun 6 23:24:32 blackpearl racoon: DEBUG2: remote: 46.134.75.12[0]
Jun 6 23:24:32 blackpearl racoon: DEBUG2: no match
Jun 6 23:24:32 blackpearl racoon: INFO: IPsec-SA request for
46.134.75.12 queued due to no phase1 found.
Jun 6 23:24:32 blackpearl racoon: DEBUG: ===
Jun 6 23:24:32 blackpearl racoon: INFO: initiate new phase 1
negotiation: 172.24.5.10[500]<=>46.134.75.12[500]
Jun 6 23:24:32 blackpearl racoon: INFO: begin Identity Protection mode.
Jun 6 23:24:32 blackpearl racoon: DEBUG: new cookie:
Jun 6 23:24:32 blackpearl racoon: DEBUG: add payload of len 48, next
type 13
Jun 6 23:24:32 blackpearl racoon: DEBUG: add payload of len 16, next
type 13
Jun 6 23:24:32 blackpearl racoon: DEBUG: add payload of len 16, next
type 13
Jun 6 23:24:32 blackpearl racoon: DEBUG: add payload of len 16, next
type 13
Jun 6 23:24:32 blackpearl racoon: DEBUG: add payload of len 16, next
type 13
Jun 6 23:24:32 blackpearl racoon: DEBUG: add payload of len 16, next type 0
Jun 6 23:24:32 blackpearl racoon: DEBUG: 180 bytes from
172.24.5.10[500] to 46.134.75.12[500]
Jun 6 23:24:32 blackpearl racoon: DEBUG: sockname 172.24.5.10[500]
Jun 6 23:24:32 blackpearl racoon: DEBUG: send packet from 172.24.5.10[500]
Jun 6 23:24:32 blackpearl racoon: DEBUG: send packet to 46.134.75.12[500]
Jun 6 23:24:32 blackpearl racoon: DEBUG: src4 172.24.5.10[500]
Jun 6 23:24:32 blackpearl racoon: DEBUG: dst4 46.134.75.12[500]
Jun 6 23:24:32 blackpearl racoon: DEBUG: 1 times of 180 bytes message
will be sent to 46.134.75.12[500]
Jun 6 23:24:32 blackpearl racoon: DEBUG:
Jun 6 23:24:32 blackpearl racoon: DEBUG: resend phase1 packet
b3a01519dfb2c4c6:0000000000000000
Jun 6 23:24:32 blackpearl racoon: phase1(ident I msg1): 0.000825
Jun 6 23:24:33 blackpearl racoon: DEBUG: ===
Jun 6 23:24:33 blackpearl racoon: DEBUG: 120 bytes message received
from 46.134.75.12[500] to 172.24.5.10[500]
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: begin.
Jun 6 23:24:33 blackpearl racoon: DEBUG: seen nptype=1(sa)
Jun 6 23:24:33 blackpearl racoon: DEBUG: seen nptype=13(vid)
Jun 6 23:24:33 blackpearl racoon: DEBUG: seen nptype=13(vid)
Jun 6 23:24:33 blackpearl racoon: DEBUG: succeed.
Jun 6 23:24:33 blackpearl racoon: INFO: received Vendor ID: RFC 3947
Jun 6 23:24:33 blackpearl racoon: INFO: received Vendor ID: DPD
Jun 6 23:24:33 blackpearl racoon: DEBUG: remote supports DPD
Jun 6 23:24:33 blackpearl racoon: [46.134.75.12] INFO: Selected NAT-T
version: RFC 3947
Jun 6 23:24:33 blackpearl racoon: DEBUG: total SA len=48
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: begin.
Jun 6 23:24:33 blackpearl racoon: DEBUG: seen nptype=2(prop)
Jun 6 23:24:33 blackpearl racoon: DEBUG: succeed.
Jun 6 23:24:33 blackpearl racoon: DEBUG: proposal #1 len=40
Jun 6 23:24:33 blackpearl racoon: DEBUG: begin.
Jun 6 23:24:33 blackpearl racoon: DEBUG: seen nptype=3(trns)
Jun 6 23:24:33 blackpearl racoon: DEBUG: succeed.
Jun 6 23:24:33 blackpearl racoon: DEBUG: transform #1 len=32
Jun 6 23:24:33 blackpearl racoon: DEBUG: type=Life Type, flag=0x8000,
lorv=seconds
Jun 6 23:24:33 blackpearl racoon: DEBUG: type=Life Duration,
flag=0x8000, lorv=28800
Jun 6 23:24:33 blackpearl racoon: DEBUG: type=Encryption Algorithm,
flag=0x8000, lorv=3DES-CBC
Jun 6 23:24:33 blackpearl racoon: DEBUG: encryption(3des)
Jun 6 23:24:33 blackpearl racoon: DEBUG: type=Authentication Method,
flag=0x8000, lorv=pre-shared key
Jun 6 23:24:33 blackpearl racoon: DEBUG: type=Hash Algorithm,
flag=0x8000, lorv=SHA
Jun 6 23:24:33 blackpearl racoon: DEBUG: hash(sha1)
Jun 6 23:24:33 blackpearl racoon: DEBUG: type=Group Description,
flag=0x8000, lorv=1024-bit MODP group
Jun 6 23:24:33 blackpearl racoon: DEBUG: hmac(modp1024)
Jun 6 23:24:33 blackpearl racoon: DEBUG: pair 1:
Jun 6 23:24:33 blackpearl racoon: DEBUG: 0x13d4c80: next=(nil) tnext=(nil)
Jun 6 23:24:33 blackpearl racoon: DEBUG: proposal #1: 1 transform
Jun 6 23:24:33 blackpearl racoon: DEBUG: type=Life Type, flag=0x8000,
lorv=seconds
Jun 6 23:24:33 blackpearl racoon: DEBUG: type=Life Duration,
flag=0x8000, lorv=28800
Jun 6 23:24:33 blackpearl racoon: DEBUG: type=Encryption Algorithm,
flag=0x8000, lorv=3DES-CBC
Jun 6 23:24:33 blackpearl racoon: DEBUG: type=Authentication Method,
flag=0x8000, lorv=pre-shared key
Jun 6 23:24:33 blackpearl racoon: DEBUG: type=Hash Algorithm,
flag=0x8000, lorv=SHA
Jun 6 23:24:33 blackpearl racoon: DEBUG: type=Group Description,
flag=0x8000, lorv=1024-bit MODP group
Jun 6 23:24:33 blackpearl racoon: DEBUG: prop#=1, prot-id=ISAKMP,
spi-size=0, #trns=1
Jun 6 23:24:33 blackpearl racoon: DEBUG: trns#=1, trns-id=IKE
Jun 6 23:24:33 blackpearl racoon: DEBUG: lifetime = 28800
Jun 6 23:24:33 blackpearl racoon: DEBUG: lifebyte = 0
Jun 6 23:24:33 blackpearl racoon: DEBUG: enctype = 3DES-CBC
Jun 6 23:24:33 blackpearl racoon: DEBUG: encklen = 0
Jun 6 23:24:33 blackpearl racoon: DEBUG: hashtype = SHA
Jun 6 23:24:33 blackpearl racoon: DEBUG: authmethod = pre-shared key
Jun 6 23:24:33 blackpearl racoon: DEBUG: dh_group = 1024-bit MODP group
Jun 6 23:24:33 blackpearl racoon: DEBUG2: checkisakmpsa:
Jun 6 23:24:33 blackpearl racoon: DEBUG: an acceptable proposal found.
Jun 6 23:24:33 blackpearl racoon: DEBUG: hmac(modp1024)
Jun 6 23:24:33 blackpearl racoon: DEBUG: agreed on pre-shared key auth.
Jun 6 23:24:33 blackpearl racoon: DEBUG: ===
Jun 6 23:24:33 blackpearl racoon: oakley_dh_generate(MODP1024): 0.004350
Jun 6 23:24:33 blackpearl racoon: DEBUG: compute DH's private.
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: compute DH's public.
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: [46.134.75.12] INFO: Hashing
46.134.75.12[500] with algo #2
Jun 6 23:24:33 blackpearl racoon: DEBUG: hash(sha1)
Jun 6 23:24:33 blackpearl racoon: [172.24.5.10] INFO: Hashing
172.24.5.10[500] with algo #2
Jun 6 23:24:33 blackpearl racoon: DEBUG: hash(sha1)
Jun 6 23:24:33 blackpearl racoon: INFO: Adding remote and local NAT-D
payloads.
Jun 6 23:24:33 blackpearl racoon: DEBUG: add payload of len 128, next
type 10
Jun 6 23:24:33 blackpearl racoon: DEBUG: add payload of len 16, next
type 20
Jun 6 23:24:33 blackpearl racoon: DEBUG: add payload of len 20, next
type 20
Jun 6 23:24:33 blackpearl racoon: DEBUG: add payload of len 20, next type 0
Jun 6 23:24:33 blackpearl racoon: DEBUG: 228 bytes from
172.24.5.10[500] to 46.134.75.12[500]
Jun 6 23:24:33 blackpearl racoon: DEBUG: sockname 172.24.5.10[500]
Jun 6 23:24:33 blackpearl racoon: DEBUG: send packet from 172.24.5.10[500]
Jun 6 23:24:33 blackpearl racoon: DEBUG: send packet to 46.134.75.12[500]
Jun 6 23:24:33 blackpearl racoon: DEBUG: src4 172.24.5.10[500]
Jun 6 23:24:33 blackpearl racoon: DEBUG: dst4 46.134.75.12[500]
Jun 6 23:24:33 blackpearl racoon: DEBUG: 1 times of 228 bytes message
will be sent to 46.134.75.12[500]
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: resend phase1 packet
b3a01519dfb2c4c6:54d41f8b8ce78205
Jun 6 23:24:33 blackpearl racoon: phase1(ident I msg2): 0.005548
Jun 6 23:24:33 blackpearl racoon: DEBUG2: getph1: start
Jun 6 23:24:33 blackpearl racoon: DEBUG2: local: 172.24.5.10[0]
Jun 6 23:24:33 blackpearl racoon: DEBUG2: remote: 46.134.75.12[0]
Jun 6 23:24:33 blackpearl racoon: DEBUG2: p->local: 172.24.5.10[500]
Jun 6 23:24:33 blackpearl racoon: DEBUG2: p->remote: 46.134.75.12[500]
Jun 6 23:24:33 blackpearl racoon: DEBUG2: matched
Jun 6 23:24:33 blackpearl racoon: DEBUG2: CHKPH1THERE: no established
ph1 handler found
Jun 6 23:24:33 blackpearl racoon: DEBUG: ===
Jun 6 23:24:33 blackpearl racoon: DEBUG: 228 bytes message received
from 46.134.75.12[500] to 172.24.5.10[500]
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: begin.
Jun 6 23:24:33 blackpearl racoon: DEBUG: seen nptype=4(ke)
Jun 6 23:24:33 blackpearl racoon: DEBUG: seen nptype=10(nonce)
Jun 6 23:24:33 blackpearl racoon: DEBUG: seen nptype=20(nat-d)
Jun 6 23:24:33 blackpearl racoon: DEBUG: seen nptype=20(nat-d)
Jun 6 23:24:33 blackpearl racoon: DEBUG: succeed.
Jun 6 23:24:33 blackpearl racoon: [172.24.5.10] INFO: Hashing
172.24.5.10[500] with algo #2
Jun 6 23:24:33 blackpearl racoon: DEBUG: hash(sha1)
Jun 6 23:24:33 blackpearl racoon: INFO: NAT-D payload #0 doesn't match
Jun 6 23:24:33 blackpearl racoon: [46.134.75.12] INFO: Hashing
46.134.75.12[500] with algo #2
Jun 6 23:24:33 blackpearl racoon: DEBUG: hash(sha1)
Jun 6 23:24:33 blackpearl racoon: INFO: NAT-D payload #1 verified
Jun 6 23:24:33 blackpearl racoon: INFO: NAT detected: ME
Jun 6 23:24:33 blackpearl racoon: INFO: KA list add:
172.24.5.10[4500]->46.134.75.12[4500]
Jun 6 23:24:33 blackpearl racoon: DEBUG: ===
Jun 6 23:24:33 blackpearl racoon: oakley_dh_compute(MODP1024): 0.004252
Jun 6 23:24:33 blackpearl racoon: DEBUG: compute DH's shared.
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: the psk found.
Jun 6 23:24:33 blackpearl racoon: DEBUG2: psk:
Jun 6 23:24:33 blackpearl racoon: DEBUG2:
Jun 6 23:24:33 blackpearl racoon: DEBUG: nonce 1:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: nonce 2:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: hmac(hmac_sha1)
Jun 6 23:24:33 blackpearl racoon: alg_oakley_hmacdef_one(hmac_sha1
size=32): 0.000022
Jun 6 23:24:33 blackpearl racoon: DEBUG: SKEYID computed:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: hmac(hmac_sha1)
Jun 6 23:24:33 blackpearl racoon: alg_oakley_hmacdef_one(hmac_sha1
size=145): 0.000012
Jun 6 23:24:33 blackpearl racoon: DEBUG: SKEYID_d computed:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: hmac(hmac_sha1)
Jun 6 23:24:33 blackpearl racoon: alg_oakley_hmacdef_one(hmac_sha1
size=165): 0.000010
Jun 6 23:24:33 blackpearl racoon: DEBUG: SKEYID_a computed:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: hmac(hmac_sha1)
Jun 6 23:24:33 blackpearl racoon: alg_oakley_hmacdef_one(hmac_sha1
size=165): 0.000012
Jun 6 23:24:33 blackpearl racoon: DEBUG: SKEYID_e computed:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: encryption(3des)
Jun 6 23:24:33 blackpearl racoon: DEBUG: hash(sha1)
Jun 6 23:24:33 blackpearl racoon: DEBUG: len(SKEYID_e) < len(Ka) (20 <
24), generating long key (Ka = K1 | K2 | ...)
Jun 6 23:24:33 blackpearl racoon: DEBUG: hmac(hmac_sha1)
Jun 6 23:24:33 blackpearl racoon: alg_oakley_hmacdef_one(hmac_sha1
size=1): 0.000010
Jun 6 23:24:33 blackpearl racoon: DEBUG: compute intermediate
encryption key K1
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: hmac(hmac_sha1)
Jun 6 23:24:33 blackpearl racoon: alg_oakley_hmacdef_one(hmac_sha1
size=20): 0.000009
Jun 6 23:24:33 blackpearl racoon: DEBUG: compute intermediate
encryption key K2
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: final encryption key computed:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: hash(sha1)
Jun 6 23:24:33 blackpearl racoon: DEBUG: encryption(3des)
Jun 6 23:24:33 blackpearl racoon: DEBUG: IV computed:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: use ID type of IPv4_address
Jun 6 23:24:33 blackpearl racoon: DEBUG: HASH with:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: hmac(hmac_sha1)
Jun 6 23:24:33 blackpearl racoon: alg_oakley_hmacdef_one(hmac_sha1
size=328): 0.000016
Jun 6 23:24:33 blackpearl racoon: DEBUG: HASH (init) computed:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: add payload of len 8, next type 8
Jun 6 23:24:33 blackpearl racoon: DEBUG: add payload of len 20, next type 0
Jun 6 23:24:33 blackpearl racoon: DEBUG: begin encryption.
Jun 6 23:24:33 blackpearl racoon: DEBUG: encryption(3des)
Jun 6 23:24:33 blackpearl racoon: DEBUG: pad length = 4
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: encryption(3des)
Jun 6 23:24:33 blackpearl racoon: alg_oakley_encdef_encrypt(3des
klen=192 size=40): 0.000063
Jun 6 23:24:33 blackpearl racoon: DEBUG: with key:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: encrypted payload by IV:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: save IV for next:
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: encrypted.
Jun 6 23:24:33 blackpearl racoon: DEBUG: Adding NON-ESP marker
Jun 6 23:24:33 blackpearl racoon: DEBUG: 72 bytes from
172.24.5.10[4500] to 46.134.75.12[4500]
Jun 6 23:24:33 blackpearl racoon: DEBUG: sockname 172.24.5.10[4500]
Jun 6 23:24:33 blackpearl racoon: DEBUG: send packet from 172.24.5.10[4500]
Jun 6 23:24:33 blackpearl racoon: DEBUG: send packet to 46.134.75.12[4500]
Jun 6 23:24:33 blackpearl racoon: DEBUG: src4 172.24.5.10[4500]
Jun 6 23:24:33 blackpearl racoon: DEBUG: dst4 46.134.75.12[4500]
Jun 6 23:24:33 blackpearl racoon: DEBUG: 1 times of 72 bytes message
will be sent to 46.134.75.12[4500]
Jun 6 23:24:33 blackpearl racoon: DEBUG:
Jun 6 23:24:33 blackpearl racoon: DEBUG: resend phase1 packet
b3a01519dfb2c4c6:54d41f8b8ce78205
Jun 6 23:24:33 blackpearl racoon: phase1(ident I msg3): 0.006486
Jun 6 23:24:34 blackpearl racoon: DEBUG2: getph1: start
Jun 6 23:24:34 blackpearl racoon: DEBUG2: local: 172.24.5.10[0]
Jun 6 23:24:34 blackpearl racoon: DEBUG2: remote: 46.134.75.12[0]
Jun 6 23:24:34 blackpearl racoon: DEBUG2: p->local: 172.24.5.10[4500]
Jun 6 23:24:34 blackpearl racoon: DEBUG2: p->remote: 46.134.75.12[4500]
Jun 6 23:24:34 blackpearl racoon: DEBUG2: matched
Jun 6 23:24:34 blackpearl racoon: DEBUG2: CHKPH1THERE: no established
ph1 handler found
Jun 6 23:24:35 blackpearl racoon: DEBUG2: getph1: start
Jun 6 23:24:35 blackpearl racoon: DEBUG2: local: 172.24.5.10[0]
Jun 6 23:24:35 blackpearl racoon: DEBUG2: remote: 46.134.75.12[0]
Jun 6 23:24:35 blackpearl racoon: DEBUG2: p->local: 172.24.5.10[4500]
Jun 6 23:24:35 blackpearl racoon: DEBUG2: p->remote: 46.134.75.12[4500]
Jun 6 23:24:35 blackpearl racoon: DEBUG2: matched
Jun 6 23:24:35 blackpearl racoon: DEBUG2: CHKPH1THERE: no established
ph1 handler found
Jun 6 23:24:36 blackpearl racoon: DEBUG2: getph1: start
Jun 6 23:24:36 blackpearl racoon: DEBUG2: local: 172.24.5.10[0]
Jun 6 23:24:36 blackpearl racoon: DEBUG2: remote: 46.134.75.12[0]
Jun 6 23:24:36 blackpearl racoon: DEBUG2: p->local: 172.24.5.10[4500]
Jun 6 23:24:36 blackpearl racoon: DEBUG2: p->remote: 46.134.75.12[4500]
Jun 6 23:24:36 blackpearl racoon: DEBUG2: matched
Jun 6 23:24:36 blackpearl racoon: DEBUG2: CHKPH1THERE: no established
ph1 handler found
Jun 6 23:24:37 blackpearl racoon: DEBUG2: getph1: start
Jun 6 23:24:37 blackpearl racoon: DEBUG2: local: 172.24.5.10[0]
Jun 6 23:24:37 blackpearl racoon: DEBUG2: remote: 46.134.75.12[0]
Jun 6 23:24:37 blackpearl racoon: DEBUG2: p->local: 172.24.5.10[4500]
Jun 6 23:24:37 blackpearl racoon: DEBUG2: p->remote: 46.134.75.12[4500]
Jun 6 23:24:37 blackpearl racoon: DEBUG2: matched
Jun 6 23:24:37 blackpearl racoon: DEBUG2: CHKPH1THERE: no established
ph1 handler found
Jun 6 23:24:38 blackpearl racoon: DEBUG2: getph1: start
Jun 6 23:24:38 blackpearl racoon: DEBUG2: local: 172.24.5.10[0]
Jun 6 23:24:38 blackpearl racoon: DEBUG2: remote: 46.134.75.12[0]
Jun 6 23:24:38 blackpearl racoon: DEBUG2: p->local: 172.24.5.10[4500]
Jun 6 23:24:38 blackpearl racoon: DEBUG2: p->remote: 46.134.75.12[4500]
Jun 6 23:24:38 blackpearl racoon: DEBUG2: matched
Jun 6 23:24:38 blackpearl racoon: DEBUG2: CHKPH1THERE: no established
ph1 handler found
Jun 6 23:24:39 blackpearl racoon: DEBUG2: getph1: start
Jun 6 23:24:39 blackpearl racoon: DEBUG2: local: 172.24.5.10[0]
Jun 6 23:24:39 blackpearl racoon: DEBUG2: remote: 46.134.75.12[0]
Jun 6 23:24:39 blackpearl racoon: DEBUG2: p->local: 172.24.5.10[4500]
Jun 6 23:24:39 blackpearl racoon: DEBUG2: p->remote: 46.134.75.12[4500]
Jun 6 23:24:39 blackpearl racoon: DEBUG2: matched
Jun 6 23:24:39 blackpearl racoon: DEBUG2: CHKPH1THERE: no established
ph1 handler found
Jun 6 23:24:40 blackpearl racoon: DEBUG2: getph1: start
Jun 6 23:24:40 blackpearl racoon: DEBUG2: local: 172.24.5.10[0]
Jun 6 23:24:40 blackpearl racoon: DEBUG2: remote: 46.134.75.12[0]
Jun 6 23:24:40 blackpearl racoon: DEBUG2: p->local: 172.24.5.10[4500]
Jun 6 23:24:40 blackpearl racoon: DEBUG2: p->remote: 46.134.75.12[4500]
Jun 6 23:24:40 blackpearl racoon: DEBUG2: matched
Jun 6 23:24:40 blackpearl racoon: DEBUG2: CHKPH1THERE: no established
ph1 handler found
Jun 6 23:24:41 blackpearl racoon: DEBUG: KA:
172.24.5.10[4500]->46.134.75.12[4500]
Jun 6 23:24:41 blackpearl racoon: DEBUG: sockname 172.24.5.10[4500]
Jun 6 23:24:41 blackpearl racoon: DEBUG: send packet from 172.24.5.10[4500]
Jun 6 23:24:41 blackpearl racoon: DEBUG: send packet to 46.134.75.12[4500]
Jun 6 23:24:41 blackpearl racoon: DEBUG: src4 172.24.5.10[4500]
Jun 6 23:24:41 blackpearl racoon: DEBUG: dst4 46.134.75.12[4500]
Jun 6 23:24:41 blackpearl racoon: DEBUG: 1 times of 1 bytes message
will be sent to 46.134.75.12[4500]
Jun 6 23:24:41 blackpearl racoon: DEBUG:
Jun 6 23:24:41 blackpearl racoon: DEBUG2: getph1: start
Jun 6 23:24:41 blackpearl racoon: DEBUG2: local: 172.24.5.10[0]
Jun 6 23:24:41 blackpearl racoon: DEBUG2: remote: 46.134.75.12[0]
Jun 6 23:24:41 blackpearl racoon: DEBUG2: p->local: 172.24.5.10[4500]
Jun 6 23:24:41 blackpearl racoon: DEBUG2: p->remote: 46.134.75.12[4500]
Jun 6 23:24:41 blackpearl racoon: DEBUG2: matched
Jun 6 23:24:41 blackpearl racoon: DEBUG2: CHKPH1THERE: no established
ph1 handler found
Jun 6 23:24:42 blackpearl racoon: DEBUG2: getph1: start
Jun 6 23:24:42 blackpearl racoon: DEBUG2: local: 172.24.5.10[0]
Jun 6 23:24:42 blackpearl racoon: DEBUG2: remote: 46.134.75.12[0]
Jun 6 23:24:42 blackpearl racoon: DEBUG2: p->local: 172.24.5.10[4500]
Jun 6 23:24:42 blackpearl racoon: DEBUG2: p->remote: 46.134.75.12[4500]
Jun 6 23:24:42 blackpearl racoon: DEBUG2: matched
Jun 6 23:24:42 blackpearl racoon: DEBUG2: CHKPH1THERE: no established
ph1 handler found
Jun 6 23:24:43 blackpearl racoon: DEBUG2: getph1: start
Jun 6 23:24:43 blackpearl racoon: DEBUG2: local: 172.24.5.10[0]
Jun 6 23:24:43 blackpearl racoon: DEBUG2: remote: 46.134.75.12[0]
Jun 6 23:24:43 blackpearl racoon: DEBUG2: p->local: 172.24.5.10[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG2: p->remote: 46.134.75.12[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG2: matched
Jun 6 23:24:43 blackpearl racoon: DEBUG2: CHKPH1THERE: no established
ph1 handler found
Jun 6 23:24:43 blackpearl racoon: DEBUG: ===
Jun 6 23:24:43 blackpearl racoon: DEBUG: 228 bytes message received
from 46.134.75.12[4500] to 172.24.5.10[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG:
Jun 6 23:24:43 blackpearl racoon: DEBUG: sockname 172.24.5.10[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG: send packet from 172.24.5.10[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG: send packet to 46.134.75.12[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG: src4 172.24.5.10[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG: dst4 46.134.75.12[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG: 1 times of 72 bytes message
will be sent to 46.134.75.12[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG:
Jun 6 23:24:43 blackpearl racoon: NOTIFY: the packet is retransmitted
by 46.134.75.12[4500] (1).
Jun 6 23:24:43 blackpearl racoon: DEBUG: 72 bytes from
172.24.5.10[4500] to 46.134.75.12[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG: sockname 172.24.5.10[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG: send packet from 172.24.5.10[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG: send packet to 46.134.75.12[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG: src4 172.24.5.10[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG: dst4 46.134.75.12[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG: 1 times of 72 bytes message
will be sent to 46.134.75.12[4500]
Jun 6 23:24:43 blackpearl racoon: DEBUG:
Jun 6 23:24:43 blackpearl racoon: DEBUG: resend phase1 packet
b3a01519dfb2c4c6:54d41f8b8ce78205
This then repeats over and over again until eventually it dies with:
Jun 6 23:25:33 blackpearl racoon: [46.134.75.12] ERROR: phase2
negotiation failed due to time up waiting for phase1. ESP
46.134.75.12[0]->172.24.5.10[0]
Jun 6 23:25:33 blackpearl racoon: INFO: delete phase 2 handler.
Any and all help much appreciated!
Kind Regards,
Jaco
On 06/06/11 22:12, Jaco Kroon wrote:
> Hi All,
>
> I've spotted some behavior which seems to be wrong, so I'm going to try
> and explain what I am seeing, hopefully someone can point out what's
> going wrong and where (and hopefully provide me with either a workaround
> or a fix).
>
> Firstly, I'm using two different clients, one Windows XP box (L2TP/IPSec
> client) and one Gentoo Linux client (racoon on the client). My server
> is also Gentoo Linux, both Linux's has ipsec-tools , and the server has
> the following patch additionally installed (looking for road-warrior
> like functionality, so the patch is basically to enable the server to
> re-use the same pre-shared key for the whole internet - yea, I know I
> should be setting up an PKI but the client is looking for a global
> pre-shared key, we've advised the risks, but a client is always right,
> even when they're wrong).
>
> --- ipsec-tools-0.7.3.o/src/racoon/oakley.c 2009-08-13
> 11:18:45.000000000 +0200
> +++ ipsec-tools-0.7.3/src/racoon/oakley.c 2011-06-06
> 09:36:11.000000000 +0200
> @@ -2498,8 +2498,21 @@
> plog(LLV_ERROR, LOCATION, iph1->remote,
> "couldn't find the pskey for %s.\n",
> saddrwop2str(iph1->remote));
> + }
> + }
> + if (iph1->authstr == NULL) {
> + /*
> + * If we could not locate a psk above try and locate
> + * the default psk, ie, "*".
> + */
> + iph1->authstr = privsep_getpsk("*", 1);
> + if (iph1->authstr == NULL) {
> + plog(LLV_ERROR, LOCATION, iph1->remote,
> + "couldn't find the the default
> pskey either.\n");
> goto end;
> }
> + plog(LLV_NOTIFY, LOCATION, iph1->remote,
> + "Using default PSK.\n");
> }
> plog(LLV_DEBUG, LOCATION, NULL, "the psk found.\n");
> /* should be secret PSK */
>
> This just allows me to put a "* psk" line in psk.txt. This part works.
>
> Pertinent config options on the server (please ask if I miss something):
>
> path pre_shared_key "/etc/racoon/psk.txt";
>
> remote anonymous {
> exchange_mode main;
> doi ipsec_doi;
> situation identity_only;
>
> nat_traversal on;
> initial_contact off;
> passive on;
> proposal_check obey;
>
> ... here goes the proposal (this passes) ...
> }
>
> In my first test case Ive got:
>
> client -> NAT GW -> inet <- Server
>
> On the NAT GW running tcpdump shows this:
>
> 18:29:02.939323 IP 172.24.5.10.500 > 46.134.75.12.500: [|isakmp]
> 18:29:02.939363 IP 46.241.240.125.500 > 46.134.75.12.500: [|isakmp]
> 18:29:03.385950 IP 46.134.75.12.500 > 46.241.240.125.500: [|isakmp]
> 18:29:03.385966 IP 46.134.75.12.500 > 172.24.5.10.500: [|isakmp]
> 18:29:04.609208 IP 172.24.5.10.500 > 46.134.75.12.500: [|isakmp]
> 18:29:04.609222 IP 46.241.240.125.500 > 46.134.75.12.500: [|isakmp]
> 18:29:05.060864 IP 46.134.75.12.500 > 46.241.240.125.500: [|isakmp]
> 18:29:05.060903 IP 46.134.75.12.500 > 172.24.5.10.500: [|isakmp]
> 18:29:06.169912 IP 172.24.5.10.4500 > 46.134.75.12.4500: NONESP-encap:
> [|isakmp]
> 18:29:06.169937 IP 46.241.240.125.4500 > 46.134.75.12.4500:
> NONESP-encap: [|isakmp]
> 18:29:14.635666 IP 46.134.75.12.500 > 46.241.240.125.4500: [|isakmp]
> 18:29:16.319506 IP 172.24.5.10.4500 > 46.134.75.12.4500: NONESP-encap:
> [|isakmp]
> 18:29:16.319522 IP 46.241.240.125.4500 > 46.134.75.12.4500:
> NONESP-encap: [|isakmp]
> 18:29:18.253730 IP 172.24.5.10.4500 > 46.134.75.12.4500:
> isakmp-nat-keep-alive
> 18:29:18.253743 IP 46.241.240.125.4500 > 46.134.75.12.4500:
> isakmp-nat-keep-alive
> 18:29:22.764709 IP 46.134.75.12.500 > 46.241.240.125.4500: [|isakmp]
> 18:29:24.771837 IP 46.134.75.12.500 > 46.241.240.125.4500: [|isakmp]
> 18:29:25.142336 IP 172.24.5.10.4500 > 46.134.75.12.4500: NONESP-encap:
> [|isakmp]
>
> 172.24.5.10 is the client.
> 46.134.75.12 is the server.
> 46.241.240.125 is the external IP of the NAT GW.
>
> As can be seen the NAT seems to work absolutely fine (all packets shows
> twice - tcpdump -i any, one packet with the external GW IP and the other
> with the internal IP), except the second and third last packets, which
> only shows on the external side.
>
> Looking at the above my assumption is that port 500 -> 500 opens a
> mapping in the connection tracking table on the GW, thus the traffic
> goes just fine in both directions. Then the 4500 -> 4500 packet does
> exactly the same and this is where the problem then comes in, the server
> still responds FROM port 500 to port 4500, seeing that the GW has no
> mapping for this incoming pair it has no choice but to drop the packet,
> preventing the security negotiation from completing.
>
> What I did to confirm that this was indeed the case is I installed the
> exact same server config a box on my LAN, and set nat_traversal to force.
>
> This resulted in a similar sequence of packets, with the exception that
> since there is no NAT the traffic from port 500 -> 4500 reached it's
> destination, and resulted in the traffic to complete correctly.
>
> I'm not all that familiar with the code so don't know where to go
> looking for this problem. Or even whether 0.8.0 has perhaps fixed this
> already (didn't see anything obvious in the ChangeLog). Kernels on my
> server and client is 2.6.37.2 in both cases. My setup for setkey on the
> server:
>
> spdadd 0.0.0.0/0[1701] 0.0.0.0/0 udp -P out ipsec
> esp/transport//require;
>
> spdadd 0.0.0.0/0 0.0.0.0/0[1701] udp -P in ipsec
> esp/transport//require;
>
> For the client it's an exact reverse with the in and out keywords just
> swapped around.
>
> The above behavior was observed and confirmed using Linux as the NAT GW,
> but the client has reported the same error occuring on Windows behind at
> least two other unknown NAT gateways.
>
> As it stands the only "fix" I can see is a really ugly iptables based
> hack to rewrite the source port to port 4500 on all packets outbound to
> socket pairs that has originally been inbound to port 4500. And
> honestly, that really feels like a massive kludge and I would not even
> know where to sta...
[truncated message content] |
|
From: Jaco K. <ja...@ul...> - 2011-06-06 20:12:26
|
Hi All,
I've spotted some behavior which seems to be wrong, so I'm going to try
and explain what I am seeing, hopefully someone can point out what's
going wrong and where (and hopefully provide me with either a workaround
or a fix).
Firstly, I'm using two different clients, one Windows XP box (L2TP/IPSec
client) and one Gentoo Linux client (racoon on the client). My server
is also Gentoo Linux, both Linux's has ipsec-tools , and the server has
the following patch additionally installed (looking for road-warrior
like functionality, so the patch is basically to enable the server to
re-use the same pre-shared key for the whole internet - yea, I know I
should be setting up an PKI but the client is looking for a global
pre-shared key, we've advised the risks, but a client is always right,
even when they're wrong).
--- ipsec-tools-0.7.3.o/src/racoon/oakley.c 2009-08-13
11:18:45.000000000 +0200
+++ ipsec-tools-0.7.3/src/racoon/oakley.c 2011-06-06
09:36:11.000000000 +0200
@@ -2498,8 +2498,21 @@
plog(LLV_ERROR, LOCATION, iph1->remote,
"couldn't find the pskey for %s.\n",
saddrwop2str(iph1->remote));
+ }
+ }
+ if (iph1->authstr == NULL) {
+ /*
+ * If we could not locate a psk above try and locate
+ * the default psk, ie, "*".
+ */
+ iph1->authstr = privsep_getpsk("*", 1);
+ if (iph1->authstr == NULL) {
+ plog(LLV_ERROR, LOCATION, iph1->remote,
+ "couldn't find the the default
pskey either.\n");
goto end;
}
+ plog(LLV_NOTIFY, LOCATION, iph1->remote,
+ "Using default PSK.\n");
}
plog(LLV_DEBUG, LOCATION, NULL, "the psk found.\n");
/* should be secret PSK */
This just allows me to put a "* psk" line in psk.txt. This part works.
Pertinent config options on the server (please ask if I miss something):
path pre_shared_key "/etc/racoon/psk.txt";
remote anonymous {
exchange_mode main;
doi ipsec_doi;
situation identity_only;
nat_traversal on;
initial_contact off;
passive on;
proposal_check obey;
... here goes the proposal (this passes) ...
}
In my first test case Ive got:
client -> NAT GW -> inet <- Server
On the NAT GW running tcpdump shows this:
18:29:02.939323 IP 172.24.5.10.500 > 46.134.75.12.500: [|isakmp]
18:29:02.939363 IP 46.241.240.125.500 > 46.134.75.12.500: [|isakmp]
18:29:03.385950 IP 46.134.75.12.500 > 46.241.240.125.500: [|isakmp]
18:29:03.385966 IP 46.134.75.12.500 > 172.24.5.10.500: [|isakmp]
18:29:04.609208 IP 172.24.5.10.500 > 46.134.75.12.500: [|isakmp]
18:29:04.609222 IP 46.241.240.125.500 > 46.134.75.12.500: [|isakmp]
18:29:05.060864 IP 46.134.75.12.500 > 46.241.240.125.500: [|isakmp]
18:29:05.060903 IP 46.134.75.12.500 > 172.24.5.10.500: [|isakmp]
18:29:06.169912 IP 172.24.5.10.4500 > 46.134.75.12.4500: NONESP-encap:
[|isakmp]
18:29:06.169937 IP 46.241.240.125.4500 > 46.134.75.12.4500:
NONESP-encap: [|isakmp]
18:29:14.635666 IP 46.134.75.12.500 > 46.241.240.125.4500: [|isakmp]
18:29:16.319506 IP 172.24.5.10.4500 > 46.134.75.12.4500: NONESP-encap:
[|isakmp]
18:29:16.319522 IP 46.241.240.125.4500 > 46.134.75.12.4500:
NONESP-encap: [|isakmp]
18:29:18.253730 IP 172.24.5.10.4500 > 46.134.75.12.4500:
isakmp-nat-keep-alive
18:29:18.253743 IP 46.241.240.125.4500 > 46.134.75.12.4500:
isakmp-nat-keep-alive
18:29:22.764709 IP 46.134.75.12.500 > 46.241.240.125.4500: [|isakmp]
18:29:24.771837 IP 46.134.75.12.500 > 46.241.240.125.4500: [|isakmp]
18:29:25.142336 IP 172.24.5.10.4500 > 46.134.75.12.4500: NONESP-encap:
[|isakmp]
172.24.5.10 is the client.
46.134.75.12 is the server.
46.241.240.125 is the external IP of the NAT GW.
As can be seen the NAT seems to work absolutely fine (all packets shows
twice - tcpdump -i any, one packet with the external GW IP and the other
with the internal IP), except the second and third last packets, which
only shows on the external side.
Looking at the above my assumption is that port 500 -> 500 opens a
mapping in the connection tracking table on the GW, thus the traffic
goes just fine in both directions. Then the 4500 -> 4500 packet does
exactly the same and this is where the problem then comes in, the server
still responds FROM port 500 to port 4500, seeing that the GW has no
mapping for this incoming pair it has no choice but to drop the packet,
preventing the security negotiation from completing.
What I did to confirm that this was indeed the case is I installed the
exact same server config a box on my LAN, and set nat_traversal to force.
This resulted in a similar sequence of packets, with the exception that
since there is no NAT the traffic from port 500 -> 4500 reached it's
destination, and resulted in the traffic to complete correctly.
I'm not all that familiar with the code so don't know where to go
looking for this problem. Or even whether 0.8.0 has perhaps fixed this
already (didn't see anything obvious in the ChangeLog). Kernels on my
server and client is 2.6.37.2 in both cases. My setup for setkey on the
server:
spdadd 0.0.0.0/0[1701] 0.0.0.0/0 udp -P out ipsec
esp/transport//require;
spdadd 0.0.0.0/0 0.0.0.0/0[1701] udp -P in ipsec
esp/transport//require;
For the client it's an exact reverse with the in and out keywords just
swapped around.
The above behavior was observed and confirmed using Linux as the NAT GW,
but the client has reported the same error occuring on Windows behind at
least two other unknown NAT gateways.
As it stands the only "fix" I can see is a really ugly iptables based
hack to rewrite the source port to port 4500 on all packets outbound to
socket pairs that has originally been inbound to port 4500. And
honestly, that really feels like a massive kludge and I would not even
know where to start with pulling off a hack like that anyway.
Kind Regards,
Jaco
|
|
From: Jaco K. <ja...@ul...> - 2011-06-06 17:59:24
|
Hi All,
I've spotted some behavior which seems to be wrong, so I'm going to try
and explain what I am seeing, hopefully someone can point out what's
going wrong and where (and hopefully provide me with either a workaround
or a fix).
Firstly, I'm using two different clients, one Windows XP box (L2TP/IPSec
client) and one Gentoo Linux client (racoon on the client). My server
is also Gentoo Linux, both Linux's has ipsec-tools , and the server has
the following patch additionally installed (looking for road-warrior
like functionality, so the patch is basically to enable the server to
re-use the same pre-shared key for the whole internet - yea, I know I
should be setting up an PKI but the client is looking for a global
pre-shared key, we've advised the risks, but a client is always right,
even when they're wrong).
--- ipsec-tools-0.7.3.o/src/racoon/oakley.c 2009-08-13
11:18:45.000000000 +0200
+++ ipsec-tools-0.7.3/src/racoon/oakley.c 2011-06-06
09:36:11.000000000 +0200
@@ -2498,8 +2498,21 @@
plog(LLV_ERROR, LOCATION, iph1->remote,
"couldn't find the pskey for %s.\n",
saddrwop2str(iph1->remote));
+ }
+ }
+ if (iph1->authstr == NULL) {
+ /*
+ * If we could not locate a psk above try and locate
+ * the default psk, ie, "*".
+ */
+ iph1->authstr = privsep_getpsk("*", 1);
+ if (iph1->authstr == NULL) {
+ plog(LLV_ERROR, LOCATION, iph1->remote,
+ "couldn't find the the default
pskey either.\n");
goto end;
}
+ plog(LLV_NOTIFY, LOCATION, iph1->remote,
+ "Using default PSK.\n");
}
plog(LLV_DEBUG, LOCATION, NULL, "the psk found.\n");
/* should be secret PSK */
This just allows me to put a "* psk" line in psk.txt. This part works.
Pertinent config options on the server (please ask if I miss something):
path pre_shared_key "/etc/racoon/psk.txt";
remote anonymous {
exchange_mode main;
doi ipsec_doi;
situation identity_only;
nat_traversal on;
initial_contact off;
passive on;
proposal_check obey;
... here goes the proposal (this passes) ...
}
In my first test case Ive got:
client -> NAT GW -> inet <- Server
On the NAT GW running tcpdump shows this:
18:29:02.939323 IP 172.24.5.10.500 > 46.134.75.12.500: [|isakmp]
18:29:02.939363 IP 46.241.240.125.500 > 46.134.75.12.500: [|isakmp]
18:29:03.385950 IP 46.134.75.12.500 > 46.241.240.125.500: [|isakmp]
18:29:03.385966 IP 46.134.75.12.500 > 172.24.5.10.500: [|isakmp]
18:29:04.609208 IP 172.24.5.10.500 > 46.134.75.12.500: [|isakmp]
18:29:04.609222 IP 46.241.240.125.500 > 46.134.75.12.500: [|isakmp]
18:29:05.060864 IP 46.134.75.12.500 > 46.241.240.125.500: [|isakmp]
18:29:05.060903 IP 46.134.75.12.500 > 172.24.5.10.500: [|isakmp]
18:29:06.169912 IP 172.24.5.10.4500 > 46.134.75.12.4500: NONESP-encap:
[|isakmp]
18:29:06.169937 IP 46.241.240.125.4500 > 46.134.75.12.4500:
NONESP-encap: [|isakmp]
18:29:14.635666 IP 46.134.75.12.500 > 46.241.240.125.4500: [|isakmp]
18:29:16.319506 IP 172.24.5.10.4500 > 46.134.75.12.4500: NONESP-encap:
[|isakmp]
18:29:16.319522 IP 46.241.240.125.4500 > 46.134.75.12.4500:
NONESP-encap: [|isakmp]
18:29:18.253730 IP 172.24.5.10.4500 > 46.134.75.12.4500:
isakmp-nat-keep-alive
18:29:18.253743 IP 46.241.240.125.4500 > 46.134.75.12.4500:
isakmp-nat-keep-alive
18:29:22.764709 IP 46.134.75.12.500 > 46.241.240.125.4500: [|isakmp]
18:29:24.771837 IP 46.134.75.12.500 > 46.241.240.125.4500: [|isakmp]
18:29:25.142336 IP 172.24.5.10.4500 > 46.134.75.12.4500: NONESP-encap:
[|isakmp]
172.24.5.10 is the client.
46.134.75.12 is the server.
46.241.240.125 is the external IP of the NAT GW.
As can be seen the NAT seems to work absolutely fine (all packets shows
twice - tcpdump -i any, one packet with the external GW IP and the other
with the internal IP), except the second and third last packets, which
only shows on the external side.
Looking at the above my assumption is that port 500 -> 500 opens a
mapping in the connection tracking table on the GW, thus the traffic
goes just fine in both directions. Then the 4500 -> 4500 packet does
exactly the same and this is where the problem then comes in, the server
still responds FROM port 500 to port 4500, seeing that the GW has no
mapping for this incoming pair it has no choice but to drop the packet,
preventing the security negotiation from completing.
What I did to confirm that this was indeed the case is I installed the
exact same server config a box on my LAN, and set nat_traversal to force.
This resulted in a similar sequence of packets, with the exception that
since there is no NAT the traffic from port 500 -> 4500 reached it's
destination, and resulted in the traffic to complete correctly.
I'm not all that familiar with the code so don't know where to go
looking for this problem. Or even whether 0.8.0 has perhaps fixed this
already. Kernels on my server and client is 2.6.37.2 in both cases. My
setup for setkey on the server:
spdadd 0.0.0.0/0[1701] 0.0.0.0/0 udp -P out ipsec
esp/transport//require;
spdadd 0.0.0.0/0 0.0.0.0/0[1701] udp -P in ipsec
esp/transport//require;
For the client it's an exact reverse with the in and out keywords just
swapped around.
The above behavior was observed and confirmed using Linux as the NAT GW,
but the client has reported the same error occuring on Windows behind at
least two other unknown NAT gateways.
As it stands the only "fix" I can see is a really ugly iptables based
hack to rewrite the source port to port 4500 on all packets outbound to
socket pairs that has originally been inbound to port 4500. And
honestly, that really feels like a massive kludge and I would not even
know where to start with pulling off a hack like that anyway.
Kind Regards,
Jaco
|
