Date: Wed, 16 Apr 2003 15:05:20 -0400 From: Damian Gerow <damian@sentex.net> To: Barry Irwin <bvi@itouchlabs.com> Cc: net@freebsd.org Subject: [LONG] Re: IPSec tunnel setup problems Message-ID: <20030416190520.GJ648@sentex.net> In-Reply-To: <00d001c303dc$191c2830$0b01a8c0@Beastie> References: <20030415223713.GB648@sentex.net> <00d001c303dc$191c2830$0b01a8c0@Beastie>
next in thread | previous in thread | raw e-mail | index | archive | help
Thus spake Barry Irwin (bvi@itouchlabs.com) [16/04/03 01:52]:
> Can I suggest you try using TCPdump to see whats going on as well.
I've done it. I see continual re-tries for Phase I, nothing for Phase II.
Here's what I see:
tcpdump:
14:31:33.613674 pyroxene.sentex.ca.isakmp > asylum.afflictions.org.isakmp: isakmp: phase 1 I agg: [|sa]
14:31:53.428132 pyroxene.sentex.ca.isakmp > asylum.afflictions.org.isakmp: isakmp: phase 1 I agg: [|sa]
And so on.
initiating:
<snip>
2003-04-16 14:43:09: DEBUG: isakmp_agg.c:162:agg_i1sen): authmethod is pre-shared key
2003-04-16 14:43:09: DEBUG: isakmp.c:2113:set_isakmp_payloa): add payload of len 52, next type 4
2003-04-16 14:43:09: DEBUG: isakmp.c:2113:set_isakmp_payloa): add payload of len 192, next type 10
2003-04-16 14:43:09: DEBUG: isakmp.c:2113:set_isakmp_payloa): add payload of len 16, next type 5
2003-04-16 14:43:09: DEBUG: isakmp.c:2113:set_isakmp_payloa): add payload of len 8, next type 0
2003-04-16 14:43:09: DEBUG: isakmp.c:2248:isakmp_printpacke): begin.
43:09.033625 64.7.134.90:500 -> 199.212.134.18:500: isakmp 1.0 msgid 00000000: phase 1 I agg:
sa: doi=ipsec situation=identity
p: #1 protoid=isakmp transform=1
t: #1 id=iketype=lifetype value=sectype=lifeduration value=0e10type=enc value=blowfishtype=keylen value=0080type=auth value=presharedtype=hash value=sha1type=group desc value=0005))))
ke: key len=192)
nonce: n len=16)
id: idtype=IPv4 protoid=udp port=500 len=4 64.7.134.90)
2003-04-16 14:43:09: DEBUG: sockmisc.c:421:sendfromt): sockname 64.7.134.90[500]
2003-04-16 14:43:09: DEBUG: sockmisc.c:423:sendfromt): send packet from 64.7.134.90[500]
2003-04-16 14:43:09: DEBUG: sockmisc.c:425:sendfromt): send packet to 199.212.134.18[500]
2003-04-16 14:43:09: DEBUG: sockmisc.c:570:sendfromt): 1 times of 312 bytes message will be sent to 64.7.134.90[500]
2003-04-16 14:43:09: DEBUG: plog.c:193:plogdum):
915b0922 44d7fb35 00000000 00000000 01100400 00000000 00000138 04000038
00000001 00000001 0000002c 01010001 00000024 01010000 800b0001 800c0e10
80010003 800e0080 80030001 80020002 80040005 0a0000c4 8c687103 3ceab145
1f1fda2e 8210ae56 12ed3492 d3bf3a20 931c12d2 96631473 71ccebb7 b0d4e3a8
674dfba6 ee7d6085 9f83a55a 85c9dd16 575485ec 06e29bd9 4c347b98 f33940c7
e5ff7a41 10a83a78 ed576db8 bc325492 301eacdc ed00ccba 2a3e1165 ed772d57
760e8201 3467c440 28352967 13e030b9 a3404356 6339f699 955c074c 2239ce9b
ef519853 62edb648 4be54c09 f54d7d49 65bf7592 806a8554 47362099 461fbc39
9efbfedc bdb94b53 8fb1d9a9 525acc05 0aea8a6c e53408b9 05000014 953e119c
29e492ca fee18307 e7c6ab9c 0000000c 011101f4 4007865a
2003-04-16 14:43:09: DEBUG: isakmp.c:1449:isakmp_ph1resen): resend phase1 packet 915b092244d7fb35:0000000000000000
receiving:
<snip>
2003-04-16 14:40:07: DEBUG: isakmp.c:221:isakmp_handler(): ===
2003-04-16 14:40:07: DEBUG: isakmp.c:222:isakmp_handler(): 312 bytes message received from 64.7.134.90[41889]
2003-04-16 14:40:07: DEBUG: plog.c:193:plogdump():
915b0922 44d7fb35 00000000 00000000 01100400 00000000 00000138 04000038
00000001 00000001 0000002c 01010001 00000024 01010000 800b0001 800c0e10
80010003 800e0080 80030001 80020002 80040005 0a0000c4 8c687103 3ceab145
1f1fda2e 8210ae56 12ed3492 d3bf3a20 931c12d2 96631473 71ccebb7 b0d4e3a8
674dfba6 ee7d6085 9f83a55a 85c9dd16 575485ec 06e29bd9 4c347b98 f33940c7
e5ff7a41 10a83a78 ed576db8 bc325492 301eacdc ed00ccba 2a3e1165 ed772d57
760e8201 3467c440 28352967 13e030b9 a3404356 6339f699 955c074c 2239ce9b
ef519853 62edb648 4be54c09 f54d7d49 65bf7592 806a8554 47362099 461fbc39
9efbfedc bdb94b53 8fb1d9a9 525acc05 0aea8a6c e53408b9 05000014 953e119c
29e492ca fee18307 e7c6ab9c 0000000c 011101f4 4007865a
2003-04-16 14:40:07: DEBUG: isakmp.c:2248:isakmp_printpacket(): begin.
40:07.915101 64.7.134.90:41889 -> 199.212.134.18:500: isakmp 1.0 msgid 00000000: phase 1 I agg:
(sa: doi=ipsec situation=identity
(p: #1 protoid=isakmp transform=1
(t: #1 id=ike (type=lifetype value=sec)(type=lifeduration value=0e10)(type=enc value=blowfish)(type=keylen value=0080)(type=auth value=preshared)(type=hash value=sha1)(type=group desc value=0005))))
(ke: key len=192)
(nonce: n len=16)
(id: idtype=IPv4 protoid=udp port=500 len=4 64.7.134.90)
2003-04-16 14:40:07: DEBUG: remoteconf.c:134:getrmconf(): no remote configuration found.
2003-04-16 14:40:07: ERROR: isakmp.c:851:isakmp_ph1begin_r(): couldn't find configuration.
So I'm seeing one host send something off to the other, who is completely
ignoring the packet. I /did/ notice that the timestamps are a bit off, but
I would't think this matters...? I tried setting the timestamps to match,
same problem as above.
Interestingly, if I go the /other/ way, I see the following message:
initiating (was: receiving):
2003-04-16 14:47:41: DEBUG: isakmp.c:221:isakmp_handle): ===
2003-04-16 14:47:41: DEBUG: isakmp.c:222:isakmp_handle): 312 bytes message received from 199.212.134.18[500]
2003-04-16 14:47:41: DEBUG: plog.c:193:plogdum):
f9221b58 980142e7 00000000 00000000 01100400 00000000 00000138 04000038
00000001 00000001 0000002c 01010001 00000024 01010000 800b0001 800c0e10
80010003 800e0080 80030001 80020002 80040005 0a0000c4 0130413e 2a9c630e
e71311f8 582c580c 5165167c 7736edac 68843d01 f818060f c5a41c15 4cbbbefb
eb628f36 c02d6033 a086e794 b4407c0e 93ebe3a4 016cc872 5b9b5c57 6107b506
273c309a 32f6b2d2 1e4165d5 7a076f4e e8710f97 ac35d559 9015dbcb 04e34479
9beb3f58 cffae12a 206e6e0c 01e92971 fe183f42 452dd46c 0b1dfce0 c5467929
e2fb4464 4a9869de b8a4cfda ca97b6d1 8d64c22d 517fe531 11b44c0b 113ca02e
04943290 05e63b20 3b4233ae 2c41c73e 9e9a7bcf 8e1fc13b 05000014 d95c7669
982aeb86 791ae2fc 38eaaa13 0000000c 011101f4 c7d48612
2003-04-16 14:47:41: DEBUG: isakmp.c:2248:isakmp_printpacke): begin.
47:41.847966 199.212.134.18:500 -> 64.7.134.90:500: isakmp 1.0 msgid 00000000: phase 1 I agg:
sa: doi=ipsec situation=identity
p: #1 protoid=isakmp transform=1
t: #1 id=iketype=lifetype value=sectype=lifeduration value=0e10type=enc value=blowfishtype=keylen value=0080type=auth value=presharedtype=hash value=sha1type=group desc value=0005))))
ke: key len=192)
nonce: n len=16)
id: idtype=IPv4 protoid=udp port=500 len=4 199.212.134.18)
2003-04-16 14:47:41: DEBUG: remoteconf.c:118:getrmcon): configuration found for 199.212.134.18[500].
2003-04-16 14:47:41: DEBUG: isakmp.c:889:isakmp_ph1begin_): ===
2003-04-16 14:47:41: INFO: isakmp.c:894:isakmp_ph1begin_): respond new phase 1 negotiation: 64.7.134.90[500]<=>199.212.134.18[500]
2003-04-16 14:47:41: INFO: isakmp.c:899:isakmp_ph1begin_): begin Aggressive mode.
2003-04-16 14:47:41: DEBUG: isakmp.c:1112:isakmp_parsewo): begin.
2003-04-16 14:47:41: DEBUG: isakmp.c:1139:isakmp_parsewo): seen nptype=sa)
2003-04-16 14:47:41: DEBUG: isakmp.c:1139:isakmp_parsewo): seen nptype=ke)
2003-04-16 14:47:41: DEBUG: isakmp.c:1139:isakmp_parsewo): seen nptype=1nonce)
2003-04-16 14:47:41: DEBUG: isakmp.c:1139:isakmp_parsewo): seen nptype=id)
2003-04-16 14:47:41: DEBUG: isakmp.c:1178:isakmp_parsewo): succeed.
2003-04-16 14:47:41: DEBUG: isakmp_agg.c:649:agg_r1rec): received payload of type ke
2003-04-16 14:47:41: DEBUG: isakmp_agg.c:649:agg_r1rec): received payload of type nonce
2003-04-16 14:47:41: DEBUG: isakmp_agg.c:649:agg_r1rec): received payload of type id
2003-04-16 14:47:41: WARNING: ipsec_doi.c:3059:ipsecdoi_checkid): ID value mismatched.
2003-04-16 14:47:41: ERROR: isakmp_agg.c:697:agg_r1rec): invalid ID payload.
2003-04-16 14:47:41: ERROR: isakmp.c:913:isakmp_ph1begin_): failed to process packet.
receiving (was: initiating):
2003-04-16 14:44:40: DEBUG: isakmp_agg.c:162:agg_i1sen): authmethod is pre-shared key
2003-04-16 14:44:40: DEBUG: isakmp.c:2113:set_isakmp_payloa): add payload of len 52, next type 4
2003-04-16 14:44:40: DEBUG: isakmp.c:2113:set_isakmp_payloa): add payload of len 192, next type 10
2003-04-16 14:44:40: DEBUG: isakmp.c:2113:set_isakmp_payloa): add payload of len 16, next type 5
2003-04-16 14:44:40: DEBUG: isakmp.c:2113:set_isakmp_payloa): add payload of len 8, next type 0
2003-04-16 14:44:40: DEBUG: isakmp.c:2248:isakmp_printpacke): begin.
44:40.221157 199.212.134.18:500 -> 64.7.134.90:500: isakmp 1.0 msgid 00000000: phase 1 I agg:
sa: doi=ipsec situation=identity
p: #1 protoid=isakmp transform=1
t: #1 id=iketype=lifetype value=sectype=lifeduration value=0e10type=enc value=blowfishtype=keylen value=0080type=auth value=presharedtype=hash value=sha1type=group desc value=0005))))
ke: key len=192)
nonce: n len=16)
id: idtype=IPv4 protoid=udp port=500 len=4 199.212.134.18)
2003-04-16 14:44:40: DEBUG: sockmisc.c:421:sendfromt): sockname 199.212.134.18[500]
2003-04-16 14:44:40: DEBUG: sockmisc.c:423:sendfromt): send packet from 199.212.134.18[500]
2003-04-16 14:44:40: DEBUG: sockmisc.c:425:sendfromt): send packet to 64.7.134.90[500]
2003-04-16 14:44:40: DEBUG: sockmisc.c:570:sendfromt): 1 times of 312 bytes message will be sent to 199.212.134.18[500]
2003-04-16 14:44:40: DEBUG: plog.c:193:plogdum):
f9221b58 980142e7 00000000 00000000 01100400 00000000 00000138 04000038
00000001 00000001 0000002c 01010001 00000024 01010000 800b0001 800c0e10
80010003 800e0080 80030001 80020002 80040005 0a0000c4 0130413e 2a9c630e
e71311f8 582c580c 5165167c 7736edac 68843d01 f818060f c5a41c15 4cbbbefb
eb628f36 c02d6033 a086e794 b4407c0e 93ebe3a4 016cc872 5b9b5c57 6107b506
273c309a 32f6b2d2 1e4165d5 7a076f4e e8710f97 ac35d559 9015dbcb 04e34479
9beb3f58 cffae12a 206e6e0c 01e92971 fe183f42 452dd46c 0b1dfce0 c5467929
e2fb4464 4a9869de b8a4cfda ca97b6d1 8d64c22d 517fe531 11b44c0b 113ca02e
04943290 05e63b20 3b4233ae 2c41c73e 9e9a7bcf 8e1fc13b 05000014 d95c7669
982aeb86 791ae2fc 38eaaa13 0000000c 011101f4 c7d48612
2003-04-16 14:44:40: DEBUG: isakmp.c:1449:isakmp_ph1resen): resend phase1 packet f9221b58980142e7:0000000000000000
So instead of a 'configuration not found' message, I'm seeing 'invalid ID
payload'.
> Other things to check:
> - Phase 1 settings are the same - dh_group etc.
Following the first format above:
initiating:
remote 199.212.134.18
{
#exchange_mode main,aggressive;
exchange_mode aggressive,main;
doi ipsec_doi;
situation identity_only;
my_identifier address 64.7.134.90;
peers_identifier address 199.212.134.18;
verify_identifier on;
nonce_size 16;
lifetime time 60 min; # sec,min,hour
initial_contact on;
support_mip6 on;
proposal_check obey; # obey, strict or claim
proposal {
encryption_algorithm blowfish;
hash_algorithm sha1;
authentication_method pre_shared_key;
dh_group modp1536;
}
}
receiving:
remote 64.7.134.90
{
#exchange_mode main,aggressive;
exchange_mode aggressive,main;
doi ipsec_doi;
situation identity_only;
my_identifier address 199.212.134.18;
peers_identifier address 64.7.134.90;
verify_identifier on;
nonce_size 16;
lifetime time 60 min; # sec,min,hour
initial_contact on;
support_mip6 on;
proposal_check obey; # obey, strict or claim
proposal {
encryption_algorithm blowfish;
hash_algorithm sha1;
authentication_method pre_shared_key;
dh_group modp1536;
}
}
The two look fine to me. But then again, I'm the one having troubles. :)
> - phase 2 settings are the same ( sainfo stuff) pfs, times etc
I have four sections, each going each way. Two for
64.7.134.90<->199.212.134.18, and two for 172.16.0.0/24<->192.168.42.0/24.
So replace the two addresses below to handle the four possibilities.
initiating:
sainfo address 64.7.134.90 any address 199.212.134.18 any
{
pfs_group modp1536;
lifetime time 60 min;
encryption_algorithm blowfish;
authentication_algorithm hmac_sha1;
compression_algorithm deflate;
}
receiving:
sainfo address 199.212.134.18 any address 64.7.134.90 any
{
pfs_group modp1536;
lifetime time 60 min;
encryption_algorithm blowfish;
authentication_algorithm hmac_sha1;
compression_algorithm deflate;
}
Again, these look pretty okay to me. But again, that's me.
> - the psk files are chmod 600 ( been cought by this one before)
Checked and double-checked.
> - The psk files contain either both hosts with the appropriate key, or just
> the remote host
Just the remote host:
initiating:
199.212.134.18 hellojellohellojellohellojello
receiving:
64.7.134.90 hellojellohellojellohellojello
Yes, that's what I'm trying with right now. I have another shared secret
for actual production use.
> - try upping the debug level on racoon and see if it moans.
I'm already running at DEBUG. I can try DEBUG2...
And just for thoroughness, here's my /etc/ipsec.conf:
initiating:
flush;
spdflush;
spdadd 192.168.42.0/24 172.16.0.0/24 any -P in ipsec esp/tunnel/199.212.134.18-64.7.134.90/require;
spdadd 172.16.0.0/24 192.168.42.0/24 any -P out ipsec esp/tunnel/64.7.134.90-199.212.134.18/require ;
receiving:
flush;
spdflush;
spdadd 192.168.42.0/24 172.16.0.0/24 any -P out ipsec esp/tunnel/199.212.134.18-64.7.134.90/require;
spdadd 172.16.0.0/24 192.168.42.0/24 any -P in ipsec esp/tunnel/64.7.134.90-199.212.134.18/require;
Something looks funny about these, but I can't tell what...
> In my experiance, have almost no trouble getting bsd-bsd IPSEC links
> talking, biggest pain has been to checkpoint boxes
Yeah, I'm ~100% sure this is a configuration error, I just can't figure out
/where/. I've worked with IPSec before (FreeS/WAN), and within the same
implementation, the error's always been user error.
Side note, I just tried changing the exchange_mode on both of them to
main,aggressive instead of aggressive,main. Here's the new tcpdump I see:
15:03:36.591876 pyroxene.sentex.ca.isakmp > asylum.afflictions.org.isakmp: isakmp: phase 1 I ident: [|sa]
15:03:37.031774 asylum.afflictions.org.isakmp > pyroxene.sentex.ca.isakmp: isakmp: phase 1 R ident: [|sa]
15:03:37.181992 pyroxene.sentex.ca.isakmp > asylum.afflictions.org.isakmp: isakmp: phase 1 I ident: [|ke]
15:03:38.545255 asylum.afflictions.org.isakmp > pyroxene.sentex.ca.isakmp: isakmp: phase 1 R ident: [|ke]
15:03:38.711593 pyroxene.sentex.ca.isakmp > asylum.afflictions.org.isakmp: isakmp: phase 1 I ident[E]: [encrypted id]
15:03:48.727758 asylum.afflictions.org.isakmp > pyroxene.sentex.ca.isakmp: isakmp: phase 1 R ident: [|ke]
15:03:48.731077 pyroxene.sentex.ca.isakmp > asylum.afflictions.org.isakmp: isakmp: phase 1 I ident[E]: [encrypted id]
That looks a /little/ more promising, but I wouldn't have thought it would
have mattered that much...? Both machines are running 4.8-RC, the initiator
as of Apr. 2 and the receiver as of Mar 15.
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20030416190520.GJ648>