[Openswan Users] Problem with MacOSX 10.5.8 roadwarriors

alet at librelogiciel.com alet at librelogiciel.com
Thu Feb 25 21:21:30 EST 2010 

Hi,

I've got aGNU/Linux Openswan 2.4.12 + xl2tpd 1.2.0, and kernel 2.6.26
(both standard from Debian Lenny) gateway which correctly accepts both
Linux and Windows Vista clients with X.509 certificates.

The same client certificate as used under Linux and Windows was used
under MacOSX for testing purposes, but I couldn't make the VPN
connection work.

my ipsec.conf is as follow :

--- CUT ---
config setup
        nat_traversal=yes
        nhelpers=0
        plutodebug="control klips"
        uniqueids=yes
        protostack=netkey
        interfaces=%defaultroute
        virtual_private=%v4:10.0.0.0/8,%v4:192.168.0.0/16,%v4:172.16.0.0/12,%v4:!10.10.66.0/24

conn %default
        keyingtries=1
        compress=yes
        disablearrivalcheck=no
        authby=rsasig
        leftid=@gwvpn.example.com
        leftrsasigkey=%cert
        leftsendcert=always
        rightrsasigkey=%cert
        rightca=%same

conn MYVPN-l2tp
        leftprotoport=17/1701
        #rightprotoport=17/1701
        rightprotoport=17/%any
        also=MYVPN

conn MYVPN-all
        leftsubnet=0.0.0.0/0
        also=MYVPN

conn MYVPN
        left=%defaultroute
        leftnexthop=10.10.66.254
        leftcert=/etc/ipsec.d/certs/gwvpn.example.com.pem
        right=%any
        rightsubnet=vhost:%priv,%no
        rightnexthop=10.10.66.254
        auto=add
        pfs=no

#Disable Opportunistic Encryption
include /etc/ipsec.d/examples/no_oe.conf
--- CUT ---

The xl2tpd server has a local ip of 10.10.66.254 and assigns addresses
from 10.10.66.1 to 10.10.66.354. For now, no ppp authentication is used,
so the VPN only authenticates machines, not users (I prefer to do one
step at a time).

I've followed Jacco de Leeuw's extensive (and wonderful) documentation,
and activated debugging info on the MacOSX side, but unfortunately I
don't know what is wrong, so here's the log (the MacOSX client is behind
a NAT box) :

