[Openswan Users] Windows Mobile 6.5 connects, but loses connection

Tue Sep 7 15:15:31 EDT 2010

Ah, I have finally found out how to get pppd debug logs. It is listed below.
I cannot find anything wrong with it. Can anyone help me with this?
It works just fine with windows xp sp3 when I use CHAP, MSCHAP, MSCHAPV2 or
PAP.

Sep  7 21:06:59 gateway pppd[21643]: Plugin
/usr/local/lib/pppd/2.4.5/radius.so loaded.
Sep  7 21:06:59 gateway pppd[21643]: RADIUS plugin initialized.
Sep  7 21:06:59 gateway pppd[21643]: pppd 2.4.5 started by root, uid 0
Sep  7 21:06:59 gateway pppd[21643]: using channel 67
Sep  7 21:06:59 gateway pppd[21643]: Using interface ppp0
Sep  7 21:06:59 gateway pppd[21643]: Connect: ppp0 <--> /dev/pts/5
Sep  7 21:06:59 gateway pppd[21643]: sent [LCP ConfReq id=0x1 <mru 1400>
<asyncmap 0x0> <auth eap> <magic 0xff2ed1c> <pcomp> <accomp>]
Sep  7 21:06:59 gateway pppd[21643]: rcvd [LCP ConfReq id=0x0 <mru 1400>
<asyncmap 0x0> <pcomp> <accomp>]
Sep  7 21:06:59 gateway pppd[21643]: sent [LCP ConfAck id=0x0 <mru 1400>
<asyncmap 0x0> <pcomp> <accomp>]
Sep  7 21:06:59 gateway pppd[21643]: rcvd [LCP ConfNak id=0x1 <auth chap
MS-v2>]
Sep  7 21:06:59 gateway pppd[21643]: sent [LCP ConfReq id=0x2 <mru 1400>
<asyncmap 0x0> <auth chap MS-v2> <magic 0xff2ed1c> <pcomp> <accomp>]
Sep  7 21:06:59 gateway pppd[21643]: rcvd [LCP ConfAck id=0x2 <mru 1400>
<asyncmap 0x0> <auth chap MS-v2> <magic 0xff2ed1c> <pcomp> <accomp>]
Sep  7 21:06:59 gateway pppd[21643]: sent [CHAP Challenge id=0x32
<fff6147eabb224db7b69ac2d22578e48>, name = "Helios.Lan"]
Sep  7 21:06:59 gateway pppd[21643]: rcvd [CHAP Response id=0x32
<c920f2c937dff065f45aafb79327bbbc0000000000000000f2f5d59ff4b1bcb34490e75e730c57206ee4dff5496510c300>,
name = "user1"]
Sep  7 21:06:59 gateway pppd[21643]: sent [CHAP Success id=0x32
"S=A7250C63D3FEDD31D93F75B992EC2CFDADAA4E90"]
Sep  7 21:06:59 gateway pppd[21643]: sent [IPCP ConfReq id=0x1 <compress VJ
0f 01> <addr 172.28.1.1>]
Sep  7 21:06:59 gateway pppd[21643]: rcvd [IPCP ConfReq id=0x0 <addr
0.0.0.0> <ms-dns1 0.0.0.0> <ms-wins 0.0.0.0> <ms-dns2 0.0.0.0> <ms-wins
0.0.0.0>]
Sep  7 21:06:59 gateway pppd[21643]: sent [IPCP ConfNak id=0x0 <addr
172.28.1.10> <ms-dns1 172.28.1.1> <ms-wins 172.28.1.1> <ms-dns2 172.28.1.1>
<ms-wins 172.28.1.1>]
Sep  7 21:06:59 gateway pppd[21643]: rcvd [proto=0x8057] 01 00 00 0e 01 0a
02 23 76 ff fe 0d 7a ea
Sep  7 21:06:59 gateway pppd[21643]: Unsupported protocol 'IPv6 Control
Protocol' (0x8057) received
Sep  7 21:06:59 gateway pppd[21643]: sent [LCP ProtRej id=0x3 80 57 01 00 00
0e 01 0a 02 23 76 ff fe 0d 7a ea]
Sep  7 21:06:59 gateway pppd[21643]: rcvd [IPCP ConfRej id=0x1 <compress VJ
0f 01>]
Sep  7 21:06:59 gateway pppd[21643]: sent [IPCP ConfReq id=0x2 <addr
172.28.1.1>]
Sep  7 21:06:59 gateway pppd[21643]: rcvd [IPCP ConfReq id=0x1 <addr
172.28.1.10> <ms-dns1 172.28.1.1> <ms-wins 172.28.1.1> <ms-dns2 172.28.1.1>
<ms-wins 172.28.1.1>]
Sep  7 21:06:59 gateway pppd[21643]: sent [IPCP ConfAck id=0x1 <addr
172.28.1.10> <ms-dns1 172.28.1.1> <ms-wins 172.28.1.1> <ms-dns2 172.28.1.1>
<ms-wins 172.28.1.1>]
Sep  7 21:06:59 gateway pppd[21643]: rcvd [IPCP ConfAck id=0x2 <addr
172.28.1.1>]
Sep  7 21:06:59 gateway pppd[21643]: found interface eth1 for proxy arp
Sep  7 21:06:59 gateway pppd[21643]: local  IP address 172.28.1.1
Sep  7 21:06:59 gateway pppd[21643]: remote IP address 172.28.1.10
Sep  7 21:06:59 gateway pppd[21643]: Script /etc/ppp/ip-up started (pid
21651)
Sep  7 21:06:59 gateway pppd[21643]: Script /etc/ppp/ip-up finished (pid
21651), status = 0x0
Sep  7 21:06:59 gateway dnsmasq-dhcp[967]: DHCPINFORM(ppp0) 172.28.1.10
00:53:45:00:00:00
Sep  7 21:06:59 gateway dnsmasq-dhcp[967]: DHCPACK(ppp0) 172.28.1.10
00:53:45:00:00:00
Sep  7 21:08:21 gateway pppd[21643]: rcvd [LCP TermReq id=0x1]
Sep  7 21:08:21 gateway pppd[21643]: LCP terminated by peer
Sep  7 21:08:21 gateway pppd[21643]: Connect time 1.4 minutes.
Sep  7 21:08:21 gateway pppd[21643]: Sent 890 bytes, received 650 bytes.
Sep  7 21:08:21 gateway pppd[21643]: Script /etc/ppp/ip-down started (pid
21664)
Sep  7 21:08:21 gateway pppd[21643]: sent [LCP TermAck id=0x1]
Sep  7 21:08:21 gateway pppd[21643]: Script /etc/ppp/ip-down finished (pid
21664), status = 0x0
Sep  7 21:08:21 gateway pppd[21643]: Terminating on signal 15
Sep  7 21:08:21 gateway pppd[21643]: Modem hangup
Sep  7 21:08:21 gateway pppd[21643]: Connection terminated.
Sep  7 21:08:21 gateway pppd[21643]: Exit.

   the options.xl2tpd:
   ipcp-accept-local
