[Openswan Users] IPSec seems to be working but could my config be upsetting pppd?

Errol Chevannes errol at malooba.com
Thu Jan 13 10:50:00 EST 2011 

Hi

I have been following various openswan tutorials but I am having trouble connecting a MacBookPro from home to an Amazon EC2 instance running openswan on Ubuntu 9.10. 

Everything seems to work, even after pppd authenticates using CHAP, but then pppd fails and the whole thing collapses.

From the logs it looks like the problem is caused by pppd rejecting Config requests for ip address 0.0.0.0 so the MacBookPro gives up after 255 tries (about 20 secs).

I was wondering (hoping) if the error could be caused by a config mistake I had made higher up the chain, although it seems that the MacBookPro is asking for something that doesn't make sense.

Could anyone here either confirm or condemn my config please? 

Any suggestions as to what to try next are really appreciated! (Next stop at the moment is reading the RFCs for PPP to figure out what the pppd messages mean)

I will be lurking in #openswan as bez.

Thanks, 

Errol

================================================
Amazon EC2 Instance
================================================
Linux Openswan U2.6.32/K2.6.35-24-virtual (netkey). Built from source (previously used 2.6.26 installed via apt-get with same results)
xl2tpd-1.2.6 (installed via apt-get)
pppd version 2.4.5
79.125.29.128 (public ip)
10.234.143.162 (private ip) 


================================================
Home
================================================
81.135.116.167 (public ip)
192.168.1.1 - 192.168.1.10 (iPhone/MacBookPro etc, via dhcp)


================================================
/etc/ipsec.conf
================================================
version 2.0     # conforms to second version of ipsec.conf specification

config setup
        nat_traversal=yes
        virtual_private=%v4:10.0.0.0/8,%v4:192.168.0.0/16,%v4:172.16.0.0/12,%v4:!10.234.143.0/24
        oe=off
        protostack=netkey

conn L2TP-PSK-NAT
        rightsubnet=vhost:%priv   
        also=L2TP-PSK-noNAT

conn L2TP-PSK-noNAT
        authby=secret
        pfs=no
        auto=add
        keyingtries=3
        rekey=no
        ikelifetime=8h
        keylife=1h
        type=transport
        left=%defaultroute	
        leftprotoport=17/1701
        right=%any
        rightprotoport=17/%any
        #forceencaps=yes


================================================
/etc/ipsec.secrets
================================================
%any     %any : PSK     "secret"


================================================
/etc/xl2tpd/xl2tpd.conf
================================================
[global]
debug avp=yes
debug network=yes
debug packet=yes
debug state=yes
debug tunnel=yes

[lns default]
ip range = 10.234.143.100 - 10.234.143.150      ; * Allocate from this IP range
local ip = 10.234.143.99                        ; * Our local IP to use
length bit = yes                                ; * Use length bit in payload?
require chap = yes                              ; * Require CHAP auth. by peer
refuse pap = yes                                ; * Refuse PAP authentication
require authentication = yes                    ; * Require peer to authenticate
name = l2tpsvr                                  ; * Report this as our hostname
ppp debug = yes                                 ; * Turn on PPP debugging
pppoptfile = /etc/ppp/options.xl2tpd            ; * ppp options file


================================================
/etc/ppp/options.xl2tpd
================================================
require-mschap-v2
debug
asyncmap 0
modem
ms-dns 172.16.0.23
auth
crtscts
lock
proxyarp
name l2tpd
lcp-echo-interval 30
lcp-echo-failure 4
hide-password


================================================
/etc/ppp/chaps-secrets
================================================
test    *       "password"      *
*       test    "password"      *



================================================
ipsec verify
================================================
Checking your system to see if IPsec got installed and started correctly:
Version check and ipsec on-path                             	[OK]
Linux Openswan U2.6.32/K2.6.35-24-virtual (netkey)
Checking for IPsec support in kernel                        	[OK]
 SAref kernel support                                       	[N/A]
 NETKEY:  Testing for disabled ICMP send_redirects          	[OK]
