IPSec between CentOS and Windows Server 2003

Discussion in 'Technical' started by crimondi, May 5, 2009.

  1. crimondi

    crimondi New Member

    I am trying to set up a host-to-host connection between my CentOS 5 box and a Windows 2003 server using a PSK. I am getting the following error messages in my racoon.log file:

    2009-05-04 07:43:27: INFO: @(#)ipsec-tools 0.6.5 (http://ipsec-tools.sourceforge.net)
    2009-05-04 07:43:27: INFO: @(#)This product linked OpenSSL 0.9.8e-fips-rhel5 01 Jul 2008 (http://www.openssl.org/)
    2009-05-04 07:43:27: DEBUG: call pfkey_send_register for AH
    2009-05-04 07:43:27: DEBUG: call pfkey_send_register for ESP
    2009-05-04 07:43:27: DEBUG: call pfkey_send_register for IPCOMP
    2009-05-04 07:43:27: DEBUG: reading config file /etc/racoon/racoon.conf
    2009-05-04 07:43:27: DEBUG2: lifetime = 28800
    2009-05-04 07:43:27: DEBUG2: lifebyte = 0
    2009-05-04 07:43:27: DEBUG2: encklen=0
    2009-05-04 07:43:27: DEBUG2: p:1 t:1
    2009-05-04 07:43:27: DEBUG2: 3DES-CBC(5)
    2009-05-04 07:43:27: DEBUG2: SHA(2)
    2009-05-04 07:43:27: DEBUG2: 2048-bit MODP group(14)
    2009-05-04 07:43:27: DEBUG2: pre-shared key(1)
    2009-05-04 07:43:27: DEBUG2:
    2009-05-04 07:43:27: DEBUG: compression algorithm can not be checked because sadb message doesn't support it.
    2009-05-04 07:43:27: DEBUG: filename: /etc/racoon/x.x.x.x.conf
    2009-05-04 07:43:27: DEBUG: reading config file /etc/racoon/x.x.x.x.conf
    2009-05-04 07:43:27: DEBUG2: lifetime = 28800
    2009-05-04 07:43:27: DEBUG2: lifebyte = 0
    2009-05-04 07:43:27: DEBUG2: encklen=0
    2009-05-04 07:43:27: DEBUG2: p:1 t:1
    2009-05-04 07:43:27: DEBUG2: 3DES-CBC(5)
    2009-05-04 07:43:27: DEBUG2: SHA(2)
    2009-05-04 07:43:27: DEBUG2: 1024-bit MODP group(2)
    2009-05-04 07:43:27: DEBUG2: pre-shared key(1)
    2009-05-04 07:43:27: DEBUG2:
    2009-05-04 07:43:27: DEBUG: hmac(modp1024)
    2009-05-04 07:43:27: DEBUG2: parse successed.
    2009-05-04 07:43:27: DEBUG: open /var/racoon/racoon.sock as racoon management.
    2009-05-04 07:43:27: DEBUG: my interface: fe80::213:72ff:fe93:9d31%eth0 (eth0)
    2009-05-04 07:43:27: DEBUG: my interface: ::1 (lo)
    2009-05-04 07:43:27: DEBUG: my interface: x.x.x.x (eth0)
    2009-05-04 07:43:27: DEBUG: my interface: 127.0.0.1 (lo)
    2009-05-04 07:43:27: DEBUG: configuring default isakmp port.
    2009-05-04 07:43:27: DEBUG: 4 addrs are configured successfully
    2009-05-04 07:43:27: ERROR: failed to bind to address 127.0.0.1[500] (Address already in use).
    2009-05-04 07:43:27: ERROR: failed to bind to address x.x.x.x [500] (Address already in use).
    2009-05-04 07:43:27: ERROR: failed to bind to address ::1[500] (Address already in use).
    2009-05-04 07:43:27: ERROR: failed to bind to address fe80::213:72ff:fe93:9d31%eth0[500] (Address already in use).
    2009-05-04 07:43:27: ERROR: no address could be bound.

    Any ideas what could be causing this?

    Thanks,

    Chris
     
  2. topdog

    topdog Active Member HowtoForge Supporter

    Some other daemon is already listening to the socket UDP 500, run
    Code:
    netstat -nulp
    to see what it is.
     
  3. crimondi

    crimondi New Member

    Thanks. I killed the process that was listening on port 500. that solved the issue of racoon being unable to bind the port. Now, think the two are not negotiating correctly. I am getting the error messages below.
    Code:
    2009-05-06 03:57:07: DEBUG: suitable outbound SP found: x.x.x.x/32[0] x.x.x.x/32[0] proto=any dir=out.
    2009-05-06 03:57:07: DEBUG: sub:0xbfbc2d78: x.x.x.x/32[0] x.x.x.x/32[0] proto=any dir=in
    2009-05-06 03:57:07: DEBUG: db :0x8721a10: x.x.x.x/32[0] x.x.x.x/32[0] proto=any dir=out
    2009-05-06 03:57:07: DEBUG: sub:0xbfbc2d78: x.x.x.x/32[0] x.x.x.x/32[0] proto=any dir=in
    2009-05-06 03:57:07: DEBUG: db :0x8722960: x.x.x.x/32[0] x.x.x.x/32[0] proto=any dir=in
    2009-05-06 03:57:07: DEBUG: suitable inbound SP found: x.x.x.x/32[0] x.x.x.x/32[0] proto=any dir=in.
    2009-05-06 03:57:07: DEBUG: new acquire x.x.x.x/32[0] x.x.x.x/32[0] proto=any dir=out
    2009-05-06 03:57:07: DEBUG: anonymous sainfo selected.
    2009-05-06 03:57:07: DEBUG:  (proto_id=AH spisize=4 spi=00000000 spi_p=00000000 encmode=Transport reqid=0:0)
    2009-05-06 03:57:07: DEBUG:   (trns_id=SHA authtype=hmac-sha)
    2009-05-06 03:57:07: DEBUG:   (trns_id=MD5 authtype=hmac-md5)
    2009-05-06 03:57:07: DEBUG:  (proto_id=ESP spisize=4 spi=00000000 spi_p=00000000 encmode=Transport reqid=0:0)
    2009-05-06 03:57:07: DEBUG:   (trns_id=3DES encklen=0 authtype=hmac-sha)
    2009-05-06 03:57:07: DEBUG:   (trns_id=3DES encklen=0 authtype=hmac-md5)
    2009-05-06 03:57:07: DEBUG:   (trns_id=BLOWFISH encklen=448 authtype=hmac-sha)
    2009-05-06 03:57:07: DEBUG:   (trns_id=BLOWFISH encklen=448 authtype=hmac-md5)
    2009-05-06 03:57:07: DEBUG:   (trns_id=AES encklen=128 authtype=hmac-sha)
    2009-05-06 03:57:07: DEBUG:   (trns_id=AES encklen=128 authtype=hmac-md5)
    2009-05-06 03:57:07: DEBUG: configuration found for x.x.x.x.
    2009-05-06 03:57:07: INFO: request for establishing IPsec-SA was queued due to no phase1 found.
    2009-05-06 03:57:07: DEBUG: 264 bytes from x.x.x.x[500] to x.x.x.x[500]
    2009-05-06 03:57:07: DEBUG: sockname x.x.x.x[500]
    2009-05-06 03:57:07: DEBUG: send packet from x.x.x.x[500]
    2009-05-06 03:57:07: DEBUG: send packet to x.x.x.x[500]
    2009-05-06 03:57:07: DEBUG: src4 x.x.x.x[500]
    2009-05-06 03:57:07: DEBUG: dst4 x.x.x.x[500]
    2009-05-06 03:57:07: DEBUG: 1 times of 264 bytes message will be sent to x.x.x.x[500]
    2009-05-06 03:57:07: DEBUG: 
    466bd9ff 422cdf20 00000000 00000000 01100400 00000000 00000108 04000034
    00000001 00000001 00000028 01010001 00000020 01010000 800b0001 800c7080
    80010005 80030001 80020002 80040002 0a000084 358a8bdb 33934615 771a5878
    b61d9439 6f101927 126293ba 42f9b29f e18486b9 8b1ccaa0 21fcccbb ca56562a
    552cc204 81d3b58b 44a42a05 d326ef7c 1dbba264 b98ad84b 62280dda 58cfa4bf
    859252e2 e9290bff 485a156b 132661fc c9e563a6 8832de63 2023dcaa ba9ff8ba
    43568016 4cb15298 2936fe8c 1e86fec5 e46060c1 05000014 c6fcbd09 95599ee1
    5de53525 e766dccd 0d00000c 011101f4 0aa46838 00000014 afcad713 68a1f1c9
    6b8696fc 77570100
    2009-05-06 03:57:07: DEBUG: resend phase1 packet 466bd9ff422cdf20:0000000000000000
    2009-05-06 03:57:08: ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP x.x.x.x[500]->x.x.x.x[500] 
    2009-05-06 03:57:08: INFO: delete phase 2 handler.
    
    
    2009-05-06 03:59:00: INFO: unsupported PF_KEY message REGISTER
    2009-05-06 03:59:00: DEBUG: get pfkey X_SPDDELETE2 message
     
    Last edited: May 6, 2009
  4. topdog

    topdog Active Member HowtoForge Supporter

    It seems like the peer is not responding on UDP 500 so the Phase1 negotiation is not taking place.
     
  5. crimondi

    crimondi New Member

    The peer is the Windows host. I have it configured to 3DES on the Confidentiality and SHA1 on the Integrity and again they are set to use the same PSK. Do you think I am missing some configuration there? Below is the peer conf file in Racoon for the Windows host. Thanks for all your help.

    Code:
    remote x.x.x.x
    {
    	exchange_mode aggressive, main;
    	my_identifier address;
    	proposal {
    	        encryption_algorithm 3des;
    		hash_algorithm sha1;
    		authentication_method pre_shared_key;
    		dh_group 2;
    	}
    }
     
  6. crimondi

    crimondi New Member

    I have worked with some of the configurations and am now getting the following in my racoon log file.

    Code:
    unknown notify message, no phase2 handle found.
    notification message 14:NO-PROPOSAL-CHOSEN, doi=1 proto_id=3 spi=00000000(size=4)
     
  7. topdog

    topdog Active Member HowtoForge Supporter

    That means phase1 (isakmp) negotiation succeeded but phase2 (ipsec) failed, you need to check that what you propose to the pear matches what is configured on your side.
     
  8. crimondi

    crimondi New Member

    Thanks for your help with this. I have checked to make sure they are the same and I believe that they are. My config for phase2 is the following:

    Code:
    sainfo anonymous
    {
    	pfs_group 1;
    	lifetime time 1 hour ;
    	encryption_algorithm 3des ;
    	authentication_algorithm hmac_sha1 ;
    	compression_algorithm deflate ;
    }
    and a larger segment of my racoon log is below:

    Code:
    2009-05-07 07:35:23: DEBUG: resend phase2 packet f54d366ed36ce644:2de9980389e965e9:0000ad9a
    2009-05-07 07:35:23: DEBUG: ===
    2009-05-07 07:35:23: DEBUG: 84 bytes message received from x.x.x.x[500] to y.y.y.y[500]
    2009-05-07 07:35:23: DEBUG: 
    f54d366e d36ce644 2de99803 89e965e9 08100501 9fb60b70 00000054 113631e6
    38cafe2d 31f87370 1a9620bd 1e10b463 f0197c28 400cb2b7 c377b3f7 a3c9de20
    6f0a0493 f9e2f519 93621694 7ed2621a 757628a8
    2009-05-07 07:35:23: DEBUG: receive Information.
    2009-05-07 07:35:23: DEBUG: compute IV for phase2
    2009-05-07 07:35:23: DEBUG: phase1 last IV:
    2009-05-07 07:35:23: DEBUG: 
    4cf18a29 f2c522c8 9fb60b70
    2009-05-07 07:35:23: DEBUG: hash(sha1)
    2009-05-07 07:35:23: DEBUG: encryption(3des)
    2009-05-07 07:35:23: DEBUG: phase2 IV computed:
    2009-05-07 07:35:23: DEBUG: 
    0a00831a 843719b9
    2009-05-07 07:35:23: DEBUG: begin decryption.
    2009-05-07 07:35:23: DEBUG: encryption(3des)
    2009-05-07 07:35:23: DEBUG: IV was saved for next processing:
    2009-05-07 07:35:23: DEBUG: 
    7ed2621a 757628a8
    2009-05-07 07:35:23: DEBUG: encryption(3des)
    2009-05-07 07:35:23: DEBUG: with key:
    2009-05-07 07:35:23: DEBUG: 
    8106a255 f5e03200 25b2aec1 32f4913f fe03d39b 69c8711a
    2009-05-07 07:35:23: DEBUG: decrypted payload by IV:
    2009-05-07 07:35:23: DEBUG: 
    0a00831a 843719b9
    2009-05-07 07:35:23: DEBUG: decrypted payload, but not trimed.
    2009-05-07 07:35:23: DEBUG: 
    0b000018 2fccb0e9 7ffbc1d3 82b3486c b7f85248 da1ce9e1 0000001c 00000001
    0304000e 00000000 0a005c00 01000000 01000000 00000000
    2009-05-07 07:35:23: DEBUG: padding len=1
    2009-05-07 07:35:23: DEBUG: skip to trim padding.
    2009-05-07 07:35:23: DEBUG: decrypted.
    2009-05-07 07:35:23: DEBUG: 
    f54d366e d36ce644 2de99803 89e965e9 08100501 9fb60b70 00000054 0b000018
    2fccb0e9 7ffbc1d3 82b3486c b7f85248 da1ce9e1 0000001c 00000001 0304000e
    00000000 0a005c00 01000000 01000000 00000000
    2009-05-07 07:35:23: DEBUG: HASH with:
    2009-05-07 07:35:23: DEBUG: 
    9fb60b70 0000001c 00000001 0304000e 00000000 0a005c00 01000000 01000000
    2009-05-07 07:35:23: DEBUG: hmac(hmac_sha1)
    2009-05-07 07:35:23: DEBUG: HASH computed:
    2009-05-07 07:35:23: DEBUG: 
    2fccb0e9 7ffbc1d3 82b3486c b7f85248 da1ce9e1
    2009-05-07 07:35:23: DEBUG: hash validated.
    2009-05-07 07:35:23: DEBUG: begin.
    2009-05-07 07:35:23: DEBUG: seen nptype=8(hash)
    2009-05-07 07:35:23: DEBUG: seen nptype=11(notify)
    2009-05-07 07:35:23: DEBUG: succeed.
    2009-05-07 07:35:23: ERROR: unknown notify message, no phase2 handle found.
    2009-05-07 07:35:23: DEBUG: notification message 14:NO-PROPOSAL-CHOSEN, doi=1 proto_id=3 spi=00000000(size=4).
    2009-05-07 07:35:23: DEBUG: get pfkey EXPIRE message
    2009-05-07 07:35:23: INFO: IPsec-SA expired: AH/Transport x.x.x.x[0]->y.y.y.y[0] spi=208723548(0xc70de5c)
    2009-05-07 07:35:23: DEBUG: no such a SA found: AH/Transport x.x.x.x[0]->y.y.y.y[0] spi=208723548(0xc70de5c)
    2009-05-07 07:35:23: DEBUG: get pfkey EXPIRE message
    2009-05-07 07:35:23: INFO: IPsec-SA expired: ESP/Transport x.x.x.x[0]->y.y.y.y[0] spi=207127279(0xc5882ef)
    2009-05-07 07:35:23: DEBUG: no such a SA found: ESP/Transport x.x.x.x[0]->y.y.y.y[0] spi=207127279(0xc5882ef)
     
  9. topdog

    topdog Active Member HowtoForge Supporter

    What is in your /etc/setkey.conf file ?
     
  10. crimondi

    crimondi New Member

    Where 'x.x.x.x' is the CentOS host, and 'y.y.y.y' and 'z.z.z.z' are the IP addresses of the Windows box.

    Code:
    spdadd x.x.x.x/32 y.y.y.y/32 any -P out ipsec
               esp/transport//require
               ah/transport//require;
    
    spdadd y.y.y.y/32 x.x.x.x/32 any -P in ipsec
               esp/transport//require
               ah/transport//require;
    
    spdadd x.x.x.x/32 z.z.z.z/32 any -P out ipsec
               esp/transport//require
               ah/transport//require;
    
    spdadd z.z.z.z/32 x.x.x.x/32 any -P in ipsec
               esp/transport//require
               ah/transport//require;
     
  11. topdog

    topdog Active Member HowtoForge Supporter

    It could be the pfs_group, any why i have not used windows as a node before only as a road warrior so beyond what i can pick up from the logs i can not say.

    Look at the logs on the windows side as well and see why it is rejecting the proposal.
     

Share This Page