ipcp-accept-remote
ms-dns 172.28.1.1
ms-dns 172.28.1.1
ms-wins 172.28.1.1
ms-wins 172.28.1.1
noccp
auth
crtscts
idle 1800
mtu 1400
mru 1400
nodefaultroute
debug
lock
proxyarp
plugin /usr/local/lib/pppd/2.4.5/radius.so

xl2tpd.conf
ipsec saref = yes
debug tunnel = yes

[lns default]
;exclusive = no
ip range = 172.28.1.10-172.28.1.99
local ip = 172.28.1.1
require chap = no
refuse pap = no
require authentication = yes
name = Helios.Lan
ppp debug = yes
pppoptfile = /etc/ppp/options.xl2tpd
length bit = yes

2010/9/7 Bart Smink <bartsmink at gmail.com>

> Sorry for the last message, I misunderstood. The logs go to
> /var/log/messages,
> it looks like there is ipv6?
>
> here it is:
> Sep  7 17:03:01 gateway pppd[9494]: Plugin
> /usr/local/lib/pppd/2.4.5/radius.so loaded.
> Sep  7 17:03:01 gateway pppd[9494]: RADIUS plugin initialized.
> Sep  7 17:03:01 gateway pppd[9494]: pppd 2.4.5 started by root, uid 0
> Sep  7 17:03:02 gateway pppd[9494]: Using interface ppp0
> Sep  7 17:03:02 gateway pppd[9494]: Connect: ppp0 <--> /dev/pts/4
> Sep  7 17:03:02 gateway pppd[9494]: Unsupported protocol 'IPv6 Control
> Protocol' (0x8057) received
> Sep  7 17:03:02 gateway pppd[9494]: found interface eth1 for proxy arp
> Sep  7 17:03:02 gateway pppd[9494]: local  IP address 172.28.1.1
> Sep  7 17:03:02 gateway pppd[9494]: remote IP address 172.28.1.10
> Sep  7 17:03:02 gateway dnsmasq-dhcp[967]: DHCPINFORM(ppp0) 172.28.1.10
> 00:53:45:00:00:00
> Sep  7 17:03:02 gateway dnsmasq-dhcp[967]: DHCPACK(ppp0) 172.28.1.10
> 00:53:45:00:00:00
> Sep  7 17:04:09 gateway pppd[9494]: Terminating on signal 15
> Sep  7 17:04:09 gateway pppd[9494]: Modem hangup
> Sep  7 17:04:09 gateway pppd[9494]: Connect time 1.2 minutes.
> Sep  7 17:04:09 gateway pppd[9494]: Sent 890 bytes, received 650 bytes.
> Sep  7 17:04:09 gateway pppd[9494]: Connection terminated.
> Sep  7 17:04:09 gateway pppd[9494]: Exit.
> Sep  7 17:14:27 gateway pppd[9941]: Plugin
> /usr/local/lib/pppd/2.4.5/radius.so loaded.
> Sep  7 17:14:27 gateway pppd[9941]: RADIUS plugin initialized.
> Sep  7 17:14:27 gateway pppd[9941]: pppd 2.4.5 started by root, uid 0
> Sep  7 17:14:27 gateway pppd[9941]: Using interface ppp0
> Sep  7 17:14:27 gateway pppd[9941]: Connect: ppp0 <--> /dev/pts/4
> Sep  7 17:14:27 gateway radiusd: nss_ldap: could not search LDAP server -
> Server is unavailable
> Sep  7 17:14:27 gateway pppd[9941]: Unsupported protocol 'IPv6 Control
> Protocol' (0x8057) received
> Sep  7 17:14:27 gateway pppd[9941]: found interface eth1 for proxy arp
> Sep  7 17:14:27 gateway pppd[9941]: local  IP address 172.28.1.1
> Sep  7 17:14:27 gateway pppd[9941]: remote IP address 172.28.1.10
> Sep  7 17:14:27 gateway dnsmasq-dhcp[967]: DHCPINFORM(ppp0) 172.28.1.10
> 00:53:45:00:00:00
> Sep  7 17:14:27 gateway dnsmasq-dhcp[967]: DHCPACK(ppp0) 172.28.1.10
> 00:53:45:00:00:00
> Sep  7 17:15:11 gateway pppd[9941]: LCP terminated by peer
> Sep  7 17:15:11 gateway pppd[9941]: Connect time 0.8 minutes.
> Sep  7 17:15:11 gateway pppd[9941]: Sent 890 bytes, received 650 bytes.
> Sep  7 17:15:11 gateway pppd[9941]: Terminating on signal 15
> Sep  7 17:15:11 gateway pppd[9941]: Modem hangup
> Sep  7 17:15:11 gateway pppd[9941]: Connection terminated.
> Sep  7 17:15:11 gateway pppd[9941]: Exit.
>

