[Openswan Users] Fwd: Re: Please help: strange behaviour with OpenSwan/xl2tpd & Android vpn client

Thu Apr 15 05:26:09 EDT 2010

Jacco,
(apologies for responding directly -- this should be reposted to the list I
believe)
> Quoting Jacco de Leeuw <jacco2 at dds.nl>:
> This should work, but my setup was slightly different from yours...

Thank you very much -- I have made those changes. Now an IPSec tunnel seems
to get established OK -- but xl2tpd never seems to succeed.

I assume it is a routing issue -- it looks from the debug logs like the
xl2tpd never gets a response through (it keeps receiving
Start-Control-Connection-Request over and over again). The new debug logs
showing xl2tpd & pppd output are below. 

The server has an external IP address, but is also assigned an internal
network address in the 192.168.x.x range to communicate with other servers
in the data centre (I am not using it however -- my /etc/network/interfaces
defines only eth0 with IP assigned via dhcp). Hence I am trying to use
10.0.0.x for the address assigned to the client on the network (this worked
when I tested pptp with server = 10.0.0.1 and client = 10.0.0.2-x -- I
really need to use IPSec/l2tp though). 

> Do you plan to try certificates once you got the PSK working?

Yes, that is my ultimate goal. It should also mean that I can fairly safely
grant access to other users too. Getting it working at all will be a huge
step though -- have been trying for days :-)

The config follows, and I've pasted the relevant log output below that.

--- xl2tpd config again: ---

