[Openswan Users] Please help: strange behaviour with OpenSwan/xl2tpd & Android vpn client
John Wells
jfw at jfwhome.com
Thu Apr 15 02:36:31 EDT 2010
Hello,
Trying to set up openSwan on Ubuntu 9.10 (Linode VPS) to talk to the
android 2.1 IPSec/L2TP VPN client using PSK.
I think I'm 99% there, but no cigar. The handset is almost invariably
behind NAT -- whether on a cellular network or on Wifi. However, the server
has a public IP address.
I'm using xl2tpd for LT2P. It seems to establish a connection OK (it calls
/etc/ppp/ip-up) , but it only lasts an instant before closing down.
Occasionally the handset shows "connected" for an instant.
If I set one of the protoports in ipsec.conf to 17/%any intead of 17/1701,
the reverse seems to occur: auth.log shows a successful IPSec connection,
but xl2tpd doesn't seem to get any messages through back to the handset --
it just keeps responding to tunnel open requests. The same behaviour occurs
over wifi & cellular network.
My aim is simply to allow the handset to route traffic to the internet. I
have attached all relevant info & logs below. Any help or hints would be
much appreciated -- I foreseee this will be a very popular setup with
android handsets proliferating the market, and I will write up a howto once
I have it up and running myself.
I see the following output in /var/log/auth/log:
Apr 15 12:43:19 jfwvps pluto[20702]: packet from 117.136.8.199:17204:
received Vendor ID payload [RFC 3947] method set to=109
Apr 15 12:43:19 jfwvps pluto[20702]: packet from 117.136.8.199:17204:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but
already using method 109
Apr 15 12:43:19 jfwvps pluto[20702]: packet from 117.136.8.199:17204:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but
already using method 109
Apr 15 12:43:19 jfwvps pluto[20702]: packet from 117.136.8.199:17204:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]
Apr 15 12:43:19 jfwvps pluto[20702]: packet from 117.136.8.199:17204:
ignoring Vendor ID payload [FRAGMENTATION 80000000]
Apr 15 12:43:19 jfwvps pluto[20702]: "PSK"[1] 117.136.8.199 #1: responding
to Main Mode from unknown peer 117.136.8.199
Apr 15 12:43:19 jfwvps pluto[20702]: "PSK"[1] 117.136.8.199 #1: transition
from state STATE_MAIN_R0 to state STATE_MAIN_R1
Apr 15 12:43:19 jfwvps pluto[20702]: "PSK"[1] 117.136.8.199 #1:
STATE_MAIN_R1: sent MR1, expecting MI2
Apr 15 12:43:20 jfwvps pluto[20702]: "PSK"[1] 117.136.8.199 #1:
NAT-Traversal: Result using RFC 3947 (NAT-Traversal): peer is NATed
Apr 15 12:43:20 jfwvps pluto[20702]: "PSK"[1] 117.136.8.199 #1: transition
from state STATE_MAIN_R1 to state STATE_MAIN_R2
Apr 15 12:43:20 jfwvps pluto[20702]: "PSK"[1] 117.136.8.199 #1:
STATE_MAIN_R2: sent MR2, expecting MI3
Apr 15 12:43:20 jfwvps pluto[20702]: "PSK"[1] 117.136.8.199 #1: Main mode
peer ID is ID_IPV4_ADDR: '10.79.92.135'
Apr 15 12:43:20 jfwvps pluto[20702]: "PSK"[1] 117.136.8.199 #1: switched
from "PSK" to "PSK"
Apr 15 12:43:20 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1: deleting
connection "PSK" instance with peer 117.136.8.199 {isakmp=#0/ipsec=#0}
Apr 15 12:43:20 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1: transition
from state STATE_MAIN_R2 to state STATE_MAIN_R3
Apr 15 12:43:20 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1: new NAT
mapping for #1, was 117.136.8.199:17204, now 117.136.8.199:17214
Apr 15 12:43:20 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1:
STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY
cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp1024}
Apr 15 12:43:21 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1: ignoring
informational payload, type IPSEC_INITIAL_CONTACT msgid=00000000
Apr 15 12:43:21 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1: received
and ignored informational message
Apr 15 12:43:22 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1: the peer
proposed: 11.22.33.44/32:17/1701 -> 10.79.92.135/32:17/1701
Apr 15 12:43:22 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1: cannot
respond to IPsec SA request because no connection is known for
11.22.33.44<11.22.33.44>[+S=C]:17/1701...117.136.8.199[10.79.92.135,+S=C]:17/0===10.79.92.135/32
Apr 15 12:43:22 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1: sending
encrypted notification INVALID_ID_INFORMATION to 117.136.8.199:17214
Apr 15 12:43:32 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1: the peer
proposed: 11.22.33.44/32:17/1701 -> 10.79.92.135/32:17/1701
Apr 15 12:43:32 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1: cannot
respond to IPsec SA request because no connection is known for
11.22.33.44<11.22.33.44>[+S=C]:17/1701...117.136.8.199[10.79.92.135,+S=C]:17/0===10.79.92.135/32
Apr 15 12:43:32 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1: sending
encrypted notification INVALID_ID_INFORMATION to 117.136.8.199:17214
Apr 15 12:43:42 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1: the peer
proposed: 11.22.33.44/32:17/1701 -> 10.79.92.135/32:17/1701
Apr 15 12:43:42 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1: cannot
respond to IPsec SA request because no connection is known for
11.22.33.44<11.22.33.44>[+S=C]:17/1701...117.136.8.199[10.79.92.135,+S=C]:17/0===10.79.92.135/32
Apr 15 12:43:42 jfwvps pluto[20702]: "PSK"[2] 117.136.8.199 #1: sending
encrypted notification INVALID_ID_INFORMATION to 117.136.8.199:17214
ipsec --version :
Linux Openswan U2.6.22/K2.6.32-linode23 (netkey)
My configuration files are as follows:
------ /etc/ipsec.conf: ----------
version 2.0
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
oe=off
protostack=netkey
conn PSK
rightsubnet=vhost:%no,%priv
also=L2TP-PSK-noNAT
conn L2TP-PSK-noNAT
left=11.22.33.44
#leftnexthop=%defaultroute
authby=secret
pfs=no
auto=add
keyingtries=3
rekey=no
type=transport
leftprotoport=17/1701
rightprotoport=17/1701
right=%any
-------- /etc/xl2tpd/xl2tpd.conf: ----------
[global]
auth file = /etc/xl2tpd/l2tp-secrets
debug tunnel = yes
debug avp = yes
debug packet = yes
debug network = yes
debug state = yes
[lns default]
exclusive = no
ip range = 10.0.0.2-10.0.0.5
local ip = 10.0.0.1
length bit = yes
refuse pap = yes
require authentication = yes
ppp debug = yes
pppoptfile = /etc/ppp/options.xl2tpd
------- /etc/ppp/options.xl2tpd: -------------
require-mschap-v2
nobsdcomp
ms-dns 8.8.8.8
ms-dns 8.8.4.4
asyncmap 0
auth
crtscts
lock
hide-password
modem
mru 1400
mtu 1400
debug
name jfwvip
proxyarp
lcp-echo-interval 30
lcp-echo-failure 4
ipcp-accept-local
ipcp-accept-remote
noipx
I also did the following to try to route the traffic to the internet --
this probably won't work yet, but I assume that the first step is getting
the tunnel up at all.
iptables -t nat -A POSTROUTING -s 10.0.0.0/24 -o eth0 -j MASQUERADE
In case it helps, here is the debug output from xl2tpd & ppp.
Apr 15 12:41:29 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 107, tunnel = 0, call = 0 ref=0 refhim=0
Apr 15 12:41:29 jfwvps xl2tpd[12855]: get_call: allocating new tunnel for
host 117.136.8.199, port 16263.
Apr 15 12:41:29 jfwvps xl2tpd[12855]: handle_avps: handling avp's for
tunnel 18053, call 11768
Apr 15 12:41:29 jfwvps xl2tpd[12855]: message_type_avp: message type 1
(Start-Control-Connection-Request)
Apr 15 12:41:29 jfwvps xl2tpd[12855]: protocol_version_avp: peer is using
version 1, revision 0.
Apr 15 12:41:29 jfwvps xl2tpd[12855]: hostname_avp: peer reports hostname
'anonymous'
Apr 15 12:41:29 jfwvps xl2tpd[12855]: framing_caps_avp: supported peer
frames: async sync
Apr 15 12:41:29 jfwvps xl2tpd[12855]: assigned_tunnel_avp: using peer's
tunnel 27203
Apr 15 12:41:29 jfwvps xl2tpd[12855]: receive_window_size_avp: peer wants
RWS of 1. Will use flow control.
Apr 15 12:41:29 jfwvps xl2tpd[12855]: challenge_avp: challenge avp found
Apr 15 12:41:29 jfwvps xl2tpd[12855]: control_finish: message type is
Start-Control-Connection-Request(1). Tunnel is 27203, call is 0.
Apr 15 12:41:30 jfwvps xl2tpd[12855]: control_finish: sending SCCRP
Apr 15 12:41:32 jfwvps xl2tpd[12855]: build_fdset: closing down tunnel
51909
Apr 15 12:41:32 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 107, tunnel = 0, call = 0 ref=0 refhim=0
Apr 15 12:41:32 jfwvps xl2tpd[12855]: get_call: allocating new tunnel for
host 117.136.8.199, port 16263.
Apr 15 12:41:32 jfwvps xl2tpd[12855]: handle_avps: handling avp's for
tunnel 5295, call 62268
Apr 15 12:41:32 jfwvps xl2tpd[12855]: message_type_avp: message type 1
(Start-Control-Connection-Request)
Apr 15 12:41:32 jfwvps xl2tpd[12855]: protocol_version_avp: peer is using
version 1, revision 0.
Apr 15 12:41:32 jfwvps xl2tpd[12855]: hostname_avp: peer reports hostname
'anonymous'
Apr 15 12:41:32 jfwvps xl2tpd[12855]: framing_caps_avp: supported peer
frames: async sync
Apr 15 12:41:32 jfwvps xl2tpd[12855]: assigned_tunnel_avp: using peer's
tunnel 27203
Apr 15 12:41:32 jfwvps xl2tpd[12855]: receive_window_size_avp: peer wants
RWS of 1. Will use flow control.
Apr 15 12:41:32 jfwvps xl2tpd[12855]: challenge_avp: challenge avp found
Apr 15 12:41:32 jfwvps xl2tpd[12855]: control_finish: message type is
Start-Control-Connection-Request(1). Tunnel is 27203, call is 0.
Apr 15 12:41:32 jfwvps xl2tpd[12855]: control_finish: Peer requested tunnel
27203 twice, ignoring second one.
Apr 15 12:41:32 jfwvps xl2tpd[12855]: build_fdset: closing down tunnel 5295
Apr 15 12:41:33 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 20, tunnel = 18053, call = 0 ref=0 refhim=0
Apr 15 12:41:33 jfwvps xl2tpd[12855]: handle_avps: handling avp's for
tunnel 18053, call 11768
Apr 15 12:41:33 jfwvps xl2tpd[12855]: message_type_avp: message type 3
(Start-Control-Connection-Connected)
Apr 15 12:41:33 jfwvps xl2tpd[12855]: control_finish: message type is
Start-Control-Connection-Connected(3). Tunnel is 27203, call is 0.
Apr 15 12:41:33 jfwvps xl2tpd[12855]: network_thread: select timeout
Apr 15 12:41:33 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 38, tunnel = 18053, call = 0 ref=0 refhim=0
Apr 15 12:41:33 jfwvps xl2tpd[12855]: handle_avps: handling avp's for
tunnel 18053, call 11768
Apr 15 12:41:33 jfwvps xl2tpd[12855]: message_type_avp: message type 10
(Incoming-Call-Request)
Apr 15 12:41:33 jfwvps xl2tpd[12855]: message_type_avp: new incoming call
Apr 15 12:41:33 jfwvps xl2tpd[12855]: assigned_call_avp: using peer's call
3162
Apr 15 12:41:33 jfwvps xl2tpd[12855]: call_serno_avp: serial number is
1721812244
Apr 15 12:41:33 jfwvps xl2tpd[12855]: control_finish: message type is
Incoming-Call-Request(10). Tunnel is 27203, call is 0.
Apr 15 12:41:33 jfwvps xl2tpd[12855]: control_finish: Sending ICRP
Apr 15 12:41:34 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 40, tunnel = 18053, call = 12947 ref=0 refhim=0
Apr 15 12:41:34 jfwvps xl2tpd[12855]: handle_avps: handling avp's for
tunnel 18053, call 12947
Apr 15 12:41:34 jfwvps xl2tpd[12855]: message_type_avp: message type 12
(Incoming-Call-Connected)
Apr 15 12:41:34 jfwvps xl2tpd[12855]: tx_speed_avp: transmit baud rate is
100000000
Apr 15 12:41:34 jfwvps xl2tpd[12855]: frame_type_avp: peer uses: async
frames
Apr 15 12:41:34 jfwvps xl2tpd[12855]: control_finish: message type is
Incoming-Call-Connected(12). Tunnel is 27203, call is 3162.
Apr 15 12:41:34 jfwvps xl2tpd[12855]: start_pppd: I'm running:
Apr 15 12:41:34 jfwvps xl2tpd[12855]: "/usr/sbin/pppd"
Apr 15 12:41:34 jfwvps xl2tpd[12855]: "passive"
Apr 15 12:41:34 jfwvps xl2tpd[12855]: "nodetach"
Apr 15 12:41:34 jfwvps xl2tpd[12855]: "10.0.0.1:10.0.0.2"
Apr 15 12:41:34 jfwvps xl2tpd[12855]: "refuse-pap"
Apr 15 12:41:34 jfwvps xl2tpd[12855]: "auth"
Apr 15 12:41:34 jfwvps xl2tpd[12855]: "debug"
Apr 15 12:41:34 jfwvps xl2tpd[12855]: "file"
Apr 15 12:41:34 jfwvps xl2tpd[12855]: "/etc/ppp/options.xl2tpd"
Apr 15 12:41:34 jfwvps xl2tpd[12855]: "/dev/pts/1"
Apr 15 12:41:34 jfwvps xl2tpd[12855]: network_thread: select timeout
Apr 15 12:41:35 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 34, tunnel = 18053, call = 12947 ref=0 refhim=0
Apr 15 12:41:36 jfwvps pppd[20462]: using channel 33
Apr 15 12:41:36 jfwvps pppd[20462]: sent [LCP ConfReq id=0x1 <mru 1400="">
<asyncmap 0x0=""> <auth chap="" ms-v2=""> <magic 0x6aaf2b01=""> <pcomp>
<accomp>]
Apr 15 12:41:36 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 39, tunnel = 18053, call = 12947 ref=0 refhim=0
Apr 15 12:41:36 jfwvps pppd[20462]: rcvd [LCP ConfAck id=0x1 <mru 1400="">
<asyncmap 0x0=""> <auth chap="" ms-v2=""> <magic 0x6aaf2b01=""> <pcomp>
<accomp>]
Apr 15 12:41:37 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 34, tunnel = 18053, call = 12947 ref=0 refhim=0
Apr 15 12:41:37 jfwvps pppd[20462]: rcvd [LCP ConfReq id=0x1 <mru 1400="">
<asyncmap 0x0=""> <magic 0x969f23fd=""> <pcomp> <accomp>]
Apr 15 12:41:37 jfwvps pppd[20462]: sent [LCP ConfAck id=0x1 <mru 1400="">
<asyncmap 0x0=""> <magic 0x969f23fd=""> <pcomp> <accomp>]
Apr 15 12:41:37 jfwvps pppd[20462]: sent [LCP EchoReq id=0x0
magic=0x6aaf2b01]
Apr 15 12:41:37 jfwvps pppd[20462]: sent [CHAP Challenge id=0x99
<cbb90ceb9256eeb9e5409ee6c72cfc9d>, name = "jfwvip"]
Apr 15 12:41:38 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 18, tunnel = 18053, call = 12947 ref=0 refhim=0
Apr 15 12:41:38 jfwvps pppd[20462]: rcvd [LCP EchoRep id=0x0
magic=0x969f23fd]
Apr 15 12:41:38 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 71, tunnel = 18053, call = 12947 ref=0 refhim=0
Apr 15 12:41:38 jfwvps pppd[20462]: rcvd [CHAP Response id=0x99
<000000000000000000000000000000000000000000000000d9c4f97234234234230cfcada57f07e78ee3e23f08277100>,
name = "jfwells"]
Apr 15 12:41:38 jfwvps pppd[20462]: sent [CHAP Success id=0x99
"S=E982F19E822342323322343234323429ACE2 M=Access granted"]
Apr 15 12:41:38 jfwvps pppd[20462]: sent [CCP ConfReq id=0x1 <deflate
15=""> <deflate(old#) 15="">]
Apr 15 12:41:38 jfwvps pppd[20462]: sent [IPCP ConfReq id=0x1 <compress
vj="" 0f="" 01=""> <addr 10.0.0.1="">]
Apr 15 12:41:38 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 25, tunnel = 18053, call = 12947 ref=0 refhim=0
Apr 15 12:41:38 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 38, tunnel = 18053, call = 12947 ref=0 refhim=0
Apr 15 12:41:38 jfwvps pppd[20462]: rcvd [CCP ConfReq id=0x1 <deflate
15=""> <deflate(old#) 15=""> <bsd v1="" 15="">]
Apr 15 12:41:38 jfwvps pppd[20462]: sent [CCP ConfRej id=0x1 <bsd v1=""
15="">]
Apr 15 12:41:38 jfwvps pppd[20462]: rcvd [IPCP ConfReq id=0x1 <compress
vj="" 0f="" 01=""> <addr 0.0.0.0=""> <ms-dns1 0.0.0.0=""> <ms-dns2
0.0.0.0="">]
Apr 15 12:41:38 jfwvps pppd[20462]: sent [IPCP ConfNak id=0x1 <addr
10.0.0.2=""> <ms-dns1 8.8.8.8=""> <ms-dns2 8.8.4.4="">]
Apr 15 12:41:39 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 26, tunnel = 18053, call = 12947 ref=0 refhim=0
Apr 15 12:41:39 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 22, tunnel = 18053, call = 12947 ref=0 refhim=0
Apr 15 12:41:39 jfwvps pppd[20462]: rcvd [IPCP ConfAck id=0x1 <compress
vj="" 0f="" 01=""> <addr 10.0.0.1="">]
Apr 15 12:41:39 jfwvps pppd[20462]: rcvd [CCP ConfAck id=0x1 <deflate
15=""> <deflate(old#) 15="">]
Apr 15 12:41:39 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 38, tunnel = 18053, call = 12947 ref=0 refhim=0
Apr 15 12:41:39 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 22, tunnel = 18053, call = 12947 ref=0 refhim=0
Apr 15 12:41:39 jfwvps pppd[20462]: rcvd [IPCP ConfReq id=0x2 <compress
vj="" 0f="" 01=""> <addr 10.0.0.2=""> <ms-dns1 8.8.8.8=""> <ms-dns2
8.8.4.4="">]
Apr 15 12:41:39 jfwvps pppd[20462]: sent [IPCP ConfAck id=0x2 <compress
vj="" 0f="" 01=""> <addr 10.0.0.2=""> <ms-dns1 8.8.8.8=""> <ms-dns2
8.8.4.4="">]
Apr 15 12:41:39 jfwvps pppd[20462]: Script /etc/ppp/ip-up started (pid
20469)
Apr 15 12:41:39 jfwvps pppd[20462]: rcvd [CCP ConfReq id=0x2 <deflate
15=""> <deflate(old#) 15="">]
Apr 15 12:41:39 jfwvps pppd[20462]: sent [CCP ConfAck id=0x2 <deflate
15=""> <deflate(old#) 15="">]
Apr 15 12:41:40 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 26, tunnel = 18053, call = 12947 ref=0 refhim=0
Apr 15 12:41:40 jfwvps pppd[20462]: rcvd [LCP TermReq id=0x2 "User
request"]
Apr 15 12:41:40 jfwvps pppd[20462]: sent [LCP TermAck id=0x2]
Apr 15 12:41:40 jfwvps pppd[20462]: Script /etc/ppp/ip-up finished (pid
20469), status = 0x0
Apr 15 12:41:40 jfwvps pppd[20462]: Script /etc/ppp/ip-down started (pid
20496)
Apr 15 12:41:41 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 36, tunnel = 18053, call = 0 ref=0 refhim=0
Apr 15 12:41:41 jfwvps xl2tpd[12855]: handle_avps: handling avp's for
tunnel 18053, call 11768
Apr 15 12:41:41 jfwvps xl2tpd[12855]: message_type_avp: message type 4
(Stop-Control-Connection-Notification)
Apr 15 12:41:41 jfwvps xl2tpd[12855]: assigned_tunnel_avp: using peer's
tunnel 27203
Apr 15 12:41:41 jfwvps xl2tpd[12855]: result_code_avp: avp is incorrect
size. 8 < 10
Apr 15 12:41:41 jfwvps xl2tpd[12855]: handle_packet: bad AVP handling!
Apr 15 12:41:41 jfwvps xl2tpd[12855]: network_thread: bad packet
Apr 15 12:41:41 jfwvps xl2tpd[12855]: build_fdset: closing down tunnel
18053
Apr 15 12:41:41 jfwvps xl2tpd[12855]: Terminating pppd: sending TERM signal
to pid 20462
Apr 15 12:41:41 jfwvps pppd[20462]: Waiting for 1 child processes...
Apr 15 12:41:41 jfwvps pppd[20462]: script /etc/ppp/ip-down, pid 20496
Apr 15 12:41:41 jfwvps pppd[20462]: sending SIGTERM to process 20496
Apr 15 12:41:41 jfwvps xl2tpd[12855]: pppd 20462 successfully terminated
Apr 15 12:41:41 jfwvps xl2tpd[12855]: network_thread: select returned error
9 (Bad file descriptor)
Apr 15 12:41:42 jfwvps xl2tpd[12855]: network_thread: select timeout
Apr 15 12:41:46 jfwvps xl2tpd[12855]: last message repeated 4 times
Apr 15 12:41:46 jfwvps xl2tpd[12855]: Unable to deliver closing message for
tunnel 18053. Destroying anyway.
Apr 15 12:43:53 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 107, tunnel = 0, call = 0 ref=0 refhim=0
Apr 15 12:43:53 jfwvps xl2tpd[12855]: get_call: allocating new tunnel for
host 117.136.8.199, port 17519.
Apr 15 12:43:53 jfwvps xl2tpd[12855]: handle_avps: handling avp's for
tunnel 33976, call 26103
Apr 15 12:43:53 jfwvps xl2tpd[12855]: message_type_avp: message type 1
(Start-Control-Connection-Request)
Apr 15 12:43:53 jfwvps xl2tpd[12855]: protocol_version_avp: peer is using
version 1, revision 0.
Apr 15 12:43:53 jfwvps xl2tpd[12855]: hostname_avp: peer reports hostname
'anonymous'
Apr 15 12:43:53 jfwvps xl2tpd[12855]: framing_caps_avp: supported peer
frames: async sync
Apr 15 12:43:53 jfwvps xl2tpd[12855]: assigned_tunnel_avp: using peer's
tunnel 28344
Apr 15 12:43:53 jfwvps xl2tpd[12855]: receive_window_size_avp: peer wants
RWS of 1. Will use flow control.
Apr 15 12:43:53 jfwvps xl2tpd[12855]: challenge_avp: challenge avp found
Apr 15 12:43:53 jfwvps xl2tpd[12855]: control_finish: message type is
Start-Control-Connection-Request(1). Tunnel is 28344, call is 0.
Apr 15 12:43:53 jfwvps xl2tpd[12855]: control_finish: sending SCCRP
Apr 15 12:43:55 jfwvps xl2tpd[12855]: build_fdset: closing down tunnel
18053
Apr 15 12:43:55 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 107, tunnel = 0, call = 0 ref=0 refhim=0
Apr 15 12:43:55 jfwvps xl2tpd[12855]: get_call: allocating new tunnel for
host 117.136.8.199, port 17519.
Apr 15 12:43:55 jfwvps xl2tpd[12855]: handle_avps: handling avp's for
tunnel 60642, call 49880
Apr 15 12:43:55 jfwvps xl2tpd[12855]: message_type_avp: message type 1
(Start-Control-Connection-Request)
Apr 15 12:43:55 jfwvps xl2tpd[12855]: protocol_version_avp: peer is using
version 1, revision 0.
Apr 15 12:43:55 jfwvps xl2tpd[12855]: hostname_avp: peer reports hostname
'anonymous'
Apr 15 12:43:55 jfwvps xl2tpd[12855]: framing_caps_avp: supported peer
frames: async sync
Apr 15 12:43:55 jfwvps xl2tpd[12855]: assigned_tunnel_avp: using peer's
tunnel 28344
Apr 15 12:43:55 jfwvps xl2tpd[12855]: receive_window_size_avp: peer wants
RWS of 1. Will use flow control.
Apr 15 12:43:55 jfwvps xl2tpd[12855]: challenge_avp: challenge avp found
Apr 15 12:43:55 jfwvps xl2tpd[12855]: control_finish: message type is
Start-Control-Connection-Request(1). Tunnel is 28344, call is 0.
Apr 15 12:43:55 jfwvps xl2tpd[12855]: control_finish: Peer requested tunnel
28344 twice, ignoring second one.
Apr 15 12:43:55 jfwvps xl2tpd[12855]: build_fdset: closing down tunnel
60642
Apr 15 12:43:55 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 20, tunnel = 33976, call = 0 ref=0 refhim=0
Apr 15 12:43:55 jfwvps xl2tpd[12855]: handle_avps: handling avp's for
tunnel 33976, call 26103
Apr 15 12:43:55 jfwvps xl2tpd[12855]: message_type_avp: message type 3
(Start-Control-Connection-Connected)
Apr 15 12:43:55 jfwvps xl2tpd[12855]: control_finish: message type is
Start-Control-Connection-Connected(3). Tunnel is 28344, call is 0.
Apr 15 12:43:56 jfwvps xl2tpd[12855]: network_thread: select timeout
Apr 15 12:43:56 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 38, tunnel = 33976, call = 0 ref=0 refhim=0
Apr 15 12:43:56 jfwvps xl2tpd[12855]: handle_avps: handling avp's for
tunnel 33976, call 26103
Apr 15 12:43:56 jfwvps xl2tpd[12855]: message_type_avp: message type 10
(Incoming-Call-Request)
Apr 15 12:43:56 jfwvps xl2tpd[12855]: message_type_avp: new incoming call
Apr 15 12:43:56 jfwvps xl2tpd[12855]: assigned_call_avp: using peer's call
63287
Apr 15 12:43:56 jfwvps xl2tpd[12855]: call_serno_avp: serial number is
1070349348
Apr 15 12:43:56 jfwvps xl2tpd[12855]: control_finish: message type is
Incoming-Call-Request(10). Tunnel is 28344, call is 0.
Apr 15 12:43:56 jfwvps xl2tpd[12855]: control_finish: Sending ICRP
Apr 15 12:43:56 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 40, tunnel = 33976, call = 62855 ref=0 refhim=0
Apr 15 12:43:56 jfwvps xl2tpd[12855]: handle_avps: handling avp's for
tunnel 33976, call 62855
Apr 15 12:43:56 jfwvps xl2tpd[12855]: message_type_avp: message type 12
(Incoming-Call-Connected)
Apr 15 12:43:56 jfwvps xl2tpd[12855]: tx_speed_avp: transmit baud rate is
100000000
Apr 15 12:43:56 jfwvps xl2tpd[12855]: frame_type_avp: peer uses: async
frames
Apr 15 12:43:56 jfwvps xl2tpd[12855]: control_finish: message type is
Incoming-Call-Connected(12). Tunnel is 28344, call is 63287.
Apr 15 12:43:56 jfwvps xl2tpd[12855]: start_pppd: I'm running:
Apr 15 12:43:56 jfwvps xl2tpd[12855]: "/usr/sbin/pppd"
Apr 15 12:43:56 jfwvps xl2tpd[12855]: "passive"
Apr 15 12:43:56 jfwvps xl2tpd[12855]: "nodetach"
Apr 15 12:43:56 jfwvps xl2tpd[12855]: "10.0.0.1:10.0.0.2"
Apr 15 12:43:56 jfwvps xl2tpd[12855]: "refuse-pap"
Apr 15 12:43:56 jfwvps xl2tpd[12855]: "auth"
Apr 15 12:43:56 jfwvps xl2tpd[12855]: "debug"
Apr 15 12:43:56 jfwvps xl2tpd[12855]: "file"
Apr 15 12:43:56 jfwvps xl2tpd[12855]: "/etc/ppp/options.xl2tpd"
Apr 15 12:43:56 jfwvps xl2tpd[12855]: "/dev/pts/1"
Apr 15 12:43:56 jfwvps pppd[20760]: using channel 34
Apr 15 12:43:56 jfwvps pppd[20760]: sent [LCP ConfReq id=0x1 <mru 1400="">
<asyncmap 0x0=""> <auth chap="" ms-v2=""> <magic 0x7daef8e9=""> <pcomp>
<accomp>]
Apr 15 12:43:57 jfwvps xl2tpd[12855]: network_thread: select timeout
Apr 15 12:43:57 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 34, tunnel = 33976, call = 62855 ref=0 refhim=0
Apr 15 12:43:57 jfwvps pppd[20760]: rcvd [LCP ConfReq id=0x1 <mru 1400="">
<asyncmap 0x0=""> <magic 0x5b91a276=""> <pcomp> <accomp>]
Apr 15 12:43:57 jfwvps pppd[20760]: sent [LCP ConfAck id=0x1 <mru 1400="">
<asyncmap 0x0=""> <magic 0x5b91a276=""> <pcomp> <accomp>]
Apr 15 12:43:57 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 39, tunnel = 33976, call = 62855 ref=0 refhim=0
Apr 15 12:43:57 jfwvps pppd[20760]: rcvd [LCP ConfAck id=0x1 <mru 1400="">
<asyncmap 0x0=""> <auth chap="" ms-v2=""> <magic 0x7daef8e9=""> <pcomp>
<accomp>]
Apr 15 12:43:57 jfwvps pppd[20760]: sent [LCP EchoReq id=0x0
magic=0x7daef8e9]
Apr 15 12:43:57 jfwvps pppd[20760]: sent [CHAP Challenge id=0x84
<eb5478f37bc11d4211bfe342d9171ca4>, name = "jfwvip"]
Apr 15 12:43:58 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 18, tunnel = 33976, call = 62855 ref=0 refhim=0
Apr 15 12:43:58 jfwvps pppd[20760]: rcvd [LCP EchoRep id=0x0
magic=0x5b91a276]
Apr 15 12:43:58 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 71, tunnel = 33976, call = 62855 ref=0 refhim=0
Apr 15 12:43:58 jfwvps pppd[20760]: rcvd [CHAP Response id=0x84
<0000000000000000000000000000000000000000000000007502313d511c472232a6bd820d7bf9fa45f2db64a8c22f1b00>,
name = "jfwells"]
Apr 15 12:43:58 jfwvps pppd[20760]: sent [CHAP Success id=0x84
"S=D29105DD305BF6CFA692F3153C59C2FA162D0A85 M=Access granted"]
Apr 15 12:43:58 jfwvps pppd[20760]: sent [CCP ConfReq id=0x1 <deflate
15=""> <deflate(old#) 15="">]
Apr 15 12:43:58 jfwvps pppd[20760]: sent [IPCP ConfReq id=0x1 <compress
vj="" 0f="" 01=""> <addr 10.0.0.1="">]
Apr 15 12:43:58 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 25, tunnel = 33976, call = 62855 ref=0 refhim=0
Apr 15 12:43:58 jfwvps pppd[20760]: rcvd [CCP ConfReq id=0x1 <deflate
15=""> <deflate(old#) 15=""> <bsd v1="" 15="">]
Apr 15 12:43:58 jfwvps pppd[20760]: sent [CCP ConfRej id=0x1 <bsd v1=""
15="">]
Apr 15 12:43:58 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 38, tunnel = 33976, call = 62855 ref=0 refhim=0
Apr 15 12:43:58 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 22, tunnel = 33976, call = 62855 ref=0 refhim=0
Apr 15 12:43:58 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 26, tunnel = 33976, call = 62855 ref=0 refhim=0
Apr 15 12:43:58 jfwvps pppd[20760]: rcvd [IPCP ConfReq id=0x1 <compress
vj="" 0f="" 01=""> <addr 0.0.0.0=""> <ms-dns1 0.0.0.0=""> <ms-dns2
0.0.0.0="">]
Apr 15 12:43:58 jfwvps pppd[20760]: sent [IPCP ConfNak id=0x1 <addr
10.0.0.2=""> <ms-dns1 8.8.8.8=""> <ms-dns2 8.8.4.4="">]
Apr 15 12:43:58 jfwvps pppd[20760]: rcvd [CCP ConfAck id=0x1 <deflate
15=""> <deflate(old#) 15="">]
Apr 15 12:43:58 jfwvps pppd[20760]: rcvd [IPCP ConfAck id=0x1 <compress
vj="" 0f="" 01=""> <addr 10.0.0.1="">]
Apr 15 12:43:59 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 22, tunnel = 33976, call = 62855 ref=0 refhim=0
Apr 15 12:43:59 jfwvps pppd[20760]: rcvd [CCP ConfReq id=0x2 <deflate
15=""> <deflate(old#) 15="">]
Apr 15 12:43:59 jfwvps pppd[20760]: sent [CCP ConfAck id=0x2 <deflate
15=""> <deflate(old#) 15="">]
Apr 15 12:43:59 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 38, tunnel = 33976, call = 62855 ref=0 refhim=0
Apr 15 12:43:59 jfwvps pppd[20760]: rcvd [IPCP ConfReq id=0x2 <compress
vj="" 0f="" 01=""> <addr 10.0.0.2=""> <ms-dns1 8.8.8.8=""> <ms-dns2
8.8.4.4="">]
Apr 15 12:43:59 jfwvps pppd[20760]: sent [IPCP ConfAck id=0x2 <compress
vj="" 0f="" 01=""> <addr 10.0.0.2=""> <ms-dns1 8.8.8.8=""> <ms-dns2
8.8.4.4="">]
Apr 15 12:43:59 jfwvps pppd[20760]: Script /etc/ppp/ip-up started (pid
20765)
Apr 15 12:43:59 jfwvps pppd[20760]: Script /etc/ppp/ip-up finished (pid
20765), status = 0x0
Apr 15 12:44:07 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 748, tunnel = 33976, call = 62855 ref=0 refhim=0
Apr 15 12:44:09 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 44, tunnel = 33976, call = 62855 ref=0 refhim=0
Apr 15 12:44:10 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 26, tunnel = 33976, call = 62855 ref=0 refhim=0
Apr 15 12:44:10 jfwvps pppd[20760]: rcvd [LCP TermReq id=0x2 "User
request"]
Apr 15 12:44:10 jfwvps pppd[20760]: Script /etc/ppp/ip-down started (pid
20808)
Apr 15 12:44:10 jfwvps pppd[20760]: sent [LCP TermAck id=0x2]
Apr 15 12:44:11 jfwvps xl2tpd[12855]: network_thread: recv packet from
117.136.8.199, size = 36, tunnel = 33976, call = 0 ref=0 refhim=0
Apr 15 12:44:11 jfwvps xl2tpd[12855]: handle_avps: handling avp's for
tunnel 33976, call 26103
Apr 15 12:44:11 jfwvps xl2tpd[12855]: message_type_avp: message type 4
(Stop-Control-Connection-Notification)
Apr 15 12:44:11 jfwvps xl2tpd[12855]: assigned_tunnel_avp: using peer's
tunnel 28344
Apr 15 12:44:11 jfwvps xl2tpd[12855]: result_code_avp: avp is incorrect
size. 8 < 10
Apr 15 12:44:11 jfwvps xl2tpd[12855]: handle_packet: bad AVP handling!
Apr 15 12:44:11 jfwvps xl2tpd[12855]: network_thread: bad packet
Apr 15 12:44:11 jfwvps xl2tpd[12855]: build_fdset: closing down tunnel
33976
Apr 15 12:44:11 jfwvps xl2tpd[12855]: Terminating pppd: sending TERM signal
to pid 20760
Apr 15 12:44:11 jfwvps pppd[20760]: Waiting for 1 child processes...
Apr 15 12:44:11 jfwvps pppd[20760]: script /etc/ppp/ip-down, pid 20808
Apr 15 12:44:12 jfwvps pppd[20760]: Script /etc/ppp/ip-down finished (pid
20808), status = 0x0
Apr 15 12:44:12 jfwvps xl2tpd[12855]: pppd 20760 successfully terminated
Apr 15 12:44:12 jfwvps xl2tpd[12855]: network_thread: select returned error
9 (Bad file descriptor)
Apr 15 12:44:12 jfwvps xl2tpd[12855]: network_thread: select timeout
Apr 15 12:44:16 jfwvps xl2tpd[12855]: last message repeated 4 times
Apr 15 12:44:16 jfwvps xl2tpd[12855]: Unable to deliver closing message for
tunnel 33976. Destroying anyway.
Thanks in advance,
John
More information about the Users
mailing list