>
>

> 2010/9/7 Bart Smink <bartsmink at gmail.com>
>
> Thank you for your response Paul,
>>>
>>> This is Openswan-2.6.28 using Netkey. I have added debug to
>>> /etc/ppp/options.xl2tpd and I ran xl2tpd -D
>>>  Things work when I use the mobile phone as a modem, so there has to be
>>> something wrong on the phone, or the authentication goes wrong.
>>>
>>> The output of xl2tpd -D is:
>>>
>>> [root at gateway ppp]# xl2tpd -D
>>> xl2tpd[9444]: setsockopt recvref[22]: Protocol not available
>>> xl2tpd[9444]: This binary does not support kernel L2TP.
>>> xl2tpd[9444]: xl2tpd version xl2tpd-1.2.6 started on gateway.helios.lan
>>> PID:9444
>>> xl2tpd[9444]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc.
>>> xl2tpd[9444]: Forked by Scott Balmos and David Stipp, (C) 2001
>>> xl2tpd[9444]: Inherited by Jeff McAdams, (C) 2002
>>> xl2tpd[9444]: Forked again by Xelerance (www.xelerance.com) (C) 2006
>>> xl2tpd[9444]: Listening on IP address 0.0.0.0, port 1701
>>> xl2tpd[9444]: control_finish: Peer requested tunnel 15 twice, ignoring
>>> second one.
>>> xl2tpd[9444]: Connection established to 62.140.137.125, 1701.  Local:
>>> 12003, Remote: 15 (ref=0/0).  LNS session is 'default'
>>> xl2tpd[9444]: start_pppd: I'm running:
>>> xl2tpd[9444]: "/usr/sbin/pppd"
>>> xl2tpd[9444]: "passive"
>>> xl2tpd[9444]: "nodetach"
>>> xl2tpd[9444]: "172.28.1.1:172.28.1.10"
>>> xl2tpd[9444]: "auth"
>>> xl2tpd[9444]: "name"
>>> xl2tpd[9444]: "Helios.Lan"
>>> xl2tpd[9444]: "debug"
>>> xl2tpd[9444]: "file"
>>> xl2tpd[9444]: "/etc/ppp/options.xl2tpd"
>>> xl2tpd[9444]: "/dev/pts/4"
>>> xl2tpd[9444]: Call established with 62.140.137.125, Local: 57733, Remote:
>>> 1, Serial: 0
>>> xl2tpd[9444]: Maximum retries exceeded for tunnel 12003.  Closing.
>>> xl2tpd[9444]: Terminating pppd: sending TERM signal to pid 9494
>>> xl2tpd[9444]: Connection 15 closed to 62.140.137.125, port 1701 (Timeout)
>>>
>>>
>>> 2010/9/7 Paul Wouters <paul at xelerance.com>
>>>
>>> On Tue, 7 Sep 2010, Bart Smink wrote:
>>>>
>>>>  I am trying to get Windows Mobile 6.5 to work with Openswan in
>>>>> combination with XL2TPD which is connected to freeradius. When
>>>>> I am trying to send data through the tunnel, the connection goes down,
>>>>> when I wait for 3 minutes, the connection goes down.
>>>>>
>>>>> What I notice is that I get "ignoring informational payload, type
>>>>> INVALID_COOKIE msgid=00000000" messages. Openswan sees it as
>>>>> information messages, but I think it is the client trying to
>>>>> communicate.
>>>>>
>>>>> I am using the example config file l2tp-cert.conf. I have not
>>>>> configured "esp=", because I would like Openswan to find out
>>>>> what encryption methods can be used, but this is not working.
>>>>>
>>>>> Can someone help me?
>>>>>
>>>>
>>>> Is this a recent openswan 2.6.x?
>>>>
>>>>
>>>>  Sep  7 15:50:31 gateway pluto[1749]: "l2tp-X.509"[11] 62.140.137.125
>>>>> #14: STATE_MAIN_R2: sent MR2, expecting MI3
>>>>> Sep  7 15:50:32 gateway pluto[1749]: "l2tp-X.509"[11] 62.140.137.125
>>>>> #14: discarding duplicate packet; already STATE_MAIN_R2
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[11] 62.140.137.125
>>>>> #14: Main mode peer ID is ID_DER_ASN1_DN: 'C=NL,
>>>>> ST=Utrecht, L=Utrecht, O=Testing Corporation, OU=Research and
>>>>> Development, CN=Left1024, E=admin at testingcorporation.nl'
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[11] 62.140.137.125
>>>>> #14: switched from "l2tp-X.509" to "l2tp-X.509"
>>>>>
>>>>
>>>> This is a little odd.
>>>>
>>>>
>>>>  Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[12] 62.140.137.125
>>>>> #14: I am sending my cert
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[12] 62.140.137.125
>>>>> #14: deleting connection "l2tp-X.509" instance with peer
>>>>> 62.140.137.107 {isakmp=#0/ipsec=#13}
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509" #13: deleting state
>>>>> (STATE_QUICK_R2)
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[12] 62.140.137.125
>>>>> #14: transition from state STATE_MAIN_R2 to state
>>>>> STATE_MAIN_R3
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[12] 62.140.137.125
>>>>> #14: new NAT mapping for #14, was 62.140.137.125:29237,
>>>>> now 62.140.137.125:29528
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[12] 62.140.137.125
>>>>> #14: STATE_MAIN_R3: sent MR3, ISAKMP SA established
>>>>> {auth=OAKLEY_RSA_SIG cipher=oakley_3des_cbc_192 prf=oakley_sha
>>>>> group=modp2048}
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[12] 62.140.137.125
>>>>> #14: peer client type is FQDN
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[12] 62.140.137.125
>>>>> #14: Applying workaround for MS-818043 NAT-T bug
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[12] 62.140.137.125
>>>>> #14: IDci was FQDN: U\221\224j, using
>>>>> NAT_OA=10.66.108.51/32 as IDci
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[12] 62.140.137.125
>>>>> #14: the peer proposed: 85.145.148.106/32:17/1701 ->
>>>>> 10.66.108.51/32:17/0
>>>>>
>>>>
>>>> There might be confusion between the two instances.
>>>>
>>>>
>>>>  O=Testing Corporation, OU=Research and Development, CN=Left1024, E=
>>>>> admin at testingcorporation.nl,+S=C]:17/0===10.66.108.51/32
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[12] 62.140.137.125
>>>>> #16: transition from state STATE_QUICK_R0 to state
>>>>> STATE_QUICK_R1
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[12] 62.140.137.125
>>>>> #16: STATE_QUICK_R1: sent QR1, inbound IPsec SA
>>>>> installed, expecting QI2
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[12] 62.140.137.125
>>>>> #16: netlink_raw_eroute: WARNING: that_client port 0 and
>>>>> that_host port 29528 don't match. Using that_client port.
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[12] 62.140.137.125
>>>>> #16: transition from state STATE_QUICK_R1 to state
>>>>> STATE_QUICK_R2
>>>>> Sep  7 15:50:34 gateway pluto[1749]: "l2tp-X.509"[12] 62.140.137.125
>>>>> #16: STATE_QUICK_R2: IPsec SA established transport mode
>>>>> {ESP=>0x00bc42b0 <0x44d1a644 xfrm=3DES_0-HMAC_SHA1 NATOA=10.66.108.51
>>>>> NATD=62.140.137.125:29528 DPD=none}
>>>>> Sep  7 15:50:37 gateway pluto[1749]: "l2tp-X.509"[11] 62.140.137.125
>>>>> #15: ignoring informational payload, type INVALID_COOKIE
>>>>> msgid=00000000
>>>>>
>>>>
>>>> This looks like the phone started a new attempt from scratch (hence the
>>>> null cookie)
>>>>
>>>>
>>>>  The output of xl2tpd -D:
>>>>>
>>>>> xl2tpd[1808]: control_finish: Peer requested tunnel 14 twice, ignoring
>>>>> second one.
>>>>> xl2tpd[1808]: Connection established to 62.140.137.125, 1701.  Local:
>>>>> 15271, Remote: 14 (ref=0/0).  LNS session is 'default'
>>>>> xl2tpd[1808]: start_pppd: I'm running:
>>>>> xl2tpd[1808]: "/usr/sbin/pppd"
>>>>> xl2tpd[1808]: "passive"
>>>>> xl2tpd[1808]: "nodetach"
>>>>> xl2tpd[1808]: "172.28.1.1:172.28.1.10"
>>>>> xl2tpd[1808]: "auth"
>>>>> xl2tpd[1808]: "name"
>>>>> xl2tpd[1808]: "Helios.Lan"
>>>>> xl2tpd[1808]: "debug"
>>>>> xl2tpd[1808]: "file"
>>>>> xl2tpd[1808]: "/etc/ppp/options.xl2tpd"
>>>>> xl2tpd[1808]: "/dev/pts/4"
>>>>> xl2tpd[1808]: Call established with 62.140.137.125, Local: 38486,
>>>>> Remote: 1, Serial: 0
>>>>> xl2tpd[1808]: control_finish: Connection closed to 62.140.137.125,
>>>>> serial 0 ()
>>>>> xl2tpd[1808]: Terminating pppd: sending TERM signal to pid 6365
>>>>> xl2tpd[1808]: control_finish: Connection closed to 62.140.137.125, port
>>>>> 1701 (), Local: 15271, Remote: 14
>>>>>
>>>>
>>>> Is there any pppd logs? add "debug" to /etc/ppp/options.xl2tpd and look
>>>> there? This might simply be an
>>>> authentication error, and the logs at the openswan end just show the
>>>> phone trying again from scratch.
>>>>
>>>> Paul
>>>>
>>>
>>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.openswan.org/pipermail/users/attachments/20100907/56869572/attachment-0001.html 