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 |
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] |