NETKEY detected, testing for disabled ICMP accept_redirects 	[OK]
Checking that pluto is running                              	[OK]
 Pluto listening for IKE on udp 500                         	[OK]
 Pluto listening for NAT-T on udp 4500                      	[OK]
Checking for 'ip' command                                   	[OK]
Checking /bin/sh is not /bin/dash                           	[WARNING]
Checking for 'iptables' command                             	[OK]
Opportunistic Encryption Support                            	[DISABLED]


================================================
tail -f /var/log/auth.log | grep pluto
================================================
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: packet from 81.135.116.167:500: received Vendor ID payload [RFC 3947] method set to=109 
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: packet from 81.135.116.167:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike] method set to=110 
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: packet from 81.135.116.167:500: ignoring unknown Vendor ID payload [8f8d83826d246b6fc7a8a6a428c11de8]
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: packet from 81.135.116.167:500: ignoring unknown Vendor ID payload [439b59f8ba676c4c7737ae22eab8f582]
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: packet from 81.135.116.167:500: ignoring unknown Vendor ID payload [4d1e0e136deafa34c4f3ea9f02ec7285]
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: packet from 81.135.116.167:500: ignoring unknown Vendor ID payload [80d0bb3def54565ee84645d4c85ce3ee]
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: packet from 81.135.116.167:500: ignoring unknown Vendor ID payload [9909b64eed937c6573de52ace952fa6b]
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: packet from 81.135.116.167:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but already using method 110
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: packet from 81.135.116.167:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but already using method 110
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: packet from 81.135.116.167:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using method 110
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: packet from 81.135.116.167:500: received Vendor ID payload [Dead Peer Detection]
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[1] 81.135.116.167 #1: responding to Main Mode from unknown peer 81.135.116.167
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[1] 81.135.116.167 #1: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[1] 81.135.116.167 #1: STATE_MAIN_R1: sent MR1, expecting MI2
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[1] 81.135.116.167 #1: NAT-Traversal: Result using draft-ietf-ipsec-nat-t-ike (MacOS X): both are NATed
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[1] 81.135.116.167 #1: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Jan 13 14:30:14 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[1] 81.135.116.167 #1: STATE_MAIN_R2: sent MR2, expecting MI3
Jan 13 14:30:15 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[1] 81.135.116.167 #1: Main mode peer ID is ID_IPV4_ADDR: '192.168.1.3'
Jan 13 14:30:15 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[1] 81.135.116.167 #1: switched from "L2TP-PSK-NAT" to "L2TP-PSK-NAT"
Jan 13 14:30:15 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #1: deleting connection "L2TP-PSK-NAT" instance with peer 81.135.116.167 {isakmp=#0/ipsec=#0}
Jan 13 14:30:15 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #1: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Jan 13 14:30:15 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #1: new NAT mapping for #1, was 81.135.116.167:500, now 81.135.116.167:4500
Jan 13 14:30:15 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #1: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp1024}
Jan 13 14:30:15 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #1: ignoring informational payload, type IPSEC_INITIAL_CONTACT msgid=00000000
Jan 13 14:30:15 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #1: received and ignored informational message
Jan 13 14:30:16 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #1: the peer proposed: 79.125.29.128/32:17/1701 -> 192.168.1.3/32:17/0
Jan 13 14:30:16 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #2: responding to Quick Mode proposal {msgid:9d4424b5}
Jan 13 14:30:16 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #2:     us: 10.234.143.162[+S=C]:17/1701
Jan 13 14:30:16 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #2:   them: 81.135.116.167[192.168.1.3,+S=C]:17/64047===192.168.1.3/32
Jan 13 14:30:16 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #2: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
Jan 13 14:30:16 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #2: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
Jan 13 14:30:16 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #2: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
Jan 13 14:30:16 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #2: STATE_QUICK_R2: IPsec SA established transport mode {ESP=>0x08f29000 <0x572102c3 xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=81.135.116.167:4500 DPD=none}
Jan 13 14:30:34 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #1: received Delete SA(0x08f29000) payload: deleting IPSEC State #2
Jan 13 14:30:34 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #1: ERROR: netlink XFRM_MSG_DELPOLICY response for flow eroute_connection delete included errno 2: No such file or directory
Jan 13 14:30:34 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #1: received and ignored informational message
Jan 13 14:30:34 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167 #1: received Delete SA payload: deleting ISAKMP State #1
Jan 13 14:30:34 ip-10-234-143-162 pluto[28916]: "L2TP-PSK-NAT"[2] 81.135.116.167: deleting connection "L2TP-PSK-NAT" instance with peer 81.135.116.167 {isakmp=#0/ipsec=#0}
Jan 13 14:30:34 ip-10-234-143-162 pluto[28916]: packet from 81.135.116.167:4500: received and ignored informational message
Jan 13 14:30:35 ip-10-234-143-162 pluto[28916]: initiate on demand from 10.234.143.162:1701 to 81.135.116.167:64047 proto=17 state: fos_start because: acquire



================================================
tail -f /var/log/syslog | grep 'pluto\|xl2tpd\|pppd'
================================================
Jan 13 14:25:06 ip-10-234-143-162 xl2tpd[28954]: xl2tpd version xl2tpd-1.2.6 started on ip-10-234-143-162 PID:28954
Jan 13 14:25:06 ip-10-234-143-162 xl2tpd[28954]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc.
Jan 13 14:25:06 ip-10-234-143-162 xl2tpd[28954]: Forked by Scott Balmos and David Stipp, (C) 2001
Jan 13 14:25:06 ip-10-234-143-162 xl2tpd[28954]: Inherited by Jeff McAdams, (C) 2002
Jan 13 14:25:06 ip-10-234-143-162 xl2tpd[28954]: Forked again by Xelerance (www.xelerance.com) (C) 2006
Jan 13 14:25:06 ip-10-234-143-162 xl2tpd[28954]: Listening on IP address 0.0.0.0, port 1701
Jan 13 14:30:16 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 60, tunnel = 0, call = 0 ref=0 refhim=0
Jan 13 14:30:16 ip-10-234-143-162 xl2tpd[28954]: get_call: allocating new tunnel for host 81.135.116.167, port 64047.
Jan 13 14:30:16 ip-10-234-143-162 xl2tpd[28954]: handle_avps: handling avp's for tunnel 42125, call 0
Jan 13 14:30:16 ip-10-234-143-162 xl2tpd[28954]: message_type_avp: message type 1 (Start-Control-Connection-Request)
Jan 13 14:30:16 ip-10-234-143-162 xl2tpd[28954]: protocol_version_avp: peer is using version 1, revision 0.
Jan 13 14:30:16 ip-10-234-143-162 xl2tpd[28954]: framing_caps_avp: supported peer frames: async sync
Jan 13 14:30:16 ip-10-234-143-162 xl2tpd[28954]: hostname_avp: peer reports hostname ''
Jan 13 14:30:16 ip-10-234-143-162 xl2tpd[28954]: assigned_tunnel_avp: using peer's tunnel 1
Jan 13 14:30:16 ip-10-234-143-162 xl2tpd[28954]: receive_window_size_avp: peer wants RWS of 4.  Will use flow control.
Jan 13 14:30:16 ip-10-234-143-162 xl2tpd[28954]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 1, call is 0.
Jan 13 14:30:16 ip-10-234-143-162 xl2tpd[28954]: control_finish: sending SCCRP
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 60, tunnel = 0, call = 0 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: get_call: allocating new tunnel for host 81.135.116.167, port 64047.
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: handle_avps: handling avp's for tunnel 19030, call 0
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: message_type_avp: message type 1 (Start-Control-Connection-Request)
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: protocol_version_avp: peer is using version 1, revision 0.
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: framing_caps_avp: supported peer frames: async sync
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: hostname_avp: peer reports hostname ''
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: assigned_tunnel_avp: using peer's tunnel 1
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: receive_window_size_avp: peer wants RWS of 4.  Will use flow control.
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 1, call is 0.
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: control_finish: Peer requested tunnel 1 twice, ignoring second one.
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: build_fdset: closing down tunnel 19030
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 20, tunnel = 42125, call = 0 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: handle_avps: handling avp's for tunnel 42125, call 0
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: message_type_avp: message type 3 (Start-Control-Connection-Connected)
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: control_finish: message type is Start-Control-Connection-Connected(3).  Tunnel is 1, call is 0.
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: Connection established to 81.135.116.167, 64047.  Local: 42125, Remote: 1 (ref=0/0).  LNS session is 'default'
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 38, tunnel = 42125, call = 0 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: handle_avps: handling avp's for tunnel 42125, call 0
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: message_type_avp: message type 10 (Incoming-Call-Request)
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: message_type_avp: new incoming call
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: assigned_call_avp: using peer's call 345
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: call_serno_avp: serial number is 1
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: control_finish: message type is Incoming-Call-Request(10).  Tunnel is 1, call is 0.
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: control_finish: Sending ICRP
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 40, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: handle_avps: handling avp's for tunnel 42125, call 363
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: message_type_avp: message type 12 (Incoming-Call-Connected)
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: tx_speed_avp: transmit baud rate is 1000000
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: frame_type_avp: peer uses: async frames
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: control_finish: message type is Incoming-Call-Connected(12).  Tunnel is 1, call is 345.
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: start_pppd: I'm running: 
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: "/usr/sbin/pppd" 
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: "passive" 
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: "nodetach" 
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: "10.234.143.99:0.0.0.0" 
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: "refuse-pap" 
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: "auth" 
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: "require-chap" 
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: "name" 
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: "l2tpsvr" 
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: "debug" 
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: "file" 
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: "/etc/ppp/options.xl2tpd" 
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: "/dev/pts/3" 
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: Call established with 81.135.116.167, Local: 363, Remote: 345, Serial: 1
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: pppd 2.4.5 started by root, uid 0
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: using channel 50
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: Using interface ppp0
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: Connect: ppp0 <--> /dev/pts/3
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MD5> <magic 0xc432f2fb> <pcomp> <accomp>]
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 32, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x755e9e54> <pcomp> <accomp>]
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x755e9e54> <pcomp> <accomp>]
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 37, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <auth chap MD5> <magic 0xc432f2fb> <pcomp> <accomp>]
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: sent [LCP EchoReq id=0x0 magic=0xc432f2fb]
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: sent [CHAP Challenge id=0x42 <4a7ab0578b7f481338418991871b7b931475f1>, name = "l2tpd"]
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 20, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: rcvd [LCP EchoReq id=0x0 magic=0x755e9e54]
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: sent [LCP EchoRep id=0x0 magic=0xc432f2fb]
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 20, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: rcvd [LCP EchoRep id=0x0 magic=0x755e9e54]
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 35, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: rcvd [CHAP Response id=0x42 <3d0692f9fa82bddec82dc1502215a644>, name = "test"]
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: sent [CHAP Success id=0x42 "Access granted"]
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 10.234.143.99>]
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 32, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 24, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: rcvd [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: sent [IPCP ConfRej id=0x1 <addr 0.0.0.0>]
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: rcvd [IPV6CP ConfReq id=0x1 <addr fe80::021f:f3ff:fe4e:6ee7>]
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: Unsupported protocol 'IPv6 Control Protovol' (0x8057) received
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: sent [LCP ProtRej id=0x2 80 57 01 01 00 0e 01 0a 02 1f f3 ff fe 4e 6e e7]
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 33, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: rcvd [LCP ProtRej id=0x2 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 20, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: sent [IPCP ConfReq id=0x2 <addr 10.234.143.99>]
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 36, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: rcvd [IPCP ConfReq id=0x2 <addrs 0.0.0.0 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: sent [IPCP ConfRej id=0x2 <addrs 0.0.0.0 0.0.0.0>]
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 20, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: rcvd [IPCP ConfAck id=0x2 <addr 10.234.143.99>]
Jan 13 14:30:18 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 36, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: rcvd [IPCP ConfReq id=0x3 <addrs 0.0.0.0 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Jan 13 14:30:18 ip-10-234-143-162 pppd[28981]: sent [IPCP ConfRej id=0x3 <addrs 0.0.0.0 0.0.0.0>]

<snip>
	THESE MESSAGES REPEAT A FEW HUNDRED TIMES WITH ONLY THE 'ConfReq id=' number changing. 
</snip>


Jan 13 14:30:33 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 36, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:33 ip-10-234-143-162 pppd[28981]: rcvd [IPCP ConfReq id=0xfd <addrs 0.0.0.0 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Jan 13 14:30:33 ip-10-234-143-162 pppd[28981]: sent [IPCP ConfRej id=0xfd <addrs 0.0.0.0 0.0.0.0>]
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 36, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:34 ip-10-234-143-162 pppd[28981]: rcvd [IPCP ConfReq id=0xfe <addrs 0.0.0.0 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Jan 13 14:30:34 ip-10-234-143-162 pppd[28981]: sent [IPCP ConfRej id=0xfe <addrs 0.0.0.0 0.0.0.0>]
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 36, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:34 ip-10-234-143-162 pppd[28981]: rcvd [IPCP ConfReq id=0xff <addrs 0.0.0.0 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Jan 13 14:30:34 ip-10-234-143-162 pppd[28981]: sent [IPCP ConfRej id=0xff <addrs 0.0.0.0 0.0.0.0>]
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 44, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:34 ip-10-234-143-162 pppd[28981]: rcvd [LCP TermReq id=0x3 "No network protocols running"]
Jan 13 14:30:34 ip-10-234-143-162 pppd[28981]: LCP terminated by peer (No network protocols running)
Jan 13 14:30:34 ip-10-234-143-162 pppd[28981]: sent [LCP TermAck id=0x3]
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 42, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: handle_avps: handling avp's for tunnel 42125, call 363
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: message_type_avp: message type 14 (Call-Disconnect-Notify)
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: assigned_call_avp: using peer's call 345
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: result_code_avp: result code out of range (768 0 14).  Ignoring.
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: control_finish: message type is Call-Disconnect-Notify(14).  Tunnel is 1, call is 345.
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: control_finish: Peer tried to disconnect without specifying result code.
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: network_thread: bad packet
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 42, tunnel = 42125, call = 0 ref=0 refhim=0
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: handle_avps: handling avp's for tunnel 42125, call 0
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: message_type_avp: message type 4 (Stop-Control-Connection-Notification)
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: assigned_tunnel_avp: using peer's tunnel 1
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: result_code_avp: result code out of range (256 0 14).  Ignoring.
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: control_finish: message type is Stop-Control-Connection-Notification(4).  Tunnel is 1, call is 0.
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: control_finish: Peer tried to disconnect without specifying result code.
Jan 13 14:30:34 ip-10-234-143-162 xl2tpd[28954]: network_thread: bad packet
Jan 13 14:30:35 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 42, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:35 ip-10-234-143-162 xl2tpd[28954]: check_control: Received out of order control packet on tunnel 1 (got 4, expected 6)
Jan 13 14:30:35 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Invalid argument
Jan 13 14:30:35 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Invalid argument
Jan 13 14:30:35 ip-10-234-143-162 xl2tpd[28954]: handle_packet: bad control packet!
Jan 13 14:30:35 ip-10-234-143-162 xl2tpd[28954]: network_thread: bad packet
Jan 13 14:30:37 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 42, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:37 ip-10-234-143-162 xl2tpd[28954]: check_control: Received out of order control packet on tunnel 1 (got 4, expected 6)
Jan 13 14:30:37 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:37 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:37 ip-10-234-143-162 xl2tpd[28954]: handle_packet: bad control packet!
Jan 13 14:30:37 ip-10-234-143-162 xl2tpd[28954]: network_thread: bad packet
Jan 13 14:30:37 ip-10-234-143-162 pppd[28981]: Connection terminated.
Jan 13 14:30:37 ip-10-234-143-162 pppd[28981]: Connect time 0.3 minutes.
Jan 13 14:30:37 ip-10-234-143-162 pppd[28981]: Sent 3657 bytes, received 6710 bytes.
Jan 13 14:30:37 ip-10-234-143-162 pppd[28981]: Modem hangup
Jan 13 14:30:37 ip-10-234-143-162 pppd[28981]: Exit.
Jan 13 14:30:37 ip-10-234-143-162 xl2tpd[28954]: child_handler : pppd exited for call 345 with code 16
Jan 13 14:30:37 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:37 ip-10-234-143-162 xl2tpd[28954]: call_close: Call 363 to 81.135.116.167 disconnected
Jan 13 14:30:38 ip-10-234-143-162 xl2tpd[28954]: network_thread: select timeout
Jan 13 14:30:38 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:39 ip-10-234-143-162 xl2tpd[28954]: network_thread: select timeout
Jan 13 14:30:39 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:40 ip-10-234-143-162 xl2tpd[28954]: network_thread: select timeout
Jan 13 14:30:40 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:41 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 42, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:41 ip-10-234-143-162 xl2tpd[28954]: check_control: Received out of order control packet on tunnel 1 (got 4, expected 6)
Jan 13 14:30:41 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:41 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:41 ip-10-234-143-162 xl2tpd[28954]: handle_packet: bad control packet!
Jan 13 14:30:41 ip-10-234-143-162 xl2tpd[28954]: network_thread: bad packet
Jan 13 14:30:41 ip-10-234-143-162 xl2tpd[28954]: network_thread: select timeout
Jan 13 14:30:41 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:42 ip-10-234-143-162 xl2tpd[28954]: network_thread: select timeout
Jan 13 14:30:42 ip-10-234-143-162 xl2tpd[28954]: Maximum retries exceeded for tunnel 42125.  Closing.
Jan 13 14:30:49 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 42, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:49 ip-10-234-143-162 xl2tpd[28954]: check_control: Received out of order control packet on tunnel 1 (got 4, expected 6)
Jan 13 14:30:49 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:49 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:49 ip-10-234-143-162 xl2tpd[28954]: handle_packet: bad control packet!
Jan 13 14:30:49 ip-10-234-143-162 xl2tpd[28954]: network_thread: bad packet
Jan 13 14:30:49 ip-10-234-143-162 xl2tpd[28954]: build_fdset: closing down tunnel 42125
Jan 13 14:30:49 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:49 ip-10-234-143-162 xl2tpd[28954]: Terminating pppd: sending TERM signal to pid 28981
Jan 13 14:30:49 ip-10-234-143-162 xl2tpd[28954]: pppd 28981 successfully terminated
Jan 13 14:30:49 ip-10-234-143-162 xl2tpd[28954]: Connection 1 closed to 81.135.116.167, port 64047 (Timeout)
Jan 13 14:30:50 ip-10-234-143-162 xl2tpd[28954]: network_thread: select timeout
Jan 13 14:30:50 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:51 ip-10-234-143-162 xl2tpd[28954]: network_thread: select timeout
Jan 13 14:30:51 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:52 ip-10-234-143-162 xl2tpd[28954]: network_thread: select timeout
Jan 13 14:30:52 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:53 ip-10-234-143-162 xl2tpd[28954]: network_thread: select timeout
Jan 13 14:30:53 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:54 ip-10-234-143-162 xl2tpd[28954]: network_thread: select timeout
Jan 13 14:30:54 ip-10-234-143-162 xl2tpd[28954]: Unable to deliver closing message for tunnel 42125. Destroying anyway.
Jan 13 14:30:57 ip-10-234-143-162 xl2tpd[28954]: network_thread: recv packet from 81.135.116.167, size = 42, tunnel = 42125, call = 363 ref=0 refhim=0
Jan 13 14:30:57 ip-10-234-143-162 xl2tpd[28954]: get_call: can't find call 363 in tunnel 42125#012 (ref=0/0)
Jan 13 14:30:57 ip-10-234-143-162 xl2tpd[28954]: network_thread: no such call 12282 on tunnel 0.  Sending special ZLB
Jan 13 14:30:57 ip-10-234-143-162 xl2tpd[28954]: check_control: Received out of order control packet on tunnel 1 (got 4, expected 6)
Jan 13 14:30:57 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:57 ip-10-234-143-162 xl2tpd[28954]: udp_xmit failed with err=-1:Operation not permitted
Jan 13 14:30:57 ip-10-234-143-162 xl2tpd[28954]: handle_special: invalid control packet
Jan 13 14:30:57 ip-10-234-143-162 xl2tpd[28954]: build_fdset: closing down tunnel 42125



================================================
tail -f /var/log/system.log (on the MacBookPro)
================================================
Jan 13 14:30:20 kingston2 pppd[345]: pppd 2.4.2 (Apple version 412.3) started by errolc, uid 501
Jan 13 14:30:20 kingston2 pppd[345]: L2TP connecting to server '79.125.29.128' (79.125.29.128)...
Jan 13 14:30:20 kingston2 pppd[345]: IPSec connection started
Jan 13 14:30:20 kingston2 racoon[348]: Connecting.
Jan 13 14:30:20 kingston2 racoon[348]: IKE Packet: transmit success. (Initiator, Main-Mode message 1).
Jan 13 14:30:20 kingston2 racoon[348]: IKE Packet: receive success. (Initiator, Main-Mode message 2).
Jan 13 14:30:20 kingston2 racoon[348]: IKE Packet: transmit success. (Initiator, Main-Mode message 3).
Jan 13 14:30:21 kingston2 racoon[348]: IKE Packet: receive success. (Initiator, Main-Mode message 4).
Jan 13 14:30:21 kingston2 racoon[348]: IKE Packet: transmit success. (Initiator, Main-Mode message 5).
Jan 13 14:30:21 kingston2 racoon[348]: IKEv1 Phase1 AUTH: success. (Initiator, Main-Mode Message 6).
Jan 13 14:30:21 kingston2 racoon[348]: IKE Packet: receive success. (Initiator, Main-Mode message 6).
Jan 13 14:30:21 kingston2 racoon[348]: IKEv1 Phase1 Initiator: success. (Initiator, Main-Mode).
Jan 13 14:30:21 kingston2 racoon[348]: IKE Packet: transmit success. (Information message).
Jan 13 14:30:21 kingston2 racoon[348]: IKEv1 Information-Notice: transmit success. (ISAKMP-SA).
Jan 13 14:30:22 kingston2 racoon[348]: IKE Packet: transmit success. (Initiator, Quick-Mode message 1).
Jan 13 14:30:22 kingston2 racoon[348]: IKE Packet: receive success. (Initiator, Quick-Mode message 2).
Jan 13 14:30:22 kingston2 racoon[348]: IKE Packet: transmit success. (Initiator, Quick-Mode message 3).
Jan 13 14:30:22 kingston2 racoon[348]: IKEv1 Phase2 Initiator: success. (Initiator, Quick-Mode).
Jan 13 14:30:22 kingston2 racoon[348]: Connected.
Jan 13 14:30:22 kingston2 pppd[345]: IPSec connection established
Jan 13 14:30:24 kingston2 pppd[345]: L2TP connection established.
Jan 13 14:30:24 kingston2 pppd[345]: Connect: ppp0 <--> socket[34:18]
Jan 13 14:30:40 kingston2 pppd[345]: IPCP: Maximum Config-Requests exceeded
Jan 13 14:30:40 kingston2 pppd[345]: Connection terminated.
Jan 13 14:30:40 kingston2 pppd[345]: L2TP disconnecting...
Jan 13 14:30:40 kingston2 pppd[345]: L2TP disconnected
Jan 13 14:30:40 kingston2 configd[19]: SCNCController: Disconnecting. (Connection tried to negotiate for, 20 seconds).
Jan 13 14:30:40 kingston2 racoon[348]: IKE Packet: transmit success. (Information message).
Jan 13 14:30:40 kingston2 racoon[348]: IKEv1 Information-Notice: transmit success. (Delete IPSEC-SA).
Jan 13 14:30:40 kingston2 racoon[348]: IKE Packet: transmit success. (Information message).
Jan 13 14:30:40 kingston2 racoon[348]: IKEv1 Information-Notice: transmit success. (Delete ISAKMP-SA).
Jan 13 14:30:41 kingston2 racoon[348]: Disconnecting. (Connection was up for, 19.095722 seconds).

More information about the Users mailing list