Issues with IPSec

nikazim · Nov 10, 2011

Hi all,

I have a L2TP/IPSec dial in server using MPD5/FreeBSD9. Everything works fine, except that a client can only connect to the VPN successfully once. Trying to reconnect again later will fail with some weird stuff going on in the background. I'm testing this with MacOS 10.7 X client.

Both kernel and ipsec-tools are compiled with NAT-T options.

Below are some details of my configuration / debugging.

racoon.conf:

Code:

path certificate    "/usr/local/etc/racoon/cert";

listen
{
        isakmp           93.xxx.xxx.xxx[500];
        isakmp_natt      93.xxx.xxx.xxx[4500];
}

remote anonymous
{
        exchange_mode     main;
        certificate_type  x509 "newcert.pem" "newkey.pem";
        my_identifier     asn1dn;
        peers_identifier  asn1dn;
        verify_identifier on;
        proposal_check    obey;
        initial_contact   on;
        nat_traversal     on;
        ike_frag          on;
        dpd_delay         20;
        support_proxy     on;

        proposal
        {
                encryption_algorithm  aes 256;
                hash_algorithm        sha1;
                authentication_method rsasig;
                dh_group              2;
        }
}

sainfo anonymous
{
        pfs_group                2;
        encryption_algorithm     aes 256;
        authentication_algorithm hmac_sha1;
        compression_algorithm    deflate;
}

setkey.conf:

Code:

flush;
spdflush;
spdadd 0.0.0.0/0 93.xxx.xxx.xxx/32[1701] udp -P in  ipsec esp/transport//require;
spdadd 93.xxx.xxx.xxx/32[1701] 0.0.0.0/0 udp -P out ipsec esp/transport//require;

racoon.log:

Code:

/* first connection */
2011-11-10 06:15:38: INFO: respond new phase 1 negotiation: 93.xxx.xxx.xxx[500]<=>60.xxx.xxx.xxx[500]
2011-11-10 06:15:38: INFO: begin Identity Protection mode.
..
2011-11-10 06:15:38: [60.xxx.xxx.xxx] INFO: Selected NAT-T version: RFC 3947
2011-11-10 06:15:39: [93.xxx.xxx.xxx] INFO: Hashing 93.xxx.xxx.xxx[500] with algo #2 
2011-11-10 06:15:39: INFO: NAT-D payload #0 verified
2011-11-10 06:15:39: [60.xxx.xxx.xxx] INFO: Hashing 60.xxx.xxx.xxx[500] with algo #2 
2011-11-10 06:15:39: INFO: NAT-D payload #1 doesn't match
2011-11-10 06:15:39: INFO: NAT detected: PEER
2011-11-10 06:15:39: [60.xxx.xxx.xxx] INFO: Hashing 60.xxx.xxx.xxx[500] with algo #2 
2011-11-10 06:15:39: [93.xxx.xxx.xxx] INFO: Hashing 93.xxx.xxx.xxx[500] with algo #2 
2011-11-10 06:15:39: INFO: Adding remote and local NAT-D payloads.
2011-11-10 06:15:39: INFO: NAT-T: ports changed to: 60.xxx.xxx.xxx[39240]<->93.xxx.xxx.xxx[4500]
2011-11-10 06:15:39: INFO: KA list add: 93.xxx.xxx.xxx[4500]->60.xxx.xxx.xxx[39240]
2011-11-10 06:15:39: WARNING: unable to get certificate CRL(3) at depth:0 SubjectName:...
2011-11-10 06:15:39: WARNING: unable to get certificate CRL(3) at depth:1 SubjectName:...
2011-11-10 06:15:39: [60.xxx.xxx.xxx] INFO: received INITIAL-CONTACT
2011-11-10 06:15:39: INFO: ISAKMP-SA established 93.xxx.xxx.xxx[4500]-60.xxx.xxx.xxx[39240] spi:00f77a1dd7409c88:57b00f55c13cdb1e
2011-11-10 06:15:41: INFO: respond new phase 2 negotiation: 93.xxx.xxx.xxx[4500]<=>60.xxx.xxx.xxx[39240]
2011-11-10 06:15:41: INFO: Adjusting my encmode UDP-Transport->Transport
2011-11-10 06:15:41: INFO: Adjusting peer's encmode UDP-Transport(4)->Transport(2)
2011-11-10 06:15:41: INFO: IPsec-SA established: ESP/Transport 93.xxx.xxx.xxx[500]->60.xxx.xxx.xxx[500] spi=259251853(0xf73de8d)
2011-11-10 06:15:41: INFO: IPsec-SA established: ESP/Transport 93.xxx.xxx.xxx[500]->60.xxx.xxx.xxx[500] spi=164146707(0x9c8ae13)
2011-11-10 06:15:41: ERROR: phase1 negotiation failed due to time up. 77eb6605e3b417b3:0000000000000000
/* connected */