[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
nodefaultroute
 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

Also, relevant configuration:

$ sysctl -p:
net.ipv4.ip_forward = 1
net.ipv4.conf.all.accept_redirects = 0
net.ipv4.conf.all.send_redirects = 0

and, prior to the connection: 

iptables -t nat -A POSTROUTING -s 10.0.0.0/24 -o eth0 -j MASQUERADE

-----Logs:------

the success line in /var/log/auth.log :

Apr 15 17:00:11 jfwvps pluto[22785]: "PSK"[2] 117.136.8.155 #4:     us:
11.22.33.44<11.22.33.44>[+S=C]:17/1701
Apr 15 17:00:11 jfwvps pluto[22785]: "PSK"[2] 117.136.8.155 #4:   them:
117.136.8.155[10.73.51.82,+S=C]:17/0===10.73.51.82/32
Apr 15 17:00:11 jfwvps pluto[22785]: "PSK"[2] 117.136.8.155 #4: keeping
refhim=4294901761 during rekey
Apr 15 17:00:11 jfwvps pluto[22785]: "PSK"[2] 117.136.8.155 #4: transition
from state STATE_QUICK_R0 to state STATE_QUICK_R1
Apr 15 17:00:11 jfwvps pluto[22785]: "PSK"[2] 117.136.8.155 #4:
STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
Apr 15 17:00:11 jfwvps pluto[22785]: "PSK"[2] 117.136.8.155 #4: transition
from state STATE_QUICK_R1 to state STATE_QUICK_R2
Apr 15 17:00:11 jfwvps pluto[22785]: "PSK"[2] 117.136.8.155 #4:
STATE_QUICK_R2: IPsec SA established transport mode {ESP=>0x072dca6a
<0xc6171912 xfrm=3DES_0-HMAC_SHA1 NATOA=none NATD=117.136.8.155:43063
DPD=none}

/var/log/debug: This pattern repeats many times before the client
apparently gives up. This is just a snippet from the middle:

......
Apr 15 17:00:25 jfwvps xl2tpd[23025]: get_call: allocating new tunnel for
host 117.136.8.155, port 58035.
Apr 15 17:00:25 jfwvps xl2tpd[23025]: handle_avps: handling avp's for
tunnel 48343, call 3995
Apr 15 17:00:25 jfwvps xl2tpd[23025]: message_type_avp: message type 1
(Start-Control-Connection-Request)
Apr 15 17:00:25 jfwvps xl2tpd[23025]: protocol_version_avp: peer is using
version 1, revision 0.
Apr 15 17:00:25 jfwvps xl2tpd[23025]: hostname_avp: peer reports hostname
'anonymous'
Apr 15 17:00:25 jfwvps xl2tpd[23025]: framing_caps_avp: supported peer
frames: async sync
Apr 15 17:00:25 jfwvps xl2tpd[23025]: assigned_tunnel_avp: using peer's
tunnel 56715
Apr 15 17:00:25 jfwvps xl2tpd[23025]: receive_window_size_avp: peer wants
RWS of 1.  Will use flow control.
Apr 15 17:00:25 jfwvps xl2tpd[23025]: challenge_avp: challenge avp found
Apr 15 17:00:25 jfwvps xl2tpd[23025]: control_finish: message type is
Start-Control-Connection-Request(1).  Tunnel is 56715, call is 0.
Apr 15 17:00:25 jfwvps xl2tpd[23025]: control_finish: Peer requested tunnel
56715 twice, ignoring second one.
Apr 15 17:00:25 jfwvps xl2tpd[23025]: build_fdset: closing down tunnel
48343
Apr 15 17:00:26 jfwvps xl2tpd[23025]: network_thread: select timeout
Apr 15 17:00:26 jfwvps xl2tpd[23025]: Unable to deliver closing message for
tunnel 46701. Destroying anyway.
Apr 15 17:00:27 jfwvps xl2tpd[23025]: network_thread: recv packet from
117.136.8.155, size = 107, tunnel = 0, call = 0 ref=0 refhim=0
Apr 15 17:00:27 jfwvps xl2tpd[23025]: get_call: allocating new tunnel for
host 117.136.8.155, port 58035.
Apr 15 17:00:27 jfwvps xl2tpd[23025]: handle_avps: handling avp's for
tunnel 4912, call 52428
Apr 15 17:00:27 jfwvps xl2tpd[23025]: message_type_avp: message type 1
(Start-Control-Connection-Request)
Apr 15 17:00:27 jfwvps xl2tpd[23025]: protocol_version_avp: peer is using
version 1, revision 0.
Apr 15 17:00:27 jfwvps xl2tpd[23025]: hostname_avp: peer reports hostname
'anonymous'
Apr 15 17:00:27 jfwvps xl2tpd[23025]: framing_caps_avp: supported peer
frames: async sync
Apr 15 17:00:27 jfwvps xl2tpd[23025]: assigned_tunnel_avp: using peer's
tunnel 56715
Apr 15 17:00:27 jfwvps xl2tpd[23025]: receive_window_size_avp: peer wants
RWS of 1.  Will use flow control.
Apr 15 17:00:27 jfwvps xl2tpd[23025]: challenge_avp: challenge avp found
Apr 15 17:00:27 jfwvps xl2tpd[23025]: control_finish: message type is
Start-Control-Connection-Request(1).  Tunnel is 56715, call is 0.
Apr 15 17:00:27 jfwvps xl2tpd[23025]: control_finish: Peer requested tunnel
56715 twice, ignoring second one.
Apr 15 17:00:27 jfwvps xl2tpd[23025]: build_fdset: closing down tunnel 4912
Apr 15 17:00:27 jfwvps xl2tpd[23025]: build_fdset: closing down tunnel
46701
Apr 15 17:00:29 jfwvps xl2tpd[23025]: network_thread: recv packet from
117.136.8.155, size = 107, tunnel = 0, call = 0 ref=0 refhim=0
Apr 15 17:00:29 jfwvps xl2tpd[23025]: get_call: allocating new tunnel for
host 117.136.8.155, port 58035.
Apr 15 17:00:29 jfwvps xl2tpd[23025]: handle_avps: handling avp's for
tunnel 28623, call 13230
Apr 15 17:00:29 jfwvps xl2tpd[23025]: message_type_avp: message type 1
(Start-Control-Connection-Request)
Apr 15 17:00:29 jfwvps xl2tpd[23025]: protocol_version_avp: peer is using
version 1, revision 0.
Apr 15 17:00:29 jfwvps xl2tpd[23025]: hostname_avp: peer reports hostname
'anonymous'
Apr 15 17:00:29 jfwvps xl2tpd[23025]: framing_caps_avp: supported peer
frames: async sync
Apr 15 17:00:29 jfwvps xl2tpd[23025]: assigned_tunnel_avp: using peer's
tunnel 56715
Apr 15 17:00:29 jfwvps xl2tpd[23025]: receive_window_size_avp: peer wants
RWS of 1.  Will use flow control.
Apr 15 17:00:29 jfwvps xl2tpd[23025]: challenge_avp: challenge avp found
Apr 15 17:00:29 jfwvps xl2tpd[23025]: control_finish: message type is
Start-Control-Connection-Request(1).  Tunnel is 56715, call is 0.
Apr 15 17:00:29 jfwvps xl2tpd[23025]: control_finish: sending SCCRP
Apr 15 17:00:31 jfwvps xl2tpd[23025]: network_thread: recv packet from
117.136.8.155, size = 107, tunnel = 0, call = 0 ref=0 refhim=0
Apr 15 17:00:31 jfwvps xl2tpd[23025]: get_call: allocating new tunnel for
host 117.136.8.155, port 58035.
Apr 15 17:00:31 jfwvps xl2tpd[23025]: handle_avps: handling avp's for
tunnel 25890, call 36456
Apr 15 17:00:31 jfwvps xl2tpd[23025]: message_type_avp: message type 1
(Start-Control-Connection-Request)
Apr 15 17:00:31 jfwvps xl2tpd[23025]: protocol_version_avp: peer is using
version 1, revision 0.
Apr 15 17:00:31 jfwvps xl2tpd[23025]: hostname_avp: peer reports hostname
'anonymous'
Apr 15 17:00:31 jfwvps xl2tpd[23025]: framing_caps_avp: supported peer
frames: async sync
Apr 15 17:00:31 jfwvps xl2tpd[23025]: assigned_tunnel_avp: using peer's
tunnel 56715
Apr 15 17:00:31 jfwvps xl2tpd[23025]: receive_window_size_avp: peer wants
RWS of 1.  Will use flow control.
Apr 15 17:00:31 jfwvps xl2tpd[23025]: challenge_avp: challenge avp found
Apr 15 17:00:31 jfwvps xl2tpd[23025]: control_finish: message type is
Start-Control-Connection-Request(1).  Tunnel is 56715, call is 0.
Apr 15 17:00:31 jfwvps xl2tpd[23025]: control_finish: Peer requested tunnel
56715 twice, ignoring second one.
Apr 15 17:00:31 jfwvps xl2tpd[23025]: build_fdset: closing down tunnel
25890
Apr 15 17:00:32 jfwvps xl2tpd[23025]: network_thread: select timeout
Apr 15 17:00:33 jfwvps xl2tpd[23025]: network_thread: recv packet from
117.136.8.155, size = 107, tunnel = 0, call = 0 ref=0 refhim=0
Apr 15 17:00:33 jfwvps xl2tpd[23025]: get_call: allocating new tunnel for
host 117.136.8.155, port 58035.
Apr 15 17:00:33 jfwvps xl2tpd[23025]: handle_avps: handling avp's for
tunnel 45643, call 42121
Apr 15 17:00:33 jfwvps xl2tpd[23025]: message_type_avp: message type 1
(Start-Control-Connection-Request)
Apr 15 17:00:33 jfwvps xl2tpd[23025]: protocol_version_avp: peer is using
version 1, revision 0.
Apr 15 17:00:33 jfwvps xl2tpd[23025]: hostname_avp: peer reports hostname
'anonymous'
Apr 15 17:00:33 jfwvps xl2tpd[23025]: framing_caps_avp: supported peer
frames: async sync
Apr 15 17:00:33 jfwvps xl2tpd[23025]: assigned_tunnel_avp: using peer's
tunnel 56715
Apr 15 17:00:33 jfwvps xl2tpd[23025]: receive_window_size_avp: peer wants
RWS of 1.  Will use flow control.
Apr 15 17:00:33 jfwvps xl2tpd[23025]: challenge_avp: challenge avp found
Apr 15 17:00:33 jfwvps xl2tpd[23025]: control_finish: message type is
Start-Control-Connection-Request(1).  Tunnel is 56715, call is 0.
Apr 15 17:00:33 jfwvps xl2tpd[23025]: control_finish: Peer requested tunnel
56715 twice, ignoring second one.
Apr 15 17:00:33 jfwvps xl2tpd[23025]: build_fdset: closing down tunnel
45643
Apr 15 17:00:33 jfwvps xl2tpd[23025]: network_thread: select timeout
Apr 15 17:00:35 jfwvps xl2tpd[23025]: last message repeated 2 times
Apr 15 17:00:35 jfwvps xl2tpd[23025]: network_thread: recv packet from
117.136.8.155, size = 107, tunnel = 0, call = 0 ref=0 refhim=0
Apr 15 17:00:35 jfwvps xl2tpd[23025]: get_call: allocating new tunnel for
host 117.136.8.155, port 58035.
Apr 15 17:00:35 jfwvps xl2tpd[23025]: handle_avps: handling avp's for
tunnel 40906, call 618
Apr 15 17:00:35 jfwvps xl2tpd[23025]: message_type_avp: message type 1
(Start-Control-Connection-Request)
Apr 15 17:00:35 jfwvps xl2tpd[23025]: protocol_version_avp: peer is using
version 1, revision 0.
Apr 15 17:00:35 jfwvps xl2tpd[23025]: hostname_avp: peer reports hostname
'anonymous'
Apr 15 17:00:35 jfwvps xl2tpd[23025]: framing_caps_avp: supported peer
frames: async sync
Apr 15 17:00:35 jfwvps xl2tpd[23025]: assigned_tunnel_avp: using peer's
tunnel 56715
Apr 15 17:00:35 jfwvps xl2tpd[23025]: receive_window_size_avp: peer wants
RWS of 1.  Will use flow control.
Apr 15 17:00:35 jfwvps xl2tpd[23025]: challenge_avp: challenge avp found
Apr 15 17:00:35 jfwvps xl2tpd[23025]: control_finish: message type is
Start-Control-Connection-Request(1).  Tunnel is 56715, call is 0.
Apr 15 17:00:35 jfwvps xl2tpd[23025]: control_finish: Peer requested tunnel
56715 twice, ignoring second one.
Apr 15 17:00:35 jfwvps xl2tpd[23025]: build_fdset: closing down tunnel
40906
Apr 15 17:00:36 jfwvps xl2tpd[23025]: network_thread: select timeout
Apr 15 17:00:37 jfwvps xl2tpd[23025]: network_thread: recv packet from
117.136.8.155, size = 107, tunnel = 0, call = 0 ref=0 refhim=0
Apr 15 17:00:37 jfwvps xl2tpd[23025]: get_call: allocating new tunnel for
host 117.136.8.155, port 58035.
Apr 15 17:00:37 jfwvps xl2tpd[23025]: handle_avps: handling avp's for
tunnel 16374, call 0
Apr 15 17:00:37 jfwvps xl2tpd[23025]: message_type_avp: message type 1
(Start-Control-Connection-Request)
Apr 15 17:00:37 jfwvps xl2tpd[23025]: protocol_version_avp: peer is using
version 1, revision 0.
Apr 15 17:00:37 jfwvps xl2tpd[23025]: hostname_avp: peer reports hostname
'anonymous'
Apr 15 17:00:37 jfwvps xl2tpd[23025]: framing_caps_avp: supported peer
frames: async sync
Apr 15 17:00:37 jfwvps xl2tpd[23025]: assigned_tunnel_avp: using peer's
tunnel 56715
Apr 15 17:00:37 jfwvps xl2tpd[23025]: receive_window_size_avp: peer wants
RWS of 1.  Will use flow control.
Apr 15 17:00:37 jfwvps xl2tpd[23025]: challenge_avp: challenge avp found
Apr 15 17:00:37 jfwvps xl2tpd[23025]: control_finish: message type is
Start-Control-Connection-Request(1).  Tunnel is 56715, call is 0.
Apr 15 17:00:37 jfwvps xl2tpd[23025]: control_finish: Peer requested tunnel
56715 twice, ignoring second one.
Apr 15 17:00:37 jfwvps xl2tpd[23025]: build_fdset: closing down tunnel
16374
Apr 15 17:00:37 jfwvps xl2tpd[23025]: build_fdset: closing down tunnel
28623
Apr 15 17:00:38 jfwvps xl2tpd[23025]: network_thread: select timeout
Apr 15 17:00:39 jfwvps xl2tpd[23025]: network_thread: recv packet from
117.136.8.155, size = 107, tunnel = 0, call = 0 ref=0 refhim=0
Apr 15 17:00:39 jfwvps xl2tpd[23025]: get_call: allocating new tunnel for
host 117.136.8.155, port 58035.
Apr 15 17:00:39 jfwvps xl2tpd[23025]: handle_avps: handling avp's for
tunnel 35287, call 1738
Apr 15 17:00:39 jfwvps xl2tpd[23025]: message_type_avp: message type 1
(Start-Control-Connection-Request)
Apr 15 17:00:39 jfwvps xl2tpd[23025]: protocol_version_avp: peer is using
version 1, revision 0.
Apr 15 17:00:39 jfwvps xl2tpd[23025]: hostname_avp: peer reports hostname
'anonymous'
Apr 15 17:00:39 jfwvps xl2tpd[23025]: framing_caps_avp: supported peer
frames: async sync
Apr 15 17:00:39 jfwvps xl2tpd[23025]: assigned_tunnel_avp: using peer's
tunnel 56715
Apr 15 17:00:39 jfwvps xl2tpd[23025]: receive_window_size_avp: peer wants
RWS of 1.  Will use flow control.
Apr 15 17:00:39 jfwvps xl2tpd[23025]: challenge_avp: challenge avp found
Apr 15 17:00:39 jfwvps xl2tpd[23025]: control_finish: message type is
Start-Control-Connection-Request(1).  Tunnel is 56715, call is 0.
Apr 15 17:00:39 jfwvps xl2tpd[23025]: control_finish: Peer requested tunnel
56715 twice, ignoring second one.
Apr 15 17:00:39 jfwvps xl2tpd[23025]: build_fdset: closing down tunnel
35287
Apr 15 17:00:39 jfwvps xl2tpd[23025]: network_thread: select timeout
Apr 15 17:00:40 jfwvps xl2tpd[23025]: network_thread: select timeout
Apr 15 17:00:41 jfwvps xl2tpd[23025]: network_thread: recv packet from
117.136.8.155, size = 107, tunnel = 0, call = 0 ref=0 refhim=0
Apr 15 17:00:41 jfwvps xl2tpd[23025]: get_call: allocating new tunnel for
host 117.136.8.155, port 58035.
Apr 15 17:00:41 jfwvps xl2tpd[23025]: handle_avps: handling avp's for
tunnel 46850, call 2537
Apr 15 17:00:41 jfwvps xl2tpd[23025]: message_type_avp: message type 1
(Start-Control-Connection-Request)
Apr 15 17:00:41 jfwvps xl2tpd[23025]: protocol_version_avp: peer is using
version 1, revision 0.
Apr 15 17:00:41 jfwvps xl2tpd[23025]: hostname_avp: peer reports hostname
'anonymous'
Apr 15 17:00:41 jfwvps xl2tpd[23025]: framing_caps_avp: supported peer
frames: async sync
Apr 15 17:00:41 jfwvps xl2tpd[23025]: assigned_tunnel_avp: using peer's
tunnel 56715
Apr 15 17:00:41 jfwvps xl2tpd[23025]: receive_window_size_avp: peer wants
RWS of 1.  Will use flow control.
Apr 15 17:00:41 jfwvps xl2tpd[23025]: challenge_avp: challenge avp found
Apr 15 17:00:41 jfwvps xl2tpd[23025]: control_finish: message type is
Start-Control-Connection-Request(1).  Tunnel is 56715, call is 0.
....

Thanks again,

John