--- CUT ---
racoon[358]: [358] INFO: ***** racoon started: pid=358  started by: 1
racoon[358]: [358] INFO: @(#) racoon / IPsec-tools
racoon[358]: [358] INFO: @(#)This product linked OpenSSL 0.9.7l 28 Sep
2006 (http://www.openssl.org/)
racoon[358]: [358] WARNING: /etc/racoon/remote/XXX.XXX.XXX.XXX.conf:13:
"support_mip6" it is obsoleted.  use "support_proxy".
racoon[358]: [358] WARNING: /etc/racoon/remote/anonymous.conf:16:
"support_mip6" it is obsoleted.  use "support_proxy".
racoon[358]: [358] DEBUG2: lifetime = 60
racoon[358]: [358] DEBUG2: lifebyte = 0
racoon[358]: [358] DEBUG2: encklen=0
racoon[358]: [358] DEBUG2: p:1 t:1
racoon[358]: [358] DEBUG2: 3DES-CBC(5)
racoon[358]: [358] DEBUG2: SHA(2)
racoon[358]: [358] DEBUG2: 1024-bit MODP group(2)
racoon[358]: [358] DEBUG2: pre-shared key(1)
racoon[358]: [358] DEBUG2:
racoon[358]: [358] DEBUG: hmac(modp1024)
racoon[358]: [358] DEBUG: compression algorithm can not be checked
because sadb message doesn't support it.
racoon[358]: [358] DEBUG: anonymous sainfo selected.
racoon[358]: [358] DEBUG2: parse successed.
racoon[358]: [358] DEBUG: my interface: fe80::1%lo0 (lo0)
racoon[358]: [358] DEBUG: my interface: 127.0.0.1 (lo0)
racoon[358]: [358] DEBUG: my interface: ::1 (lo0)
racoon[358]: [358] DEBUG: my interface: fe80::219:e3ff:fed3:3a67%en1
(en1)
racoon[358]: [358] DEBUG: my interface: 10.13.0.130 (en1)
racoon[358]: [358] DEBUG: configuring default isakmp port.
racoon[358]: [358] DEBUG: 10 addrs are configured successfully
racoon[358]: [358] INFO: 10.13.0.130[500] used as isakmp port (fd=7)
racoon[358]: [358] INFO: 10.13.0.130[4500] used as isakmp port (fd=8)
racoon[358]: [358] INFO: fe80::219:e3ff:fed3:3a67%en1[500] used as
isakmp port (fd=9)
racoon[358]: [358] INFO: fe80::219:e3ff:fed3:3a67%en1[4500] used as
isakmp port (fd=10)
racoon[358]: [358] INFO: ::1[500] used as isakmp port (fd=11)
racoon[358]: [358] INFO: ::1[4500] used as isakmp port (fd=12)
racoon[358]: [358] INFO: 127.0.0.1[500] used as isakmp port (fd=13)
racoon[358]: [358] INFO: 127.0.0.1[4500] used as isakmp port (fd=14)
racoon[358]: [358] INFO: fe80::1%lo0[500] used as isakmp port (fd=15)
racoon[358]: [358] INFO: fe80::1%lo0[4500] used as isakmp port (fd=16)
racoon[358]: [358] DEBUG: open /etc/racoon/racoon.sock as racoon
management.
racoon[358]: [358] DEBUG: opened /etc/racoon/vpncontrol.sock as racoon
management.
racoon[358]: [358] DEBUG: get pfkey X_SPDDUMP message
racoon[358]: [358] DEBUG2: \n02120200 02000000 00000000 66010000
racoon[358]: [358] DEBUG: pfkey X_SPDDUMP failed: No such file or
directory
pppd[356]: L2TP sent SCCRQ
racoon[358]: [358] NOTIFY: accepted connection on vpn control socket.
pppd[356]: IPSec connection started
racoon[358]: [358] DEBUG: get pfkey X_SPDADD message
racoon[358]: [358] DEBUG: received bind command on vpn control socket.
racoon[358]: [358] DEBUG: get pfkey X_SPDADD message
racoon[358]: [358] DEBUG: sub:0xbffff7a4: XXX.XXX.XXX.XXX/32[1701]
10.13.0.130/32[49261] proto=udp dir=in
racoon[358]: [358] DEBUG: db :0x10abc8: 10.13.0.130/32[49261]
XXX.XXX.XXX.XXX/32[1701] proto=udp dir=out
racoon[358]: [358] DEBUG: sub:0xbffff7a4: XXX.XXX.XXX.XXX/32[0]
10.13.0.130/32[49261] proto=udp dir=in
racoon[358]: [358] DEBUG: db :0x10abc8: 10.13.0.130/32[49261]
XXX.XXX.XXX.XXX/32[1701] proto=udp dir=out
racoon[358]: [358] DEBUG: sub:0xbffff7a4: XXX.XXX.XXX.XXX/32[0]
10.13.0.130/32[49261] proto=udp dir=in
racoon[358]: [358] DEBUG: db :0x10ae08: XXX.XXX.XXX.XXX/32[1701]
10.13.0.130/32[49261] proto=udp dir=in
racoon[358]: [358] DEBUG: get pfkey ACQUIRE message
racoon[358]: [358] DEBUG: suitable outbound SP found:
10.13.0.130/32[49261] XXX.XXX.XXX.XXX/32[1701] proto=udp dir=out.
racoon[358]: [358] DEBUG: sub:0xbffff790: XXX.XXX.XXX.XXX/32[1701]
10.13.0.130/32[49261] proto=udp dir=in
racoon[358]: [358] DEBUG: db :0x10abc8: 10.13.0.130/32[49261]
XXX.XXX.XXX.XXX/32[1701] proto=udp dir=out
racoon[358]: [358] DEBUG: sub:0xbffff790: XXX.XXX.XXX.XXX/32[1701]
10.13.0.130/32[49261] proto=udp dir=in
racoon[358]: [358] DEBUG: db :0x10ae08: XXX.XXX.XXX.XXX/32[1701]
10.13.0.130/32[49261] proto=udp dir=in
racoon[358]: [358] DEBUG: suitable inbound SP found:
XXX.XXX.XXX.XXX/32[1701] 10.13.0.130/32[49261] proto=udp dir=in.
racoon[358]: [358] DEBUG: new acquire 10.13.0.130/32[49261]
XXX.XXX.XXX.XXX/32[1701] proto=udp dir=out
racoon[358]: [358] DEBUG:  (proto_id=ESP spisize=4 spi=00000000
spi_p=00000000 encmode=Transport reqid=0:0)
racoon[358]: [358] DEBUG:   (trns_id=AES encklen=128 authtype=hmac-sha)
racoon[358]: [358] DEBUG:   (trns_id=AES encklen=128 authtype=hmac-md5)
racoon[358]: [358] DEBUG:   (trns_id=3DES encklen=0 authtype=hmac-sha)
racoon[358]: [358] DEBUG:   (trns_id=3DES encklen=0 authtype=hmac-md5)
racoon[358]: [358] DEBUG: configuration found for XXX.XXX.XXX.XXX.
racoon[358]: [358] INFO: IPsec-SA request for XXX.XXX.XXX.XXX queued due
to no phase1 found.
racoon[358]: [358] DEBUG: ===
racoon[358]: [358] INFO: initiate new phase 1 negotiation:
10.13.0.130[500]<=>XXX.XXX.XXX.XXX[500]
racoon[358]: [358] INFO: begin Identity Protection mode.
racoon[358]: [358] DEBUG: new cookie:\n09d0f581073d3097
racoon[358]: [358] DEBUG: add payload of len 48, next type 13
racoon[358]: [358] DEBUG: add payload of len 16, next type 13
last message repeated 9 times ---
racoon[358]: [358] DEBUG: add payload of len 16, next type 0
racoon[358]: [358] DEBUG: 300 bytes from 10.13.0.130[500] to
XXX.XXX.XXX.XXX[500]
racoon[358]: [358] DEBUG: sockname 10.13.0.130[500]
racoon[358]: [358] DEBUG: send packet from 10.13.0.130[500]
racoon[358]: [358] DEBUG: send packet to XXX.XXX.XXX.XXX[500]
racoon[358]: [358] DEBUG: 1 times of 300 bytes message will be sent to
XXX.XXX.XXX.XXX[500]
racoon[358]: [358] DEBUG: resend phase1 packet
pppd[356]: IPSec phase 1 client started
pppd[356]: IPSec connection failed
racoon[358]: [358] NOTIFY: vpn_control socket closed by peer.
racoon[358]: [358] DEBUG: 300 bytes from 10.13.0.130[500] to
XXX.XXX.XXX.XXX[500]
racoon[358]: [358] DEBUG: sockname 10.13.0.130[500]
racoon[358]: [358] DEBUG: send packet from 10.13.0.130[500]
racoon[358]: [358] DEBUG: send packet to XXX.XXX.XXX.XXX[500]
racoon[358]: [358] DEBUG: 1 times of 300 bytes message will be sent to
XXX.XXX.XXX.XXX[500]
racoon[358]: [358] DEBUG: resend phase1 packet
racoon[358]: [358] DEBUG: ==== Got HUP signal - re-parsing.
racoon[358]: [358] DEBUG: an undead schedule has been deleted.
last message repeated 1 time ---
racoon[358]: [358] DEBUG: ===== parse config
pppd[356]: Exit.
racoon[358]: [358] DEBUG: reading config file /etc/racoon/racoon.conf
racoon[358]: [358] DEBUG: filename: /etc/racoon/remote/*.conf
racoon[358]: [358] DEBUG: reading config file
/etc/racoon/remote/anonymous.conf
racoon[358]: [358] WARNING: /etc/racoon/remote/anonymous.conf:16:
"support_mip6" it is obsoleted.  use "support_proxy".
racoon[358]: [358] DEBUG2: lifetime = 60
racoon[358]: [358] DEBUG2: lifebyte = 0
racoon[358]: [358] DEBUG2: encklen=0
racoon[358]: [358] DEBUG2: p:1 t:1
racoon[358]: [358] DEBUG2: 3DES-CBC(5)
racoon[358]: [358] DEBUG2: SHA(2)
racoon[358]: [358] DEBUG2: 1024-bit MODP group(2)
racoon[358]: [358] DEBUG2: pre-shared key(1)
racoon[358]: [358] DEBUG2:
racoon[358]: [358] DEBUG: hmac(modp1024)
racoon[358]: [358] DEBUG: compression algorithm can not be checked
because sadb message doesn't support it.
racoon[358]: [358] DEBUG2: lifetime = 60
racoon[358]: [358] DEBUG2: lifebyte = 0
racoon[358]: [358] DEBUG2: encklen=0
racoon[358]: [358] DEBUG2: p:1 t:1
racoon[358]: [358] DEBUG2: 3DES-CBC(5)
racoon[358]: [358] DEBUG2: SHA(2)
racoon[358]: [358] DEBUG2: 1024-bit MODP group(2)
racoon[358]: [358] DEBUG2: pre-shared key(1)
racoon[358]: [358] DEBUG2:
racoon[358]: [358] DEBUG: hmac(modp1024)
racoon[358]: [358] DEBUG: compression algorithm can not be checked
because sadb message doesn't support it.
racoon[358]: [358] DEBUG: anonymous sainfo selected.
racoon[358]: [358] DEBUG2: parse successed.
racoon[358]: [358] DEBUG: my interface: fe80::1%lo0 (lo0)
racoon[358]: [358] DEBUG: my interface: 127.0.0.1 (lo0)
racoon[358]: [358] DEBUG: my interface: ::1 (lo0)
racoon[358]: [358] DEBUG: my interface: fe80::219:e3ff:fed3:3a67%en1
(en1)
racoon[358]: [358] DEBUG: my interface: 10.13.0.130 (en1)
racoon[358]: [358] DEBUG: configuring default isakmp port.
racoon[358]: [358] DEBUG: 10 addrs are configured successfully
racoon[358]: [358] INFO: 10.13.0.130[500] used as isakmp port (fd=7)
racoon[358]: [358] INFO: 10.13.0.130[4500] used as isakmp port (fd=8)
racoon[358]: [358] INFO: fe80::219:e3ff:fed3:3a67%en1[500] used as
isakmp port (fd=9)
racoon[358]: [358] INFO: fe80::219:e3ff:fed3:3a67%en1[4500] used as
isakmp port (fd=10)
racoon[358]: [358] INFO: ::1[500] used as isakmp port (fd=11)
racoon[358]: [358] INFO: ::1[4500] used as isakmp port (fd=12)
racoon[358]: [358] INFO: 127.0.0.1[500] used as isakmp port (fd=13)
racoon[358]: [358] INFO: 127.0.0.1[4500] used as isakmp port (fd=14)
racoon[358]: [358] INFO: fe80::1%lo0[500] used as isakmp port (fd=15)
racoon[358]: [358] INFO: fe80::1%lo0[4500] used as isakmp port (fd=16)
racoon[358]: [358] DEBUG: get pfkey X_SPDDELETE message
racoon[358]: [358] DEBUG: sub:0xbffff7a4: 10.13.0.130/32[49261]
XXX.XXX.XXX.XXX/32[1701] proto=udp dir=out
racoon[358]: [358] DEBUG: db :0x10abc8: 10.13.0.130/32[49261]
XXX.XXX.XXX.XXX/32[1701] proto=udp dir=out
racoon[358]: [358] DEBUG: get pfkey X_SPDDELETE message
--- CUT ---

For readability I've removed some hexadecimal dumps in DEBUG2 lines, and
I've "hidden" my VPN gateway's IP address with XXX.XXX.XXX.XXX

At the same time on the VPN gateway's side, I've got :

--- CUT ---
gwvpn pluto[6438]: |
gwvpn pluto[6438]: | *received 300 bytes from 202.171.78.63:33428 on eth0 (port=500)
gwvpn pluto[6438]: |  processing packet with exchange type=ISAKMP_XCHG_IDPROT (2)
gwvpn pluto[6438]: packet from 202.171.78.63:33428: received Vendor ID payload [RFC 3947] method set to=109
gwvpn pluto[6438]: packet from 202.171.78.63:33428: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike] method set to=110
gwvpn pluto[6438]: packet from 202.171.78.63:33428: ignoring unknown Vendor ID payload [8f8d83826d246b6fc7a8a6a428c11de8]
gwvpn pluto[6438]: packet from 202.171.78.63:33428: ignoring unknown Vendor ID payload [439b59f8ba676c4c7737ae22eab8f582]
gwvpn pluto[6438]: packet from 202.171.78.63:33428: ignoring unknown Vendor ID payload [4d1e0e136deafa34c4f3ea9f02ec7285]
gwvpn pluto[6438]: packet from 202.171.78.63:33428: ignoring unknown Vendor ID payload [80d0bb3def54565ee84645d4c85ce3ee]
gwvpn pluto[6438]: packet from 202.171.78.63:33428: ignoring unknown Vendor ID payload [9909b64eed937c6573de52ace952fa6b]
gwvpn pluto[6438]: packet from 202.171.78.63:33428: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but already using method 110
gwvpn pluto[6438]: packet from 202.171.78.63:33428: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but already using method 110
gwvpn pluto[6438]: packet from 202.171.78.63:33428: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using method 110
gwvpn pluto[6438]: packet from 202.171.78.63:33428: received Vendor ID payload [Dead Peer Detection]
gwvpn pluto[6438]: | instantiated "MYVPN-l2tp" for 202.171.78.63
gwvpn pluto[6438]: | creating state object #7 at 0x8864c50
gwvpn pluto[6438]: | processing connection MYVPN-l2tp[6] 202.171.78.63
gwvpn pluto[6438]: | ICOOKIE:  05 70 7c 5f  3f a4 06 b7
gwvpn pluto[6438]: | RCOOKIE:  ac 46 a8 ce  34 48 49 14
gwvpn pluto[6438]: | peer:  ca ab 4e 3f
gwvpn pluto[6438]: | state hash entry 21
gwvpn pluto[6438]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #7
gwvpn pluto[6438]: "MYVPN-l2tp"[6] 202.171.78.63 #7: responding to Main Mode from unknown peer 202.171.78.63
gwvpn pluto[6438]: | ike_alg_enc_ok(ealg=5,key_len=0): blocksize=8, keyminlen=192, keydeflen=192, keymaxlen=192, ret=1
gwvpn pluto[6438]: | complete state transition with STF_OK
gwvpn pluto[6438]: "MYVPN-l2tp"[6] 202.171.78.63 #7: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
gwvpn pluto[6438]: | sending reply packet to 202.171.78.63:33428 (from port=500)
gwvpn pluto[6438]: | sending 136 bytes for STATE_MAIN_R0 through eth0:500 to 202.171.78.63:33428:
gwvpn pluto[6438]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #7
gwvpn pluto[6438]: "MYVPN-l2tp"[6] 202.171.78.63 #7: STATE_MAIN_R1: sent MR1, expecting MI2
gwvpn pluto[6438]: | modecfg pull: noquirk policy:push not-client
gwvpn pluto[6438]: | phase 1 is done, looking for phase 1 to unpend
gwvpn pluto[6438]: | next event EVENT_RETRANSMIT in 10 seconds for #7
gwvpn pluto[6438]: |
gwvpn pluto[6438]: | *received 228 bytes from 202.171.78.63:33428 on eth0 (port=500)
gwvpn pluto[6438]: |  processing packet with exchange type=ISAKMP_XCHG_IDPROT (2)
gwvpn pluto[6438]: | ICOOKIE:  05 70 7c 5f  3f a4 06 b7
gwvpn pluto[6438]: | RCOOKIE:  ac 46 a8 ce  34 48 49 14
gwvpn pluto[6438]: | peer:  ca ab 4e 3f
gwvpn pluto[6438]: | state hash entry 21
gwvpn pluto[6438]: | peer and cookies match on #7, provided msgid 00000000 vs 00000000
gwvpn pluto[6438]: | state object #7 found, in STATE_MAIN_R1
gwvpn pluto[6438]: | processing connection MYVPN-l2tp[6] 202.171.78.63
gwvpn pluto[6438]: "MYVPN-l2tp"[6] 202.171.78.63 #7: NAT-Traversal: Result using draft-ietf-ipsec-nat-t-ike (MacOS X): peer is NATed
gwvpn pluto[6438]: | inserting event EVENT_NAT_T_KEEPALIVE, timeout in 20 seconds
gwvpn pluto[6438]: | helper -1 doing build_kenonce op id: 0
gwvpn pluto[6438]: | processing connection MYVPN-l2tp[6] 202.171.78.63
gwvpn pluto[6438]: | started looking for secret for @gwvpn.example.com->202.171.78.63 of kind PPK_PSK
gwvpn pluto[6438]: | instantiating him to 0.0.0.0
gwvpn pluto[6438]: | actually looking for secret for @gwvpn.example.com->0.0.0.0 of kind PPK_PSK
gwvpn pluto[6438]: | concluding with best_match=0 best=(nil) (lineno=-1)
gwvpn pluto[6438]: | complete state transition with STF_OK
gwvpn pluto[6438]: "MYVPN-l2tp"[6] 202.171.78.63 #7: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
gwvpn pluto[6438]: | sending reply packet to 202.171.78.63:33428 (from port=500)
gwvpn pluto[6438]: | sending 428 bytes for STATE_MAIN_R1 through eth0:500 to 202.171.78.63:33428:
gwvpn pluto[6438]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #7
gwvpn pluto[6438]: "MYVPN-l2tp"[6] 202.171.78.63 #7: STATE_MAIN_R2: sent MR2, expecting MI3
gwvpn pluto[6438]: | modecfg pull: noquirk policy:push not-client
gwvpn pluto[6438]: | phase 1 is done, looking for phase 1 to unpend
gwvpn pluto[6438]: | complete state transition with STF_INLINE
gwvpn pluto[6438]: | next event EVENT_RETRANSMIT in 10 seconds for #7
gwvpn pluto[6438]: |
gwvpn pluto[6438]: | *time to handle event
gwvpn pluto[6438]: | handling event EVENT_RETRANSMIT
gwvpn pluto[6438]: | event after this is EVENT_NAT_T_KEEPALIVE in 10 seconds
gwvpn pluto[6438]: | processing connection MYVPN-l2tp[6] 202.171.78.63
gwvpn pluto[6438]: | handling event EVENT_RETRANSMIT for 202.171.78.63 "MYVPN-l2tp" #7
gwvpn pluto[6438]: | sending 428 bytes for EVENT_RETRANSMIT through eth0:500 to 202.171.78.63:33428:
gwvpn pluto[6438]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #7
gwvpn pluto[6438]: | next event EVENT_NAT_T_KEEPALIVE in 10 seconds
--- CUT ---

Any idea what could be wrong ? (I don't know MacOSX much unfortunately)

Thanks in advance

Jerome Alet

More information about the Users mailing list