/* disconnect */
2011-11-10 06:15:48: INFO: purged IPsec-SA proto_id=ESP spi=164146707.
2011-11-10 06:15:48: INFO: purging ISAKMP-SA spi=00f77a1dd7409c88:57b00f55c13cdb1e.
2011-11-10 06:15:48: INFO: purged IPsec-SA spi=259251853.
2011-11-10 06:15:48: INFO: purged ISAKMP-SA spi=00f77a1dd7409c88:57b00f55c13cdb1e.
2011-11-10 06:15:48: INFO: ISAKMP-SA deleted 93.xxx.xxx.xxx[4500]-60.xxx.xxx.xxx[39240] spi:00f77a1dd7409c88:57b00f55c13cdb1e
2011-11-10 06:15:48: INFO: KA remove: 93.xxx.xxx.xxx[4500]->60.xxx.xxx.xxx[39240]
2011-11-10 06:15:48: INFO: IPsec-SA request for 60.xxx.xxx.xxx queued due to no phase1 found.
2011-11-10 06:15:48: INFO: initiate new phase 1 negotiation: 93.xxx.xxx.xxx[500]<=>60.xxx.xxx.xxx[500]
2011-11-10 06:15:48: INFO: begin Identity Protection mode.
2011-11-10 06:16:20: [60.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 60.xxx.xxx.xxx[0]->93.xxx.xxx.xxx[0] 
2011-11-10 06:16:20: INFO: delete phase 2 handler.
2011-11-10 06:16:38: ERROR: phase1 negotiation failed due to time up. 6b182e02842ba4ba:0000000000000000

/* reconnect */
2011-11-10 06:18:18: INFO: respond new phase 1 negotiation: 93.xxx.xxx.xxx[500]<=>60.xxx.xxx.xxx[500]
2011-11-10 06:18:18: INFO: begin Identity Protection mode.
..
2011-11-10 06:18:18: [60.xxx.xxx.xxx] INFO: Selected NAT-T version: RFC 3947
2011-11-10 06:18:19: [93.xxx.xxx.xxx] INFO: Hashing 93.xxx.xxx.xxx[500] with algo #2 
2011-11-10 06:18:19: INFO: NAT-D payload #0 verified
2011-11-10 06:18:19: [60.xxx.xxx.xxx] INFO: Hashing 60.xxx.xxx.xxx[500] with algo #2 
2011-11-10 06:18:19: INFO: NAT-D payload #1 doesn't match
2011-11-10 06:18:19: INFO: NAT detected: PEER
2011-11-10 06:18:19: [60.xxx.xxx.xxx] INFO: Hashing 60.xxx.xxx.xxx[500] with algo #2 
2011-11-10 06:18:19: [93.xxx.xxx.xxx] INFO: Hashing 93.xxx.xxx.xxx[500] with algo #2 
2011-11-10 06:18:19: INFO: Adding remote and local NAT-D payloads.
2011-11-10 06:18:19: INFO: NAT-T: ports changed to: 60.xxx.xxx.xxx[39774]<->93.xxx.xxx.xxx[4500]
2011-11-10 06:18:19: INFO: KA list add: 93.xxx.xxx.xxx[4500]->60.xxx.xxx.xxx[39774]
2011-11-10 06:18:19: WARNING: unable to get certificate CRL(3) at depth:0 SubjectName:...
2011-11-10 06:18:19: WARNING: unable to get certificate CRL(3) at depth:1 SubjectName:...
2011-11-10 06:18:19: [60.xxx.xxx.xxx] INFO: received INITIAL-CONTACT
2011-11-10 06:18:19: INFO: ISAKMP-SA established 93.xxx.xxx.xxx[4500]-60.xxx.xxx.xxx[39774] spi:6e719bd6e76e8173:302a148a53babd2e
2011-11-10 06:18:20: INFO: respond new phase 2 negotiation: 93.xxx.xxx.xxx[4500]<=>60.xxx.xxx.xxx[39774]
2011-11-10 06:18:20: INFO: Adjusting my encmode UDP-Transport->Transport
2011-11-10 06:18:20: INFO: Adjusting peer's encmode UDP-Transport(4)->Transport(2)
2011-11-10 06:18:21: INFO: IPsec-SA established: ESP/Transport 93.xxx.xxx.xxx[500]->60.xxx.xxx.xxx[500] spi=217311109(0xcf3e785)
2011-11-10 06:18:21: INFO: IPsec-SA established: ESP/Transport 93.xxx.xxx.xxx[500]->60.xxx.xxx.xxx[500] spi=88113922(0x5408302)
2011-11-10 06:18:41: INFO: purging ISAKMP-SA spi=6e719bd6e76e8173:302a148a53babd2e.
2011-11-10 06:18:41: INFO: purged IPsec-SA spi=217311109.
2011-11-10 06:18:41: INFO: purged ISAKMP-SA spi=6e719bd6e76e8173:302a148a53babd2e.
2011-11-10 06:18:41: INFO: ISAKMP-SA deleted 93.xxx.xxx.xxx[4500]-60.xxx.xxx.xxx[39774] spi:6e719bd6e76e8173:302a148a53babd2e
2011-11-10 06:18:41: INFO: KA remove: 93.xxx.xxx.xxx[4500]->60.xxx.xxx.xxx[39774]
/* reconnect fails */

Looking at tcpdump output, the server seems to be using the wrong port when trying to reply to the client during the second connection:

Code:

06:18:18.738819 IP 60.xxx.xxx.xxx.500 > 93.xxx.xxx.xxx.500: isakmp: phase 1 I ident
06:18:18.745389 IP 93.xxx.xxx.xxx.500 > 60.xxx.xxx.xxx.500: isakmp: phase 1 R ident
06:18:19.056859 IP 60.xxx.xxx.xxx.500 > 93.xxx.xxx.xxx.500: isakmp: phase 1 I ident
06:18:19.104005 IP 93.xxx.xxx.xxx.500 > 60.xxx.xxx.xxx.500: isakmp: phase 1 R ident
06:18:19.423112 IP 60.xxx.xxx.xxx.39774 > 93.xxx.xxx.xxx.4500: NONESP-encap: isakmp: phase 1 I ident[E]
06:18:19.464968 IP 93.xxx.xxx.xxx.4500 > 60.xxx.xxx.xxx.39774: NONESP-encap: isakmp: phase 1 R ident[E]
06:18:19.466459 IP 93.xxx.xxx.xxx.4500 > 60.xxx.xxx.xxx.39774: NONESP-encap: isakmp: phase 2/others R inf[E]
06:18:20.774357 IP 60.xxx.xxx.xxx.39774 > 93.xxx.xxx.xxx.4500: NONESP-encap: isakmp: phase 2/others I oakley-quick[E]
06:18:20.779456 IP 93.xxx.xxx.xxx.4500 > 60.xxx.xxx.xxx.39774: NONESP-encap: isakmp: phase 2/others R oakley-quick[E]
06:18:21.063297 IP 60.xxx.xxx.xxx.39774 > 93.xxx.xxx.xxx.4500: NONESP-encap: isakmp: phase 2/others I oakley-quick[E]
06:18:21.067602 IP 60.xxx.xxx.xxx.39774 > 93.xxx.xxx.xxx.4500: UDP-encap: ESP(spi=0x0cf3e785,seq=0x1), length 132
06:18:21.074855 IP 93.xxx.xxx.xxx.4500 > 60.xxx.xxx.xxx.39240: UDP-encap: ESP(spi=0x05408302,seq=0x1), length 164
06:18:21.350972 IP 60.xxx.xxx.xxx > 93.xxx.xxx.xxx: ICMP host 60.xxx.xxx.xxx unreachable - admin prohibited filter, length 36

Port 39240 is the port that was used in the previous connection.

It looks to me that somehow that racoon generates invalid SA entry for the 2nd connection? If I flush the entry (setkey -F) then the client can reconnect again.

Has anyone seen this before?

Thanks,
Nik

tobias · Apr 30, 2012

Did you find a solution to this? I have the same problem.

Issues with IPSec

nikazim

tobias